fix(logs): restart re-attach loses a fast run's output — found by deflaking e2e - #14140
fix(logs): restart re-attach loses a fast run's output — found by deflaking e2e#14140ndeloof wants to merge 3 commits into
Conversation
docker-agent
left a comment
docker-agent
left a comment
There was a problem hiding this comment.
Assessment: 🔴 CRITICAL
Two issues in the new polling closure introduced by this PR:
-
Unsafe type assertion (panics) —
serviceState["State"].(string)at line 46 has no nil/type guard. Ifcompose psreturns{}or{"State": null}(possible when a service is not yet registered), the assertion panics inside thepoll.WaitOnclosure and crashes the test goroutine instead of retrying. -
Wrong poll result on missing service — Line 43 returns
poll.Error(terminates polling) when the service key is absent/mismatched. During a startup race this converts a transient "not yet visible" condition into a hard failure — the same class of race this PR aims to fix.
ndeloof
changed the title
|
CI caught the loss again with the FinishedAt anchor (still 2× world for 3× exit notices after a full minute, oldstable runner) — so there is a second mechanism. Local experiments can't reproduce it: 15 bare-daemon runs of a millisecond-lived Added instrumentation instead of speculation: on timeout the test now dumps the daemon's own |
Codecov Report✅ All modified and coverable lines are covered by tests. 📢 Thoughts on this report? Let us know! |
e0ef00b to
f4f7d5e
Compare
There was a problem hiding this comment.
Pull request overview
This PR addresses a log-following correctness bug in Compose where re-attaching after a restart can miss output from very fast container runs, and it also deflakes several e2e tests that were intermittently failing in CI.
Changes:
- Fix log re-attach anchoring by using the previous run’s end time (and tracking it from ordered events) instead of anchoring on
StartedAt. - Deflake e2e coverage by polling for convergent daemon state (
RequireServiceState) and waiting for asynchronous log lines inTestAttachRestart. - Increase an e2e timeout to reduce sporadic CI timeouts on slower runners.
Reviewed changes
Copilot reviewed 6 out of 6 changed files in this pull request and generated 2 comments.
Show a summary per file
| File | Description |
|---|---|
| pkg/e2e/compose_up_test.go | Extends a scenario step timeout to reduce CI flakiness. |
| pkg/e2e/compose_test.go | Hardens TestAttachRestart by waiting for expected log output instead of asserting a single snapshot. |
| pkg/e2e/assert.go | Makes RequireServiceState poll until compose ps converges to the expected state. |
| pkg/compose/up.go | Changes up log re-attach to use a safer “since” anchor captured at start-event time. |
| pkg/compose/logs.go | Implements runEndTracker and switches follow/re-attach log anchoring away from StartedAt. |
| pkg/compose/logs_test.go | Adds a unit test validating the run-end tracking anchor behavior across fast restarts. |
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
docker-agent
left a comment
docker-agent
left a comment
There was a problem hiding this comment.
Assessment: 🟡 NEEDS ATTENTION
One CONFIRMED medium-severity finding in the new RequireServiceState poll helper.
Three tests failed 9 CI runs across 5 branches this week, all on asynchronous-observation races, none reproducible locally: - RequireServiceState asserted on a single `compose ps` snapshot; the daemon reports state transitions asynchronously from everything else a test observes (TestUpDependenciesNotStopped saw 'created' while the container's logs were already flowing). It now polls until the state converges (15s bound). - TestAttachRestart counted restart log lines in a snapshot taken as soon as the third exit notice appeared; exit notices come from the events monitor while log lines come from the re-attached logs stream — two channels with no ordering between them. The count is now awaited like the exit notices already were; a genuinely lost line still fails, by timeout. - TestUpExitCodeFromContainerKilled ran a full up+abort cycle under a 60s ceiling, once exceeded on a loaded oldstable runner; raised to 120s. Signed-off-by: Nicolas De Loof <nicolas.deloof@gmail.com>
…e new run's start The CI hardening in the previous commit turned TestAttachRestart's flake into a reliable detector, and what it detected is a real loss: re-attaching with since=StartedAt drops a fast run's first lines forever, because the daemon starts copying stdout before it records StartedAt. Anchoring on the inspected FinishedAt fixes the common case but leaves a narrower race CI still caught: when the new run itself finishes before compose reacts to its start event, the inspected FinishedAt is already the NEW run's own end, and the log window drops everything the run printed — two worlds for three exit notices, the third never arriving no matter how long you wait. Both re-attach sites (attached up, logs --follow) therefore anchor on the session's own record of the container's previous exit (runEndTracker): the monitor delivers events in order, so the anchor captured synchronously at start-event time is necessarily the previous run's end — nanosecond-precise, immune to how fast the new run dies. The inspected FinishedAt remains the fallback for a container the session never saw exit, and a fresh container keeps no lower bound. A unit test pins the ordering contract, including the fast-run sequence CI caught. Signed-off-by: Nicolas De Loof <nicolas.deloof@gmail.com>
The FinishedAt anchor did not cure the third-run loss on CI (still 2 worlds for 3 exit notices after a full minute, oldstable runner). The remaining suspects are on both sides of the API: a line the daemon never captured (copier torn down before a millisecond-lived run's output) or a line compose still fails to relay. On timeout the test now dumps `docker logs` for the container — ground truth that discriminates the two on the next CI occurrence. Signed-off-by: Nicolas De Loof <nicolas.deloof@gmail.com>
Three e2e tests failed 9 CI runs across 5 unrelated branches this week. Deflaking them (first commit) turned
TestAttachRestartfrom a flake into a reliable detector — and its first CI run proved the loss is real: with the hardened test waiting a full minute, the third restart's log line still never arrived (2× worldfor3× exit notices, the re-attachedlogs?since=…request hanging empty).The bug (second commit): re-attaching with
since=StartedAtdrops a fast run's first lines forever — the daemon starts copying stdout before it recordsStartedAt, so a process that prints and exits within milliseconds gets its output timestamped just before the anchor. Both re-attach sites (attachedup,logs --follow) now anchor on the previous run'sFinishedAt: nothing can be logged between one run's end and the next one's start, so the window captures the whole new run without replaying the previous one (zeroFinishedAt⇒ no lower bound, exact for a fresh container).The deflakes (first commit):
RequireServiceStatepolls until the daemon-reported state converges instead of asserting onecompose pssnapshot (TestUpDependenciesNotStopped, ×5);TestAttachRestartawaits the log-line count like it already awaited exit notices — events monitor and re-attached logs stream are unordered channels; a genuinely lost line still fails, by timeout (that is how the bug above was caught);TestUpExitCodeFromContainerKilled's 60s ceiling → 120s (one timeout on a loaded oldstable runner).🤖 Generated with Claude Code