Skip to content

integration: add wait#48940

Merged
thaJeztah merged 1 commit intomoby:masterfrom
thaJeztah:integration_add_wait
Nov 27, 2024
Merged

integration: add wait#48940
thaJeztah merged 1 commit intomoby:masterfrom
thaJeztah:integration_add_wait

Conversation

@thaJeztah
Copy link
Member

@thaJeztah thaJeztah commented Nov 25, 2024

To see if this addresses the flaky tests mentioned there;

Full(er) list of test failures:

  • TestBuildUserNamespaceValidateCapabilitiesAreV2
  • TestNetworkNat
  • TestNetworkLocalhostTCPNat
  • TestBuildSquashParent
  • TestDiff
  • TestUsernsCommit
  • TestReadPluginNoRead/explicitly_enabled_caching

Most failures are related to not getting output from a container run. As I can't repro this locally I'm not sure how to bisect it.

Cherry-picked several WIP commits from
https://github.com/moby/moby/commits/b0a592798f4d9d7162f8aedca89ada3a29d60e2c/

Originally-authored-by: Rodrigo Campos rodrigoca@microsoft.com

- What I did

- How I did it

- How to verify it

- Description for the changelog

- A picture of a cute animal (not mandatory but encouraged)

Comment on lines +126 to +128

poll.WaitOn(t, container.IsInState(ctx, apiClient, id, "running"), poll.WithDelay(100*time.Millisecond))
return id
Copy link
Member Author

Choose a reason for hiding this comment

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

Honestly, these are the ones I'm not 100% sure about; to my knowledge, container.Run should only return when the container is running, so I'm wondering if we actually need a wait for it to be running here 🤔

Comment on lines +555 to +556
poll.WaitOn(t, container.IsInState(ctx, c, cID, "running"), poll.WithDelay(100*time.Millisecond))

Copy link
Member Author

Choose a reason for hiding this comment

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

Same for this one (and other ones that check for running state after calling container.Run

@thaJeztah thaJeztah force-pushed the integration_add_wait branch from fe1ebfb to 686cfad Compare November 26, 2024 12:48
container.WithCmd("/bin/sh", "-c", "cat /hello"),
)

poll.WaitOn(t, container.IsStopped(ctx, client, cid), poll.WithDelay(100*time.Millisecond))
Copy link
Member Author

Choose a reason for hiding this comment

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

Looks like the default is 100 miliseconds, so we can remove this as well;

config := defaultConfig()

func defaultConfig() *Settings {
return &Settings{Timeout: 10 * time.Second, Delay: 100 * time.Millisecond}

@thaJeztah thaJeztah force-pushed the integration_add_wait branch from 686cfad to 2f49d3b Compare November 26, 2024 12:57
Comment on lines +33 to +39
retry:
conn, err := net.Dial("tcp", net.JoinHostPort(endpoint.String(), "8080"))
if err != nil && try < 10 {
try++
time.Sleep(200 * time.Millisecond)
goto retry
}
Copy link
Contributor

Choose a reason for hiding this comment

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

I'm not really a fan of the go labels, maybe we can refactor this to be:

Suggested change
retry:
conn, err := net.Dial("tcp", net.JoinHostPort(endpoint.String(), "8080"))
if err != nil && try < 10 {
try++
time.Sleep(200 * time.Millisecond)
goto retry
}
var conn *net.Conn
var err error
for i:=0; i < 10; i++ {
conn, err = net.Dial("tcp", net.JoinHostPort(endpoint.String(), "8080"))
if err == nil && conn != nil {
break
}
time.Sleep(200 *time.Milisecond)
}
assert.NilError(t, err, "could not dial ...")
assert.NotNil(t, conn, "connection should not be nil")

Copy link
Member Author

Choose a reason for hiding this comment

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

Yeah, not a fan generally as well. This was part of the original patch that I took it from. I was considering rewriting it to a poll.Check (and to use poll.WaitOn here) but chose to keep the changes as they were;

// Check is a function which will be used as check for the [WaitOn] method.
type Check func(t LogT) Result

I can have a quick try though

Copy link
Member Author

Choose a reason for hiding this comment

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

Rewrote it to use poll.WaitOn;

diff --git a/integration/container/nat_test.go b/integration/container/nat_test.go
index 839619f8e5..5219548fc5 100644
--- a/integration/container/nat_test.go
+++ b/integration/container/nat_test.go
@@ -6,6 +6,7 @@ import (
 	"fmt"
 	"io"
 	"net"
+	"strconv"
 	"strings"
 	"testing"
 	"time"
@@ -25,20 +26,25 @@ func TestNetworkNat(t *testing.T) {
 
 	ctx := setupTest(t)
 
-	msg := "it works"
-	startServerContainer(ctx, t, msg, 8080)
+	const msg = "it works"
+	const port = 8080
+	startServerContainer(ctx, t, msg, port)
 
 	endpoint := getExternalAddress(t)
-	try := 0
-retry:
-	conn, err := net.Dial("tcp", net.JoinHostPort(endpoint.String(), "8080"))
-	if err != nil && try < 10 {
-		try++
-		time.Sleep(200 * time.Millisecond)
-		goto retry
-	}
-	assert.NilError(t, err)
-	defer conn.Close()
+
+	var conn net.Conn
+	addr := net.JoinHostPort(endpoint.String(), strconv.Itoa(port))
+	poll.WaitOn(t, func(t poll.LogT) poll.Result {
+		var err error
+		conn, err = net.Dial("tcp", addr)
+		if err != nil {
+			return poll.Continue("waiting for %s to be accessible: %v", addr, err)
+		}
+		return poll.Success()
+	})
+	defer func() {
+		assert.Check(t, conn.Close())
+	}()
 
 	data, err := io.ReadAll(conn)
 	assert.NilError(t, err)
@@ -47,23 +53,26 @@ retry:
 
 func TestNetworkLocalhostTCPNat(t *testing.T) {
 	skip.If(t, testEnv.IsRemoteDaemon)
-	skip.If(t, testEnv.GitHubActions, "FIXME: https://github.com/moby/moby/issues/41561")
 
 	ctx := setupTest(t)
 
-	msg := "hi yall"
-	startServerContainer(ctx, t, msg, 8081)
-
-	try := 0
-retry:
-	conn, err := net.Dial("tcp", "localhost:8081")
-	if err != nil && try < 10 {
-		try++
-		time.Sleep(200 * time.Millisecond)
-		goto retry
-	}
-	assert.NilError(t, err)
-	defer conn.Close()
+	const msg = "hi yall"
+	const port = 8081
+	startServerContainer(ctx, t, msg, port)
+
+	var conn net.Conn
+	addr := net.JoinHostPort("localhost", strconv.Itoa(port))
+	poll.WaitOn(t, func(t poll.LogT) poll.Result {
+		var err error
+		conn, err = net.Dial("tcp", addr)
+		if err != nil {
+			return poll.Continue("waiting for %s to be accessible: %v", addr, err)
+		}
+		return poll.Success()
+	})
+	defer func() {
+		assert.Check(t, conn.Close())
+	}()
 
 	data, err := io.ReadAll(conn)
 	assert.NilError(t, err)
diff --git a/integration/networking/port_mapping_linux_test.go b/integration/networking/port_mapping_linux_test.go
index 494f4a4ba1..ad87e7cf4a 100644
--- a/integration/networking/port_mapping_linux_test.go
+++ b/integration/networking/port_mapping_linux_test.go
@@ -25,6 +25,7 @@ import (
 	"gotest.tools/v3/assert"
 	is "gotest.tools/v3/assert/cmp"
 	"gotest.tools/v3/icmd"
+	"gotest.tools/v3/poll"
 	"gotest.tools/v3/skip"
 )
 
@@ -254,15 +255,16 @@ func TestProxy4To6(t *testing.T) {
 	inspect := container.Inspect(ctx, t, c, serverId)
 	hostPort := inspect.NetworkSettings.Ports["80/tcp"][0].HostPort
 
-	try := 0
-retry:
-	resp, err := http.Get("http://[::1]:" + hostPort)
-	if err != nil && try < 10 {
-		try++
-		time.Sleep(100 * time.Millisecond)
-		goto retry
-	}
-	assert.NilError(t, err)
+	var resp *http.Response
+	addr := "http://[::1]:" + hostPort
+	poll.WaitOn(t, func(t poll.LogT) poll.Result {
+		var err error
+		resp, err = http.Get(addr)
+		if err != nil {
+			return poll.Continue("waiting for %s to be accessible: %v", addr, err)
+		}
+		return poll.Success()
+	})
 	assert.Check(t, is.Equal(resp.StatusCode, 404))
 }
 

Copy link
Member Author

Choose a reason for hiding this comment

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

Failure with this patch looks something like this;

make BIND_DIR=. TEST_FILTER='TestNetworkLocalhostTCPNat' test-integration
...
=== RUN   TestNetworkLocalhostTCPNat
    nat_test.go:60: timeout hit after 10s: waiting for localhost:8081 to be accessible: dial tcp [::1]:8081: connect: connection refused
--- FAIL: TestNetworkLocalhostTCPNat (10.24s)

@thaJeztah thaJeztah force-pushed the integration_add_wait branch from 2f49d3b to 64bae63 Compare November 27, 2024 13:08

var conn net.Conn
addr := net.JoinHostPort(endpoint.String(), strconv.Itoa(port))
poll.WaitOn(t, func(t poll.LogT) poll.Result {
Copy link
Member Author

Choose a reason for hiding this comment

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

FWIW; I didn't bother setting a custom interval (some of these used 200 ms) or a custom timeout (e.g. original used 10 * 200 ms = 2 seconds), so the defaults (100 ms interval and 10 seconds timeout) is used for these.


func TestNetworkLocalhostTCPNat(t *testing.T) {
skip.If(t, testEnv.IsRemoteDaemon)
skip.If(t, testEnv.GitHubActions, "FIXME: https://github.com/moby/moby/issues/41561")
Copy link
Member Author

Choose a reason for hiding this comment

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

Removed this skip as well; I think this patch should also fix that issue;

@thaJeztah
Copy link
Member Author

😭 linter is complaining now for something silly. Guess I need a //nolint there;

integration/networking/port_mapping_linux_test.go:262:15: G107: Potential HTTP request made with variable url (gosec)
		resp, err = http.Get(addr)
		            ^

Cherry-picked several WIP commits from
https://github.com/moby/moby/commits/b0a592798f4d9d7162f8aedca89ada3a29d60e2c/

Originally-authored-by: Rodrigo Campos <rodrigoca@microsoft.com>
Co-Authored-by: Kir Kolyshkin <kolyshkin@gmail.com>
Signed-off-by: Akihiro Suda <akihiro.suda.cz@hco.ntt.co.jp>
Signed-off-by: Kir Kolyshkin <kolyshkin@gmail.com>
Signed-off-by: Sebastiaan van Stijn <github@gone.nl>
@thaJeztah
Copy link
Member Author

note for back porting; one part doesn't apply clean in older branches, but is trivial to fix; see #48969 (comment)

Copy link
Contributor

@robmry robmry left a comment

Choose a reason for hiding this comment

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

Waiting for containers to be stopped before looking at their logs makes sense I think... but I'm not sure why the wait is needed for the networking tests.

Port mappings should be set up and working before the start request returns, but maybe there's some issue there - or the process in the container isn't running and listening before the request returns? I don't think packet loss should be an issue, it's unlikely to happen, and there should be retries.

It's something we should come back to, but stabilising the tests in the meantime makes sense too.

@robmry
Copy link
Contributor

robmry commented Nov 27, 2024

I restarted this one - not changed by this PR ...

=== Failed
=== FAIL: amd64.integration-cli TestDockerSwarmSuite/TestServiceCreateWithConfigReferencedTwice (1.96s)
    docker_cli_service_create_test.go:364: assertion failed: error is not nil: exit status 1
test output with log
=== Failed
=== FAIL: amd64.integration-cli TestDockerSwarmSuite/TestServiceCreateWithConfigReferencedTwice (1.96s)
    docker_cli_service_create_test.go:364: assertion failed: error is not nil: exit status 1
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.284582742Z" level=debug msg="/usr/sbin/ip6tables, [--wait -t filter -C DOCKER-USER -j RETURN]"
        time="2024-11-27T15:25:24.285416793Z" level=debug msg="/usr/sbin/ip6tables, [--wait -
    daemon.go:318: [d1f402d43c986]  filter -C FORWARD -j DOCKER-USER]"
        time="2024-11-27T15:25:24.286245293Z" level=debug msg="/usr/sbin/ip6tables, [--wait -D FORWARD -j DOCKER-USER]"
        time="2024-11-27T15:25:24.2870903
    daemon.go:318: [d1f402d43c986] 5Z" level=debug msg="/usr/sbin/ip6tables, [--wait -I FORWARD -j DOCKER-USER]"
        time="2024-11-27T15:25:24.296085606Z" level=debug msg="state for task xk7tlac0fu71v6efzccli58as updated to FAILED" method="(*Dispatcher).processUpdates" module=dispatcher node.id=724
    daemon.go:318: [d1f402d43c986] c5nhcit7nfjd5x3gqjjfp state.transition="PREPARING->FAILED" task.id=xk7tlac0fu71v6efzccli58as
        time="2024-11-27T15:25:24.296196033Z" level=debug msg="dispatcher committed status updat
    daemon.go:318: [d1f402d43c986]  to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=7249c5nhcit7nfjd5x3gqjjfp state.transition="PREPARING->FAILED" task.id=xk7tlac0fu71v6efzccli58as
        time="2024-11-27T15:25:24.297552847Z" level=debug msg="task u7wy9m15eewxv84k3bnl3rsmi was marked pending allocation" module=node node.id=7249c5nhcit7nfjd5x3gq
    daemon.go:318: [d1f402d43c986] jfp
        time="2024-11-27T15:25:24.297581310Z" level=debug msg="allocated task u7wy9m15eewxv84k3bnl3rsmi, state update PENDING" method="(*Allocator).allocateTask" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
        time="2024-11-27T15:25:24.297656050Z" level=debug msg="committed allocated 
    daemon.go:318: [d1f402d43c986] ask u7wy9m15eewxv84k3bnl3rsmi, state update {2024-11-27T15:25:24.297578655Z PENDING pending task scheduling  <nil> nil  (timestamp: nil Timestamp)}" module=node node.id=7249c5nhcit7nfj
    daemon.go:318: [d1f402d43c986] 5x3gqjjfp
        time="2024-11-27T15:25:24.297904685Z" level=debug msg="Task u7wy9m15eewxv84k3bnl3rsmi is already in allocated state PENDING" method="(*Allocator).doTaskAlloc" module=node node.id=7249c5nhcit7nfjd
    daemon.go:318: [d1f402d43c986] x3gqjjfp
        time="2024-11-27T15:25:24.337140041Z" level=debug msg="handling GET request" method=GET module=api request-url=/v1.48/tasks/xk7tlac0fu71v6efzccli58as spanID=ae16d9e9b7ea05a1 status=200 traceID=960d6e0ff6c5b6a9b5f06d5251a07480 vars="map[id:xk7tlac0fu71v6efzccli58as versi
    daemon.go:318: [d1f402d43c986] n:1.48]"
        time="2024-11-27T15:25:24.344742305Z" level=debug msg="handling GET request" method=
    daemon.go:318: [d1f402d43c986] ET module=api request-url=/_ping spanID=93e339678072a872 status=200 traceID=cf807b128af9f9d1688e8b1776ec02ff vars="map[]"
        time="2024
    daemon.go:318: [d1f402d43c986] 11-27T15:25:24.345360724Z" level=debug msg="handling GET request" method=GET module=api request-url=/v1.30/c
    daemon.go:318: [d1f402d43c986] ntainers/476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2/json spanID=96ad9ed5924bafe6 status=200 traceID=2d520589e2
    daemon.go:318: [d1f402d43c986] c6e0ac1558d6d366dff86 vars="map[name:476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 version:1.30]"
        time="2024-11-27T15:25:24
    daemon.go:318: [d1f402d43c986] 346137792Z" level=error msg="Error setting up exec command in container 476b27b5243e96ae3735138da1be3965b4d266da7
    daemon.go:318: [d1f402d43c986] 8957bb190c849683b816e2: container 476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 is not running" spanID=6e3d6be286e4c[611](https://github.com/moby/moby/actions/runs/12052806904/job/33607104239?pr=48940#step:8:612) tra
    daemon.go:318: [d1f402d43c986] eID=5b8a5939a269316ab03bd300734d0c69
        time="2024-11-27T15:25:24.346163220Z" level=debug msg="handling POST request" error-response="container 476b27b5243e96ae3735138da1be3965b4d266da7
    daemon.go:318: [d1f402d43c986] 8957bb190c849683b816e2 is not running" form-data="{\"AttachStderr\":true,\"AttachStdin\":false,\"AttachStdout\":true,\"Cmd\":[\"cat\",\"/target1\"],\"Detach\":false,\"Detac
    daemon.go:318: [d1f402d43c986] Keys\":\"\",\"Env\":null,\"Privileged\":false,\"Tty\":false,\"User\":\"\"}" method=POST module=api request-url=/v1.30/containers/476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c8
    daemon.go:318: [d1f402d43c986] 9683b816e2/exec spanID=6e3d6be286e4c611 status=409 traceID=5b8a5939a269316ab03bd300734d0c69 vars="map[name:476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 
    daemon.go:318: [d1f402d43c986] ersion:1.30]"
         msg="/usr/sbin/iptables, [--wait -D FORWARD -j DOCKER-INGRESS]"
        time="2024-11-27T15:25:24.282770881Z" level=debug msg="/usr/sbin
    daemon.go:318: [d1f402d43c986] iptables, [--wait -I FORWARD -j DOCKER-INGRESS]"
        time="2024-11-27T15:25:24.283711571Z" level=debug msg="/usr/sbin/ip6tables, [--wait -t filter -n -L DOCKER-USER]"
        time="2024-11-2
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.284582742Z" level=debug msg="/usr/sbin/ip6tables, [--wait -t filter -C DOCKER-USER -j RETURN]"
        time="2024-11-27T15:25:24.285416793Z" level=debug msg="/u
    daemon.go:318: [d1f402d43c986] r/sbin/ip6tables, [--wait -t filter -C FORWARD -j DOCKER-USER]"
        time="2024-11-27T15:25:24.286245293Z" level=debug msg="/usr/sbin/ip6tables, [--wait -D FORWARD -j DOCKER-USER]"
    daemon.go:318: [d1f402d43c986] ime="2024-11-27T15:25:24.287090315Z" level=debug msg="/usr/sbin/ip6tables, [--wait -I FORWARD -j DOCKER-USER]"
        time="2024-11-27T15:25:24.296085606Z" level=debug msg="state fo
    daemon.go:318: [d1f402d43c986]  task xk7tlac0fu71v6efzccli58as updated to FAILED" method="(*Dispatcher).processUpdates" module=dispatcher node.id=7249c5nhcit7nfjd5x3gqjjfp state.transition="PREPARING->FAILED" task.id=xk7tlac0fu71v6efzccli58as
        time="2024-11-27T15:25:24.296196033Z" le
    daemon.go:318: [d1f402d43c986] el=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=7249c5nhcit7nfjd5x3gqjjfp state.transition="
    daemon.go:318: [d1f402d43c986] REPARING->FAILED" task.id=xk7tlac0fu71v6efzccli58as
        time="2024-11-27T15:25:24.297552847Z" level=debug msg="task u7wy9m15eewxv84k3bnl3rsmi was marked pending allocation" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
        time="2024-11-27T15:25:24.297581310Z" level=debug
    daemon.go:318: [d1f402d43c986] msg="allocated task u7wy9m15eewxv84k3bnl3rsmi, state update PENDING" method="(*Allocator).allocateTask" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
        time="2024-11-27T15:25:24.29
    daemon.go:318: [d1f402d43c986] 656050Z" level=debug msg="committed allocated task u7wy9m15eewxv84k3bnl3rsmi, state update {2024-11-27T15:25:24.297578655Z PENDI
    daemon.go:318: [d1f402d43c986] G pending task scheduling  <nil> nil  (timestamp: nil Timestamp)}" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
        time="2024-11-27T15:25:24.297904685Z" level=debug msg=
    daemon.go:318: [d1f402d43c986] Task u7wy9m15eewxv84k3bnl3rsmi is already in allocated state PENDING" method="(*Allocator).doTaskAlloc" module=node node.id=7249
    daemon.go:318: [d1f402d43c986] 5nhcit7nfjd5x3gqjjfp
        time="2024-11-27T15:25:24.337140041Z" level=debug msg="handling GET request" method=GET module=api request-url=/v1.48/tasks/xk7tlac0fu71v6efzccli58as spanID=ae16d9e9b7ea05a1 status=200 traceID=960d6e0ff6c5b6a9b5f06d5251a07480 vars="map[id:xk7tl
    daemon.go:318: [d1f402d43c986] c0fu71v6efzccli58as version:1.48]"
        time="2024-11-27T15:25:24.344742305Z" level=debug msg="handling GET request" method=GET module=api request-url=/_ping spanID=93e3396
    daemon.go:318: [d1f402d43c986] 8072a872 status=200 traceID=cf807b128af9f9d1688e8b1776ec02ff vars="map[]"
        time="2024-11-27T15:25:24.345360724Z" level=debug msg=
    daemon.go:318: [d1f402d43c986] handling GET request" method=GET module=api request-url=/v1.30/containers/476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2/json spanID=96ad9ed5924bafe6 status=200 traceID=2d520589e23c6e0ac
    daemon.go:318: [d1f402d43c986] 558d6d366dff86 vars="map[name:476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 version:1.30]"
        time="2024-11-27T15:25:24.34[613](https://github.com/moby/moby/actions/runs/12052806904/job/33607104239?pr=48940#step:8:614)7792Z" level=error msg="Error setting up exec command in container 476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2: contai
    daemon.go:318: [d1f402d43c986] er 476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 is not running" spanID=6e3d6be286e4c611 traceID=5b8a5939a269316ab03bd300734d0c69
        time="2024-11-27T15:25:24.34[616](https://github.com/moby/moby/actions/runs/12052806904/job/33607104239?pr=48940#step:8:617)3220Z" level=debug msg="handling POST request" error-response="container 476b27b52
    daemon.go:318: [d1f402d43c986] 3e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 is not running" form-data="{\"AttachStderr\":true,\"AttachStdin\":false,\"AttachStdout\":true,\"Cmd\":[\"cat\",\"/target1\"],\"Detach\":false,\"DetachK
    daemon.go:318: [d1f402d43c986] ys\":\"\",\"Env\":null,\"Privileged\":false,\"Tty\":false,\"User\":\"\"}" method=POST module=api request-url=/v1.30/containers/476b27b5243e96ae3735138da1be3965b4d266da7b895
    daemon.go:318: [d1f402d43c986] bb190c849683b816e2/exec spanID=6e3d6be286e4c611 status=409 traceID=5b8a5939a269316ab03bd300734d0c69 vars="map[name:476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 version:1.30]"
         msg="/u
    daemon.go:318: [d1f402d43c986] r/sbin/iptables, [--wait -D FORWARD -j DOCKER-INGRESS]"
        time="2024-11-27T15:25:24.282770881Z" level=debug msg="/usr/sbin/iptables, [--wait -I FORWARD -j DOCK
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.284582742Z" level=debug msg="/usr/sbin/ip6tables, [--wait -t filter -C DOCKER-USER -j RETURN]"
        time="2024-11-27T15:25:24.285416793Z" level=debug msg="/usr/sbin/ip6tables, [--wait -t filter -C FORW
    daemon.go:318: [d1f402d43c986] RD -j DOCKER-USER]"
        time="2024-11-27T15:25:24.286245293Z" level=debug msg="/usr/sbin/ip6tables, [--wait -D FORWARD -j DOCKER
    daemon.go:318: [d1f402d43c986] USER]"
        time="2024-11-27T15:25:24.287090315Z" level=debug msg="/usr/sbin/ip6tables, [--wait -I FORWARD -j DOCKER-USER]"
        time="2024-11-27T15:25:24.296085606Z" level=debug msg="state for task xk
    daemon.go:318: [d1f402d43c986] tlac0fu71v6efzccli58as updated to FAILED" method="(*Dispatcher).processUpdates" module=dispatcher node.id=7249c5nhcit7nfjd5x3gqjjfp state.transition="PREPARING->FAILED" task.id=xk7tlac0fu71v6efzccli58as
        time="2024-11-27T15:25:24.29[619](https://github.com/moby/moby/actions/runs/12052806904/job/33607104239?pr=48940#step:8:620)6033Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=7249c5nhcit7nfjd5x3gqjjfp state.transition="PRE
    daemon.go:318: [d1f402d43c986] ARING->FAILED" task.id=xk7tlac0fu71v6efzccli58as
        time="2024-11-27T15:25:24.297552847Z" level=debug msg="task u7wy9m15eewxv84k3bnl3rsmi was marked pending allocation" module=node node.id=7249c
    daemon.go:318: [d1f402d43c986] nhcit7nfjd5x3gqjjfp
        time="2024-11-27T15:25:24.297581310Z" level=debug msg="allocated task u7wy9m15eewxv84k3bnl3rsmi, state update PENDING" method="(*A
    daemon.go:318: [d1f402d43c986] locator).allocateTask" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
        time="2024-11-27T15:25:24.297656050Z" level=debug msg="committed allocated task u
    daemon.go:318: [d1f402d43c986] wy9m15eewxv84k3bnl3rsmi, state update {2024-11-27T15:25:24.297578655Z PENDING pending task scheduling  <nil> nil  (timestamp: nil Timestamp)}" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
        time="2024-11-27T15:25:24.297904685Z" level=debug msg="Task u7wy9m15eewxv
    daemon.go:318: [d1f402d43c986] 4k3bnl3rsmi is already in allocated state PENDING" method="(*Allocator).doTaskAlloc" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
        time="2024-11-27T15:25:24.337140041Z
    daemon.go:318: [d1f402d43c986]  level=debug msg="handling GET request" method=GET module=api request-url=/v1.48/tasks/xk7tlac0fu71v6efzccli58as spanID=ae16d9e9
    daemon.go:318: [d1f402d43c986] 7ea05a1 status=200 traceID=960d6e0ff6c5b6a9b5f06d5251a07480 vars="map[id:xk7tlac0fu71v6efzccli58as version:1.48]"
        time="2024-11-27T15:25:24.344742305Z" level=debug msg="handling GET request" method=GET module=api request-url=/_ping spanID=93e339678072a872 statu
    daemon.go:318: [d1f402d43c986] =200 traceID=cf807b128af9f9d1688e8b1776ec02ff vars="map[]"
        time="2024-11-27T15:25:24.345360724Z" level=debug msg="handling GET request" method=GET module=api request-u
    daemon.go:318: [d1f402d43c986] l=/v1.30/containers/476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2/json spanID=96ad9ed5924bafe6 status=200 tra
    daemon.go:318: [d1f402d43c986] eID=2d520589e23c6e0ac1558d6d366dff86 vars="map[name:476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 version:1.30]"
        time="2024-11-27T15:25:24.346137792Z" level=error msg="Error setting up exec command in container 476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2: container 476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 is not running" spanID=6e3d6be286e4c611 tra
    daemon.go:318: [d1f402d43c986] eID=5b8a5939a269316ab03bd300734d0c69
        time="2024-11-27T15:25:24.346163220Z" level=debug msg="handling POST request
    daemon.go:318: [d1f402d43c986]  error-response="container 476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 is not running" form-data="{\"A
    daemon.go:318: [d1f402d43c986] tachStderr\":true,\"AttachStdin\":false,\"AttachStdout\":true,\"Cmd\":[\"cat\",\"/target1\"],\"Detach\":false,\"D
    daemon.go:318: [d1f402d43c986] tachKeys\":\"\",\"Env\":null,\"Privileged\":false,\"Tty\":false,\"User\":\"\"}" method=POST module=api request-ur
    daemon.go:318: [d1f402d43c986] =/v1.30/containers/476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2/exec spanID=6e3d6be286e4c611 
    daemon.go:318: [d1f402d43c986] tatus=409 traceID=5b8a5939a269316ab03bd300734d0c69 vars="map[name:476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 version:1.30]"
         msg="/usr/sbin/iptables, [--wait -D FORWARD -j DOCKER-INGRESS]"
        time="2024-11-27T15:25:24.282770881Z" level=debug msg="/usr/sbin/iptables, [--wait -I FORWARD -j DOCKER-INGRESS]"
        time="2024-11-27T15:25:
    daemon.go:318: [d1f402d43c986] 4.283711571Z" level=debug msg="/usr/sbin/ip6tables, [--wait -t filter -n -L DOCKER-USER]"
        time="2024-11-27T15:25:24.2845
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.284582742Z" level=debug msg="/usr/sbin/ip6tables, [--wait -t filter -C DOCKER-USER -j RETURN]"
        time="2024-11-27T15:25:24.285416793Z" level=debug msg="/usr/sbin/ip6tables, [--wait -t filter -C FORWARD -j DOCKER-USER]"
        time="2024-11-27T15:25:24.28[624](https://github.com/moby/moby/actions/runs/12052806904/job/33607104239?pr=48940#step:8:625)5293Z" level=debug msg="/usr/sbin/ip6tables, [--wait -D FORWARD -j DOCKER-
    daemon.go:318: [d1f402d43c986] SER]"
        time="2024-11-27T15:25:24.287090315Z" level=debug msg="/usr/sbin/ip6tables, [--wait -I FORWARD -j DOCKER-USER]"
        tim
    daemon.go:318: [d1f402d43c986] ="2024-11-27T15:25:24.296085606Z" level=debug msg="state for task xk7tlac0fu71v6efzccli58as updated to FAILED" 
    daemon.go:318: [d1f402d43c986] ethod="(*Dispatcher).processUpdates" module=dispatcher node.id=7249c5nhcit7nfjd5x3gqjjfp state.transition="PREP
    daemon.go:318: [d1f402d43c986] RING->FAILED" task.id=xk7tlac0fu71v6efzccli58as
        time="2024-11-27T15:25:24.296196033Z" level=debug msg="dispatcher committed status update to store" 
    daemon.go:318: [d1f402d43c986] ethod="(*Dispatcher).processUpdates" module=dispatcher node.id=7249c5nhcit7nfjd5x3gqjjfp state.transition="PREPA
    daemon.go:318: [d1f402d43c986] ING->FAILED" task.id=xk7tlac0fu71v6efzccli58as
        time="2024-11-27T15:25:24.297552847Z" level=debug msg="task u7wy9m15eewxv84k3bnl3rsmi was marked pending allocation" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
        time="2024-1
    daemon.go:318: [d1f402d43c986] -27T15:25:24.297581310Z" level=debug msg="allocated task u7wy9m15eewxv84k3bnl3rsmi, state update PENDING" method="(*Allocator).allocateTask" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
        time="2024-11-27T15:25:24.297656050Z" level=debug msg="committed allocated task u7wy9m15eewxv84k3bnl3rsmi, state update {2024-11-27T15:25:24.297578655Z PENDING pending task scheduling  <nil> nil  (timestamp: nil Timestamp)}" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
        time="2024-11-27T15:25:24.297904685Z" level=debug msg="Task u7wy9m15eewxv84k3bnl3rsmi is already in allocated state PEND
    daemon.go:318: [d1f402d43c986] NG" method="(*Allocator).doTaskAlloc" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
        time="2024-11-27T15:25:24.337140041Z" level=debug msg="handling GET request" method=GET module=api request-url=/v1.48/tasks/xk7tlac0fu71v6efzccli58as spanID=ae16d9e9b7ea05a1 stat
    daemon.go:318: [d1f402d43c986] s=200 traceID=960d6e0ff6c5b6a9b5f06d5251a07480 vars="map[id:xk7tlac0fu71v6efzccli58as version:1.48]"
        time="2024-11-27T15:25:24.344742305Z" level=debug msg="handling GE
    daemon.go:318: [d1f402d43c986]  request" method=GET module=api request-url=/_ping spanID=93e339678072a872 status=200 traceID=cf807b128af9f9d1688e8b1776ec02ff v
    daemon.go:318: [d1f402d43c986] rs="map[]"
        time="2024-11-27T15:25:24.345360724Z" level=debug msg="handling GET request" method=GET module=api request-url=/v1.30/containers/476b27b5243e96ae3735138da1b
    daemon.go:318: [d1f402d43c986] 3965b4d266da7b8957bb190c849683b816e2/json spanID=96ad9ed5924bafe6 status=200 traceID=2d520589e23c6e0ac1558d6d366dff86 vars="map[
    daemon.go:318: [d1f402d43c986] ame:476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 version:1.30]"
        time="2024-11-27T15:25:24.346137792Z" level=error msg="Error setting up exec command in container 476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2: container 476b27b5243e96ae37351
    daemon.go:318: [d1f402d43c986] 8da1be3965b4d266da7b8957bb190c849683b816e2 is not running" spanID=6e3d6be286e4c611 traceID=5b8a5939a269316ab03bd300734d0c69
        time="2024-11-27T15:25:24.3461[632](https://github.com/moby/moby/actions/runs/12052806904/job/33607104239?pr=48940#step:8:633)20Z" level=debug msg="handling POST request" error-response="container 476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 is not running" form-data="{\"AttachStderr\":true,\"Att
    daemon.go:318: [d1f402d43c986] chStdin\":false,\"AttachStdout\":true,\"Cmd\":[\"cat\",\"/target1\"],\"Detach\":false,\"
    daemon.go:318: [d1f402d43c986] etachKeys\":\"\",\"Env\":null,\"Privileged\":false,\"Tty\":false,\"User\":\"\"}" method
    daemon.go:318: [d1f402d43c986] POST module=api request-url=/v1.30/containers/476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2/ex
    daemon.go:318: [d1f402d43c986] c spanID=6e3d6be286e4c611 status=409 traceID=5b8a5939a269316ab03bd300734d0c69 vars="map[name:476b27b5243e96ae3735138da1be39
    daemon.go:318: [d1f402d43c986] 5b4d266da7b8957bb190c849683b816e2 version:1.30]"
         msg="/usr/sbin/iptables, [--wait -D FORWARD -j DOCKER-INGRESS]"
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.282770881Z" level=debug msg="/usr/sbin/iptables, [--wait -I FORWARD -j DOCKER-INGRESS]"
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.283711571Z" level=debug msg="/usr/sbin/ip6tables, [--wait -t filter -n -L DOCKER-USER]"
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.284582742Z" level=debug msg="/usr/sbin/ip6tables, [--wait -t filter -C DOCKER-USER -j RETURN]"
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.285416793Z" level=debug msg="/usr/sbin/ip6tables, [--wait -t filter -C FORWARD -j DOCKER-USER]"
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.286245293Z" level=debug msg="/usr/sbin/ip6tables, [--wait -D FORWARD -j DOCKER-USER]"
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.287090315Z" level=debug msg="/usr/sbin/ip6tables, [--wait -I FORWARD -j DOCKER-USER]"
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.296085606Z" level=debug msg="state for task xk7tlac0fu71v6efzccli58as updated to FAILED" method="(*Dispatcher).processUpdates" module=dispatcher node.id=7249c5nhcit7nfjd5x3gqjjfp state.transition="PREPARING->FAILED" task.id=xk7tlac0fu71v6efzccli58as
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.296196033Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=7249c5nhcit7nfjd5x3gqjjfp state.transition="PREPARING->FAILED" task.id=xk7tlac0fu71v6efzccli58as
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.297552847Z" level=debug msg="task u7wy9m15eewxv84k3bnl3rsmi was marked pending allocation" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.297581310Z" level=debug msg="allocated task u7wy9m15eewxv84k3bnl3rsmi, state update PENDING" method="(*Allocator).allocateTask" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.297656050Z" level=debug msg="committed allocated task u7wy9m15eewxv84k3bnl3rsmi, state update {2024-11-27T15:25:24.297578[655](https://github.com/moby/moby/actions/runs/12052806904/job/33607104239?pr=48940#step:8:656)Z PENDING pending task scheduling  <nil> nil  (timestamp: nil Timestamp)}" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.297904685Z" level=debug msg="Task u7wy9m15eewxv84k3bnl3rsmi is already in allocated state PENDING" method="(*Allocator).doTaskAlloc" module=node node.id=7249c5nhcit7nfjd5x3gqjjfp
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.337140041Z" level=debug msg="handling GET request" method=GET module=api request-url=/v1.48/tasks/xk7tlac0fu71v6efzccli58as spanID=ae16d9e9b7ea05a1 status=200 traceID=960d6e0ff6c5b6a9b5f06d5251a07480 vars="map[id:xk7tlac0fu71v6efzccli58as version:1.48]"
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.344742305Z" level=debug msg="handling GET request" method=GET module=api request-url=/_ping spanID=93e339678072a872 status=200 traceID=cf807b128af9f9d1688e8b1776ec02ff vars="map[]"
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.345360724Z" level=debug msg="handling GET request" method=GET module=api request-url=/v1.30/containers/476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2/json spanID=96ad9ed5924bafe6 status=200 traceID=2d520589e23c6e0ac1558d6d366dff86 vars="map[name:476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 version:1.30]"
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.346137792Z" level=error msg="Error setting up exec command in container 476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2: container 476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 is not running" spanID=6e3d6be286e4c611 traceID=5b8a5939a269316ab03bd300734d0c69
    daemon.go:318: [d1f402d43c986] time="2024-11-27T15:25:24.346163220Z" level=debug msg="handling POST request" error-response="container 476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 is not running" form-data="{\"AttachStderr\":true,\"AttachStdin\":false,\"AttachStdout\":true,\"Cmd\":[\"cat\",\"/target1\"],\"Detach\":false,\"DetachKeys\":\"\",\"Env\":null,\"Privileged\":false,\"Tty\":false,\"User\":\"\"}" method=POST module=api request-url=/v1.30/containers/476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2/exec spanID=6e3d6be286e4c611 status=409 traceID=5b8a5939a269316ab03bd300734d0c69 vars="map[name:476b27b5243e96ae3735138da1be3965b4d266da7b8957bb190c849683b816e2 version:1.30]"
    --- FAIL: TestDockerSwarmSuite/TestServiceCreateWithConfigReferencedTwice (1.96s)

=== FAIL: amd64.integration-cli TestDockerSwarmSuite (1530.51s)

@thaJeztah
Copy link
Member Author

Thanks! Ok let's bring this one in and see if CI is more stable after this

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

[ci] fix networking flakiness on s390x, ppc64le, GitHub actions

5 participants