From cef0904a8938da1f5c48254541c60aeff09ba55f Mon Sep 17 00:00:00 2001 From: Nicolas De Loof Date: Wed, 16 Sep 2026 09:01:25 +0200 Subject: [PATCH 1/3] test(e2e): wait on state, not on an unsynchronized log line 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 --- pkg/e2e/assert.go | 32 ++++++++++++++++++++++++++++++++ pkg/e2e/compose_test.go | 12 +++++++++++- pkg/e2e/up_test.go | 9 +++++++-- 3 files changed, 50 insertions(+), 3 deletions(-) diff --git a/pkg/e2e/assert.go b/pkg/e2e/assert.go index a5b973dd15..c3feb3c061 100644 --- a/pkg/e2e/assert.go +++ b/pkg/e2e/assert.go @@ -20,9 +20,11 @@ import ( "encoding/json" "strings" "testing" + "time" "gotest.tools/v3/assert" is "gotest.tools/v3/assert/cmp" + "gotest.tools/v3/poll" ) // RequireServiceState ensures that the container is in the expected state @@ -41,3 +43,33 @@ func RequireServiceState(t testing.TB, cli *CLI, service string, state string) { service, serviceState["Name"], ) } + +// RequireEventuallyServiceState polls `compose ps` until the service reaches +// the expected state, instead of checking once. +// +// `compose ps` makes a fresh ContainerList call to the daemon, an entirely +// different channel than a container's log stream: an application log line +// already relayed to a caller is no guarantee the daemon-reported state +// has caught up yet by the time that caller turns around and calls `ps` in a +// new process. Callers observing readiness through a log line (or any signal +// other than this same `ps` state) must poll here rather than check once. +func RequireEventuallyServiceState(t testing.TB, cli *CLI, service string, state string) { + t.Helper() + 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 + if err := json.Unmarshal([]byte(psRes.Stdout()), &serviceState); err != nil { + return poll.Continue("invalid `compose ps` JSON: command output: %s", psRes.Combined()) + } + last = serviceState + current, _ := serviceState["State"].(string) + if !strings.EqualFold(current, state) { + return poll.Continue("service %q not in state %q yet (got %q)", service, state, current) + } + return poll.Success() + } + poll.WaitOn(t, check, poll.WithDelay(250*time.Millisecond), poll.WithTimeout(15*time.Second)) + + assert.Assert(t, is.Equal(service, last["Service"]), "Found ps output for unexpected service") +} diff --git a/pkg/e2e/compose_test.go b/pkg/e2e/compose_test.go index 59d6cdd481..7c29a05651 100644 --- a/pkg/e2e/compose_test.go +++ b/pkg/e2e/compose_test.go @@ -157,7 +157,17 @@ func TestAttachRestart(t *testing.T) { debug) }, 4*time.Minute, 2*time.Second) - assert.Equal(t, strings.Count(res.Stdout(), "failing-1 | world"), 3, res.Combined()) + // The "exited" status above comes from the /events stream; the "world" + // log line comes from a separate, unsynchronized /logs?follow=1 + // connection (pkg/compose/up.go's followStartedContainers). 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 above — + // wait for it instead of counting it immediately. + c.WaitForCondition(t, func() (bool, string) { + debug := res.Combined() + return strings.Count(res.Stdout(), "failing-1 | world") == 3, + fmt.Sprintf("'failing-1 | world' not found 3 times in : \n%s\n", debug) + }, 30*time.Second, 1*time.Second) } func TestInitContainer(t *testing.T) { diff --git a/pkg/e2e/up_test.go b/pkg/e2e/up_test.go index 744a95a41a..e025e7d866 100644 --- a/pkg/e2e/up_test.go +++ b/pkg/e2e/up_test.go @@ -81,8 +81,13 @@ func TestUpDependenciesNotStopped(t *testing.T) { t.Log("Waiting for containers to be in running state") upOut.RequireEventuallyContains(t, "hello app") - RequireServiceState(t, c, "app", "running") - RequireServiceState(t, c, "dependency", "running") + // "hello app" comes from the log stream, an unsynchronized channel from + // the `ps` call below (a fresh ContainerList in a new process): the log + // line reaching this test is no guarantee the daemon-reported state has + // caught up yet, so poll for it instead of checking once (see + // RequireEventuallyServiceState). + RequireEventuallyServiceState(t, c, "app", "running") + RequireEventuallyServiceState(t, c, "dependency", "running") t.Log("Simulating Ctrl-C") assert.NilError(t, syscall.Kill(-cmd.Process.Pid, syscall.SIGINT), From 1e99163b137f6706d88f653f8cece4b31f328f12 Mon Sep 17 00:00:00 2001 From: Nicolas De Loof Date: Wed, 16 Sep 2026 10:49:55 +0200 Subject: [PATCH 2/3] fix(e2e): parse `compose ps --format=json` as NDJSON `--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 --- pkg/e2e/assert.go | 33 ++++++++++++++++++++++----------- 1 file changed, 22 insertions(+), 11 deletions(-) diff --git a/pkg/e2e/assert.go b/pkg/e2e/assert.go index c3feb3c061..6dee641675 100644 --- a/pkg/e2e/assert.go +++ b/pkg/e2e/assert.go @@ -18,6 +18,7 @@ package e2e import ( "encoding/json" + "fmt" "strings" "testing" "time" @@ -55,21 +56,31 @@ func RequireServiceState(t testing.TB, cli *CLI, service string, state string) { // other than this same `ps` state) must poll here rather than check once. func RequireEventuallyServiceState(t testing.TB, cli *CLI, service string, state string) { t.Helper() - 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 - if err := json.Unmarshal([]byte(psRes.Stdout()), &serviceState); err != nil { - return poll.Continue("invalid `compose ps` JSON: command output: %s", psRes.Combined()) + if psRes.ExitCode != 0 { + return poll.Continue("compose ps exited %d: %s", psRes.ExitCode, psRes.Combined()) } - last = serviceState - current, _ := serviceState["State"].(string) - if !strings.EqualFold(current, state) { - return poll.Continue("service %q not in state %q yet (got %q)", service, state, current) + // --format=json prints one JSON object per line (NDJSON), not a + // single object or array: a scaled service, or a transient window + // during recreation where the old and new containers are both + // listed, means more than one line for the requested service. + 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 + } + if current, _ := entry["State"].(string); strings.EqualFold(current, state) { + return poll.Success() + } } - return poll.Success() + return poll.Continue("service %q not in state %q yet: %s", service, state, psRes.Stdout()) } poll.WaitOn(t, check, poll.WithDelay(250*time.Millisecond), poll.WithTimeout(15*time.Second)) - - assert.Assert(t, is.Equal(service, last["Service"]), "Found ps output for unexpected service") } From de4808100447f8cea3686273e4e86c00900a485a Mon Sep 17 00:00:00 2001 From: Nicolas De Loof Date: Wed, 16 Sep 2026 11:00:38 +0200 Subject: [PATCH 3/3] fix(e2e): require every listed entry for the service to match state 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 #14228) Signed-off-by: Nicolas De Loof --- pkg/e2e/assert.go | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/pkg/e2e/assert.go b/pkg/e2e/assert.go index 6dee641675..c68a64b4fa 100644 --- a/pkg/e2e/assert.go +++ b/pkg/e2e/assert.go @@ -64,7 +64,9 @@ func RequireEventuallyServiceState(t testing.TB, cli *CLI, service string, state // --format=json prints one JSON object per line (NDJSON), not a // single object or array: a scaled service, or a transient window // during recreation where the old and new containers are both - // listed, means more than one line for the requested service. + // listed, means more than one line for the requested service — every + // one of them must reach the expected state, not just the first. + var found bool for _, line := range strings.Split(strings.TrimSpace(psRes.Stdout()), "\n") { if line == "" { continue @@ -76,10 +78,14 @@ func RequireEventuallyServiceState(t testing.TB, cli *CLI, service string, state if svc, _ := entry["Service"].(string); !strings.EqualFold(svc, service) { continue } - if current, _ := entry["State"].(string); strings.EqualFold(current, state) { - return poll.Success() + 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()) } poll.WaitOn(t, check, poll.WithDelay(250*time.Millisecond), poll.WithTimeout(15*time.Second))