feat(collector): log extension startup completion and duration#2413
feat(collector): log extension startup completion and duration#2413mvanhorn wants to merge 1 commit into
Conversation
Capture a start timestamp in main.go before the launch log and thread it through lifecycle.NewManager. After the collector starts successfully, emit a single info-level "OpenTelemetry Lambda extension startup complete" log carrying a startup_duration field so operators can see when the extension is ready and measure its cold-start contribution. Signed-off-by: Matt Van Horn <mvanhorn@gmail.com>
|
Thanks @mvanhorn for working on this! I'm a bit swamped at the moment but will take a look as soon as possible! |
| return c.err | ||
| } | ||
|
|
||
| func TestRun(t *testing.T) { |
There was a problem hiding this comment.
I know this is an existing test you didn't touch but since your addition of the extension startup log line, it has become flaky. I've noticed it panicking several times when I was running the tests locally. Looks like it's because the last case in here runs lm.Run(ctx) inside a goroutine that is never joined, using the logger which is zaptest.NewLogger(t), and thus it panics when anything logs after the test returns.
I think the goroutine needs to be joined before this test returns, and maybe switch require.NoError to assert.NoError for safety also.
| return err | ||
| } | ||
|
|
||
| lm.logger.Info("OpenTelemetry Lambda extension startup complete", zap.Duration("startup_duration", time.Since(lm.startTime))) |
There was a problem hiding this comment.
The log line in itself is correct, but an existing test has become flaky due to its addition. See comment in the testfile.
Summary
The collector extension emits a
"Launching OpenTelemetry Lambda extension"info log at process start, but nothing marks that startup has finished or how long it took. This adds a single info-level"OpenTelemetry Lambda extension startup complete"log carrying astartup_durationfield, emitted once the collector has started successfully.A start timestamp is captured in
main.goimmediately before the launch log and threaded intolifecycle.NewManager(the only production caller, so the signature change is contained). Aftercollector.Startreturns successfully inmanager.Run, the completion log is emitted withzap.Duration("startup_duration", time.Since(startTime)). The duration measures from the extension's launch log through successful collector start.Why this matters
Operators consuming the info-level firehose currently cannot tell when the extension is actually ready, nor measure its contribution to cold start. In #2101, @wpessers confirmed this is a valid concern, split the original report into two sub-features, and narrowed the remaining ask to exactly this startup-duration logging. This keeps it a single info-level statement so it is visible in the default firehose, with no new log-level knob (the log-decoupling sub-feature is out of scope and already addressed separately).
Testing
Added
TestRunLogsStartupDurationinmanager_test.gousing a zap observer core:MockCollectorstart emits exactly one startup-complete log with a non-negativestartup_durationfield.collector.Startreturns an error, the startup-complete log is NOT emitted andRunreturns the error, preserving current failure behavior.go build ./...,go vet, andgo test ./internal/lifecycle/...pass in thecollectormodule.Fixes #2101