feat(collector): log extension startup completion and duration - #2413
feat(collector): log extension startup completion and duration#2413mvanhorn wants to merge 2 commits 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! |
wpessers
added
enhancement
| 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.
The existing lifecycle test became flaky after the extension startup log line landed; synchronize the assertion so it no longer races the goroutine emitting the log.
|
Good catch on the flakiness - pushed be5b17d, which synchronizes that assertion so it no longer races the startup log goroutine. go test -count=5 on the lifecycle package stays green locally. |
| t.Run("zero-value start time produces a valid duration without panicking", func(t *testing.T) { | ||
| core, logs := observer.New(zap.InfoLevel) | ||
| logger := zap.New(core) | ||
|
|
||
| server := shutdownServer(t) | ||
| u, err := url.Parse(server.URL) | ||
| require.NoError(t, err) | ||
|
|
||
| lm := manager{ | ||
| collector: &MockCollector{}, | ||
| logger: logger, | ||
| listener: telemetryapi.NewListener(logger), | ||
| extensionClient: extensionapi.NewClient(logger, u.Host, extensionEventTypes), | ||
| // startTime intentionally left as the zero value. | ||
| } | ||
| require.NotPanics(t, func() { | ||
| require.NoError(t, lm.Run(context.Background())) | ||
| }) | ||
|
|
||
| entries := logs.FilterMessage(startupCompleteMsg).All() | ||
| require.Len(t, entries, 1) | ||
| duration, ok := entries[0].ContextMap()["startup_duration"].(time.Duration) | ||
| require.True(t, ok) | ||
| assert.GreaterOrEqual(t, duration, time.Duration(0)) | ||
| }) |
There was a problem hiding this comment.
This seems not so useful. Leaving startTime as the zero value means time.Time{} or in other words 01/01/0001 00:00:00. If you use that to calculate the time.Since() on inside manager.go you will exceed the max value that can be represented and thus clamp to said max value. So, this literally can't panic and duration will always be greater than 0. Not sure what is actually meant to be tested here?
| require.True(t, ok, "startup-complete log must carry a startup_duration field") | ||
| duration, ok := field.(time.Duration) | ||
| require.True(t, ok, "startup_duration must be a duration field") | ||
| assert.GreaterOrEqual(t, duration, time.Duration(0), "startup_duration must be non-negative") |
There was a problem hiding this comment.
I don't think this can ever fail. What was the intention behind this test?
2 participants
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