Skip to content

test(e2e): wait on state, not on an unsynchronized log line - #14228

Merged
glours merged 3 commits into
docker:mainfrom
ndeloof:flaky-e2e-wait-conditions
Sep 16, 2026
Merged

glours merged 3 commits into
docker:mainfrom
ndeloof:flaky-e2e-wait-conditions

Conversation

@ndeloof

@ndeloof ndeloof commented Sep 16, 2026

Copy link
Copy Markdown
Contributor

Fixes two recurring e2e flakes seen in CI: TestAttachRestart (assertion failed: 2 (int) != 3 (int): Attaching to failing-1) and TestUpDependenciesNotStopped (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:

  • TestAttachRestart counts "failing-1 | world" in the captured output immediately after a WaitForCondition on "failing-1 exited with code 1" reaching 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 event is observed.
  • TestUpDependenciesNotStopped calls 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 brand new compose ps process — has caught up yet.

Neither is a compose bug: ps/ContainerList and 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: each compose ps invocation makes a fresh ContainerList call). 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:

  • TestAttachRestart gets a second, bounded WaitForCondition on the log count (30s/1s), instead of an instantaneous count.
  • TestUpDependenciesNotStopped uses a new RequireEventuallyServiceState (pkg/e2e/assert.go), which polls compose ps (15s/250ms) instead of checking it once.

No product code changed.

🤖 Generated with Claude Code

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>
@ndeloof
ndeloof requested review from a team as code owners September 16, 2026 07:02
@ndeloof
ndeloof requested a review from glours September 16, 2026 07:02

@docker-agent docker-agent left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Assessment: 🟡 NEEDS ATTENTION

Comment thread pkg/e2e/assert.go Outdated
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 {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[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

Comment thread pkg/e2e/assert.go Outdated
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

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[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 docker-agent left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Comment thread pkg/e2e/assert.go Outdated
continue
}
if current, _ := entry["State"].(string); strings.EqualFold(current, state) {
return poll.Success()

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[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

codecov Bot commented Sep 16, 2026

Copy link
Copy Markdown

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 docker-agent left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

@glours glours left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@glours
glours merged commit e64f64b into docker:main Sep 16, 2026
50 checks passed
glours pushed a commit that referenced this pull request Sep 16, 2026
`--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>
@ndeloof
ndeloof deleted the flaky-e2e-wait-conditions branch September 16, 2026 13:23
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants