test(e2e): wait on state, not on an unsynchronized log line - #14228
Conversation
TestAttachRestart and TestUpDependenciesNotStopped each flaked on an assertion checked exactly once, right after an unrelated signal on a different channel to the daemon: - TestAttachRestart counted "failing-1 | world" immediately after a WaitForCondition on "failing-1 exited with code 1" reached 3. The exited status comes from the /events stream; the log line comes from a separate /logs?follow=1 connection (followStartedContainers in pkg/compose/up.go). Nothing orders one relative to the other, so the last restart's log line can still be in flight the instant the 3rd exited is observed. - TestUpDependenciesNotStopped called RequireServiceState right after seeing "hello app" in the attached log stream. That line reaching the test is no guarantee the daemon-reported container state (read via a fresh `compose ps` in a brand new process) has caught up yet. Neither is a compose bug: `ps`/ContainerList and the log stream are independent channels with no cross-channel ordering guarantee from the engine, and compose does not cache container state. Both tests now poll for the actual condition instead of using a log line as a proxy for it: TestAttachRestart gets a second, bounded WaitForCondition on the log count, and TestUpDependenciesNotStopped uses a new RequireEventuallyServiceState (pkg/e2e/assert.go) that polls `compose ps` instead of checking it once. Signed-off-by: Nicolas De Loof <nicolas.deloof@gmail.com>
docker-agent
left a comment
There was a problem hiding this comment.
Assessment: 🟡 NEEDS ATTENTION
| check := func(poll.LogT) poll.Result { | ||
| psRes := cli.RunDockerComposeCmdNoCheck(t, "ps", "--all", "--format=json", service) | ||
| var serviceState map[string]any | ||
| if err := json.Unmarshal([]byte(psRes.Stdout()), &serviceState); err != nil { |
There was a problem hiding this comment.
[medium] compose ps --format=json emits NDJSON but is unmarshalled as a single object
compose ps --all --format=json <service> uses the docker/cli Go-template formatter which writes one JSON object per line (NDJSON), not a JSON array. The formatter test in cmd/formatter/formatter_test.go confirms this: its expected output is {"Name":"myName1",...}\n{"Name":"myName2",...}\n. When a service has more than one container — a scaled service, or during recreation when the old container is still being removed as the new one starts — json.Unmarshal receives a multi-line string and fails with invalid character '{' after top-level value. Every poll iteration returns poll.Continue("invalid compose ps JSON …") and the function always times out after 15 s instead of detecting the correct state.
Even for a scale: 1 service (as in TestUpDependenciesNotStopped) the window exists: while the daemon removes the old container and creates the replacement, both can be listed simultaneously, giving two NDJSON lines that break the unmarshal.
Fix: scan stdout line by line and unmarshal each object independently; succeed as soon as one entry for the requested service reaches the expected state:
psRes := cli.RunDockerComposeCmdNoCheck(t, "ps", "--all", "--format=json", service)
if psRes.ExitCode() != 0 {
return poll.Continue("compose ps exited %d: %s", psRes.ExitCode(), psRes.Combined())
}
for _, line := range strings.Split(strings.TrimSpace(psRes.Stdout()), "\n") {
if line == "" {
continue
}
var entry map[string]any
if err := json.Unmarshal([]byte(line), &entry); err != nil {
return poll.Error(fmt.Errorf("invalid `compose ps` JSON line %q: %w", line, err))
}
if svc, _ := entry["Service"].(string); !strings.EqualFold(svc, service) {
continue
}
current, _ := entry["State"].(string)
if strings.EqualFold(current, state) {
last = entry
return poll.Success()
}
}
return poll.Continue("service %q not in state %q yet", service, state)| Confidence | Score |
|---|---|
| 🟢 strong | 97/100 |
| var last map[string]any | ||
| check := func(poll.LogT) poll.Result { | ||
| psRes := cli.RunDockerComposeCmdNoCheck(t, "ps", "--all", "--format=json", service) | ||
| var serviceState map[string]any |
There was a problem hiding this comment.
[low] Non-zero compose ps exit code is not checked before JSON parsing
RunDockerComposeCmdNoCheck does not abort on non-zero exit codes, but the function never inspects psRes.ExitCode() before passing stdout to json.Unmarshal. When the project is not yet started (or a transient daemon error occurs), stdout is empty or contains an error message — neither is valid JSON, so json.Unmarshal fails and poll.Continue("invalid compose ps JSON …") is returned. Functionally the poll keeps retrying, which is the right behaviour, but the error message misleadingly says "invalid JSON" rather than identifying the actual exit code and cause. psRes.Combined() is included, so the raw output is visible, but the label is incorrect and makes debugging harder.
The established project pattern for this idiom adds an explicit exit code guard before the unmarshal:
if psRes.ExitCode() != 0 {
return poll.Continue("compose ps exited %d: %s", psRes.ExitCode(), psRes.Combined())
}| Confidence | Score |
|---|---|
| 🟢 strong | 100/100 |
`--format=json` prints one JSON object per line, not a single object: RequireEventuallyServiceState's json.Unmarshal into a single map broke as soon as more than one container was listed for the service (a scaled service, or the transient window during recreation where the old and new containers are both listed) -- every poll iteration reported "invalid JSON" and the function always timed out instead of detecting the actual state. Scan stdout line by line, matching entries by Service, and succeed as soon as one reaches the expected state. Also check the exit code before parsing so a real `compose ps` failure is reported as such instead of a misleading "invalid JSON" message. (docker-agent review on docker#14228) Signed-off-by: Nicolas De Loof <nicolas.deloof@gmail.com>
docker-agent
left a comment
There was a problem hiding this comment.
This incremental review covers commits since cef0904a8938da1f5c48254541c60aeff09ba55f.
Assessment: 🟡 NEEDS ATTENTION
The NDJSON fix and exit-code guard from the prior review are both correctly applied. One medium-confidence logic concern remains in the new loop.
| continue | ||
| } | ||
| if current, _ := entry["State"].(string); strings.EqualFold(current, state) { | ||
| return poll.Success() |
There was a problem hiding this comment.
[medium] poll.Success() on the first matching entry can return before all containers for the service reach the expected state
The loop iterates NDJSON lines and calls poll.Success() as soon as one entry for the requested service matches the expected state — without examining any remaining entries for that service. The code's own comment acknowledges that a recreation window can produce two entries for the same service simultaneously (old + new container). In that window, the old container could appear first with State: "running" while the new container has State: "starting", causing the poll to succeed prematurely.
For the specific test (TestUpDependenciesNotStopped, scale: 1, single up invocation) this window does not occur in practice, so the flakiness impact is negligible. However, as a general helper used in any test that polls after recreation, the semantic is fragile.
A more robust approach would collect all per-service entries in the loop and succeed only when every entry for the service is in the expected state:
var found bool
for _, line := range strings.Split(strings.TrimSpace(psRes.Stdout()), "\n") {
if line == "" {
continue
}
var entry map[string]any
if err := json.Unmarshal([]byte(line), &entry); err != nil {
return poll.Error(fmt.Errorf("invalid `compose ps` JSON line %q: %w", line, err))
}
if svc, _ := entry["Service"].(string); !strings.EqualFold(svc, service) {
continue
}
found = true
if current, _ := entry["State"].(string); !strings.EqualFold(current, state) {
return poll.Continue("service %q not in state %q yet (got %q): %s", service, state, current, psRes.Stdout())
}
}
if found {
return poll.Success()
}
return poll.Continue("service %q not in state %q yet: %s", service, state, psRes.Stdout())| Confidence | Score |
|---|---|
| 🟡 moderate | 70/100 |
Codecov Report✅ All modified and coverable lines are covered by tests. 📢 Thoughts on this report? Let us know! |
RequireEventuallyServiceState succeeded on the first NDJSON entry for the service matching the expected state, without checking any remaining entries. During a recreation window compose ps can list two containers for the same (scale: 1) service simultaneously (old and new); the old one could still read "running" while the new one is "starting", passing the poll prematurely on stale state. Track whether any entry for the service was seen, and only succeed once every one of them matches -- fail (poll.Continue) on the first mismatch instead. (docker-agent review on docker#14228) Signed-off-by: Nicolas De Loof <nicolas.deloof@gmail.com>
docker-agent
left a comment
There was a problem hiding this comment.
This review covers only the commits pushed since 1e99163b137f.
Assessment: 🟢 APPROVE
The fix correctly addresses the "first-match wins" race identified in the previous review cycle. The restructured loop now requires every NDJSON entry for the requested service to reach the expected state before returning poll.Success() — if any entry is still in a different state, polling continues. The found boolean is declared inside the closure (resets to false on every poll invocation), so there is no state leak between retries. All edge cases (empty stdout, no entries for the service, blank lines) fall through correctly to the trailing poll.Continue. No bugs found in the introduced lines.
`--format=json` prints one JSON object per line, not a single object: RequireEventuallyServiceState's json.Unmarshal into a single map broke as soon as more than one container was listed for the service (a scaled service, or the transient window during recreation where the old and new containers are both listed) -- every poll iteration reported "invalid JSON" and the function always timed out instead of detecting the actual state. Scan stdout line by line, matching entries by Service, and succeed as soon as one reaches the expected state. Also check the exit code before parsing so a real `compose ps` failure is reported as such instead of a misleading "invalid JSON" message. (docker-agent review on #14228) Signed-off-by: Nicolas De Loof <nicolas.deloof@gmail.com>
Fixes two recurring e2e flakes seen in CI:
TestAttachRestart(assertion failed: 2 (int) != 3 (int): Attaching to failing-1) andTestUpDependenciesNotStopped(assertion failed: running (string) != created (string)).Context
Both tests checked a condition exactly once, right after observing an unrelated signal on a different channel to the daemon:
TestAttachRestartcounts"failing-1 | world"in the captured output immediately after aWaitForConditionon"failing-1 exited with code 1"reaching 3. The exited status comes from the/eventsstream; the log line comes from a separate/logs?follow=1connection (followStartedContainersinpkg/compose/up.go). Nothing orders one relative to the other, so the last restart's log line can still be in flight the instant the 3rd exited event is observed.TestUpDependenciesNotStoppedcallsRequireServiceStateright after seeing"hello app"in the attached log stream. That line reaching the test is no guarantee the daemon-reported container state — read via a brand newcompose psprocess — has caught up yet.Neither is a compose bug:
ps/ContainerListand a container's log stream are independent channels with no cross-channel ordering guarantee from the engine, and compose does not cache container state (verified: eachcompose psinvocation makes a freshContainerListcall). This matches the project's own testing guidance (pkg/e2e/SCENARIO.md: state-based checks first) — these two tests just predate it.What this PR brings
Both tests now poll for the actual condition instead of using a log line as a proxy for it:
TestAttachRestartgets a second, boundedWaitForConditionon the log count (30s/1s), instead of an instantaneous count.TestUpDependenciesNotStoppeduses a newRequireEventuallyServiceState(pkg/e2e/assert.go), which pollscompose ps(15s/250ms) instead of checking it once.No product code changed.
🤖 Generated with Claude Code