fix(logs): restart re-attach loses a fast run's output — found by deflaking e2e - #14140
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❌ Patch coverage is
📢 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.
docker-agent
left a comment
docker-agent
left a comment
There was a problem hiding this comment.
Assessment: 🟡 NEEDS ATTENTION
The anchor-on-FinishedAt approach is sound, and the runEndTracker design correctly captures the previous run's exit time synchronously before the re-attach goroutine starts. One edge case in the new Observe guard may reintroduce the original log-loss bug in rare daemon environments.
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>
Review finding on runEndTracker.Observe: recording nothing for an exit event without a timestamp is the deliberate choice — the anchor is evaluated by the daemon against its own log clock, so substituting the local clock would introduce real skew mis-anchoring to paper over a hypothetical daemon quirk, while dropping only degrades that container to the pre-tracker fallback. Signed-off-by: Nicolas De Loof <nicolas.deloof@gmail.com>
2730609 to
516230b
Compare
…rror Wait listed running containers only, so a service that finished between up and the listing — a fast run, or a service long done by the time the user types the command — failed with 'no containers for project' in a few milliseconds instead of returning its recorded exit code. This is also the root cause of the TestWaitAndDrop flake: its 'faster' service sleeps 2 seconds, less than the harness latency between the two steps. The condition wait observes (container no longer running) already holds for such a target: fall back to a full listing only when no container is running, and let ContainerWait return the recorded status immediately. Scoping the fallback to the previously-erroring path keeps every other semantics intact — in particular a stale exited one-off can never short-circuit a wait that has live containers to observe. Exit-code propagation verified end to end: wait on an already-failed service returns its code (7), not an error. Signed-off-by: Nicolas De Loof <nicolas.deloof@gmail.com>
TestAttachRestart kept failing residually after the re-attach anchoring fix, and its new daemon-view dump told exactly why: the daemon holds all three 'world' lines while compose printed two. The monitor returns on the final die event — an events-channel fact — and up canceled the global context on the spot, killing the re-attach log streams with the last run's line still in flight: the exit notice outran the output that preceded it. Re-attach streams are now counted in a WaitGroup, and the monitor wrapper waits for them to reach their natural EOF — guaranteed once the containers exited — before canceling, under a bound that only protects against a wedged daemon and is skipped entirely when the context is already down (Ctrl-C). AttachRestart passes 5/5 locally with this drain; it failed within 2 CI attempts without it. Signed-off-by: Nicolas De Loof <nicolas.deloof@gmail.com>
…timeout TestWatch/debian flakes on loaded runners during 'writing to a file until Compose watch is up and running': that bootstrap loop ran under poll.WaitOn's default 10s budget, which must absorb image pull/build, container start and watcher initialization. Only the bootstrap gets the 2-minute budget — every later step keeps the sharp default so a real sync regression still fails fast. Signed-off-by: Nicolas De Loof <nicolas.deloof@gmail.com>
TestUpExitCodeFromContainerKilled hung for its full 2-minute budget on CI, and its event transcript shows why: 'Aborting on container exit' sweeps the application while the start phase — which runs on a deliberately uncancelable context for SIGTERM management — was still starting services; test-1 came up AFTER its stop and stayed up, so the monitor never drained and up never returned. The abort listener now watches the events stream past its trigger: any container started after the sweep is a late starter from that race, and gets stopped as it appears. Event-driven, so there is no listing window to miss; idempotent stops make duplicates harmless. The exit code semantics are preserved: the late starter's own 143 flows through captureExitCodeFrom exactly as when the sweep wins the race. TestUpExitCodeFrom* pass 5/5 locally. Signed-off-by: Nicolas De Loof <nicolas.deloof@gmail.com>
glours
left a comment
glours
left a comment
There was a problem hiding this comment.
runEndTracker/drain/stopLateStarter are well-reasoned and well-tested.
One gap worth a follow-up: the race stopLateStarter fixes for stopOnFirstExit (on-exit cascade) still seems open for gracefulTeardown (Ctrl+C/SIGINT/SIGTERM).
monitor.Start only returns once its containers set is empty, and onContainerStart re-adds any container that starts, regardless of why. stopApplication()'s stop sweep is a one-shot listing — a container that starts after it keeps monitor.Start blocked until it exits on its own. This PR wires stopLateStarter to catch that, but only inside stopOnFirstExit's own closure. gracefulTeardown calls the same stopApplication() with no equivalent listener.
Worse, the window is wider here: stopOnFirstExit only fires once something has already exited (startup is well underway), while Ctrl+C can land at t≈0, before monitor.Start even starts and while s.start() (on its deliberately uncancelable context) is still climbing the dependency graph — most services may still be created, not running. The only recovery today is a second manual Ctrl+C.
Not a regression from this PR, so I wouldn't block on it — but same root cause, same file, worth a fast follow-up (e.g. arm the late-starter watch once u.isTerminated is set, not just inside stopOnFirstExit).
…-exit glours' review on this PR (pullrequestreview-5277692679): stopLateStarter only ever got armed inside stopOnFirstExit's own closure, so it caught a service racing the on-exit cascade's sweep but not one racing gracefulTeardown's (Ctrl+C/SIGTERM) identical one-shot stopApplication sweep -- same root cause, same file, just the other trigger. Worse for that path: Ctrl+C can land at t~=0, before monitor.Start even starts and while s.start() (its own uncancelable context) is still climbing the dependency graph, so most services may still be created, not running. The only recovery today is a second manual Ctrl+C. u.isTerminated already flags "termination is underway" and was already set by gracefulTeardown (just not consulted for late-starter catching, and set after stopApplication rather than before it). Extract the late-starter watch out of stopOnFirstExit into its own listener, stopLateStarters, armed on u.isTerminated regardless of which path set it, and register it unconditionally (Ctrl+C works regardless of the on-exit policy, unlike stopOnFirstExit's own listener). stopOnFirstExit now sets isTerminated itself before its sweep, symmetric with gracefulTeardown (also reordered to set it before stopApplication, not after). isLateStarter is extracted as a pure predicate, following the existing shouldFollowStartEvent precedent, and unit-tested (TestIsLateStarter): the previous fix (ca86748) shipped only against a flaky test hitting the on-exit case by chance, with no dedicated regression test at all. Signed-off-by: Nicolas De Loof <nicolas.deloof@gmail.com>
|
Addressed in 39bf0d6: extracted the late-starter watch out of |
What this PR does, in one sentence
Turns the flakiest e2e tests into reliable ones by fixing the product races they were detecting: restart re-attach anchoring, shutdown log draining, and
waiton already-exited targets — one dedicated commit per test for traceability.Context
TestAttachRestart,TestWaitAndDropandTestWatchcost a CI rerun on most runs. Investigating them one by one showed the first two were not test problems: the tests were correctly detecting real product races that only needed a loaded runner to fire.What the PR brings
One commit per fixed test:
waitlisted running containers only, so a target that finished betweenupand the listing failed with "no containers for project" in milliseconds instead of returning its recorded exit code — the exact conditionwaitexists to observe, already satisfied. A fallback full listing runs only when nothing is running, scoping the change to the previously-erroring path: a stale exited one-off can never short-circuit a wait that has live containers to observe. Exit-code propagation verified end to end (an already-failed service returns 7).uphangs until killed. The abort listener now watches the events stream past its trigger and stops any late starter as it appears — event-driven, so no listing window to miss, and the late starter's own 143 still flows to--exit-code-from. Passes 5/5 locally.Also in the series: the three state/stream deflakes that started this investigation, the daemon-view failure dump that made the residual AttachRestart mode diagnosable, and unit tests locking each behavior (log-window anchoring, wait fallback listings, drain accounting).
🤖 Generated with Claude Code