Skip to content

Potential performance regression (?) in v2.0 (even with --plain) #4317

New issue
New issue
Open
Open
Potential performance regression (?) in v2.0 (even with --plain)#4317
Labels
area/performanceexpertregressionUsed to work but has been broken
@AkihiroSuda

Description

@AkihiroSuda
AkihiroSuda
opened on Nov 7, 2025

Moby's CI is failing after upgrading Lima from v1.2.2 to v2.0.1:

This failure is assumed to be caused due to some performance regression in Lima v2.0.

The CI only uses --plain mode with oraclelinux-8 though.
The VM image was not changed in v1.2.2...v2.0.1 .

Hmm looks like the failure doesn't go away:


=== Failed
=== FAIL: amd64.docker.docker.integration.network.bridge TestCreateWithMultiNetworks (2.34s)
    bridge_linux_test.go:45: assertion failed: error is not nil: Post "http://%2Fgo%2Fsrc%2Fgithub.com%2Fdocker%2Fdocker%2Fbundles%2Ftest-integration%2Fdocker.sock/v1.52/containers/9b94e4146576363657b86a29079aa1011b0261f9aafb571730b0fb801510882d/start": context deadline exceeded
    panic.go:615: assertion failed: error is not nil: Error response from daemon: error while removing network: network testnet2 has active endpoints (name:"goofy_galois" id:"417e9f553aed")
    panic.go:615: assertion failed: error is not nil: Error response from daemon: error while removing network: network testnet1 has active endpoints (name:"goofy_galois" id:"b9ccc93c55df")

Originally posted by @vvoland in moby/moby#51420 (comment)

It hit a timeout ...

Daemon log for the non-rootless test... 
time="2025-11-06T16:35:14.970413750Z" level=debug msg="handling POST request" form-data="{\"AttachStderr\":true,\"AttachStdin\":false,\"AttachStdout\":true,\"Cmd\":[\"ip\",\"-o\",\"-4\",\"addr\",\"show\"],\"Domainname\":\"\",\"Entrypoint\":null,\"Env\":null,\"HostConfig\":{\"AutoRemove\":false,\"Binds\":null,\"BlkioDeviceReadBps\":null,\"BlkioDeviceReadIOps\":null,\"BlkioDeviceWriteBps\":null,\"BlkioDeviceWriteIOps\":null,\"BlkioWeight\":0,\"BlkioWeightDevice\":null,\"CapAdd\":null,\"CapDrop\":null,\"Cgroup\":\"\",\"CgroupParent\":\"\",\"CgroupnsMode\":\"\",\"ConsoleSize\":[0,0],\"ContainerIDFile\":\"\",\"CpuCount\":0,\"CpuPercent\":0,\"CpuPeriod\":0,\"CpuQuota\":0,\"CpuRealtimePeriod\":0,\"CpuRealtimeRuntime\":0,\"CpuShares\":0,\"CpusetCpus\":\"\",\"CpusetMems\":\"\",\"DeviceCgroupRules\":null,\"DeviceRequests\":null,\"Devices\":null,\"Dns\":null,\"DnsOptions\":null,\"DnsSearch\":null,\"ExtraHosts\":null,\"GroupAdd\":null,\"IOMaximumBandwidth\":0,\"IOMaximumIOps\":0,\"IpcMode\":\"\",\"Isolation\":\"\",\"Links\":null,\"LogConfig\":{\"Config\":null,\"Type\":\"\"},\"MaskedPaths\":null,\"Memory\":0,\"MemoryReservation\":0,\"MemorySwap\":0,\"MemorySwappiness\":null,\"NanoCpus\":0,\"NetworkMode\":\"testnet1\",\"OomKillDisable\":null,\"OomScoreAdj\":0,\"PidMode\":\"\",\"PidsLimit\":null,\"PortBindings\":null,\"Privileged\":false,\"PublishAllPorts\":false,\"ReadonlyPaths\":null,\"ReadonlyRootfs\":false,\"RestartPolicy\":{\"MaximumRetryCount\":0,\"Name\":\"\"},\"SecurityOpt\":null,\"ShmSize\":0,\"UTSMode\":\"\",\"Ulimits\":null,\"UsernsMode\":\"\",\"VolumeDriver\":\"\",\"VolumesFrom\":null},\"Hostname\":\"\",\"Image\":\"busybox\",\"Labels\":null,\"NetworkingConfig\":{\"EndpointsConfig\":{\"testnet1\":{\"Aliases\":null,\"DNSNames\":null,\"DriverOpts\":null,\"EndpointID\":\"\",\"Gateway\":\"\",\"GlobalIPv6Address\":\"\",\"GlobalIPv6PrefixLen\":0,\"GwPriority\":0,\"IPAMConfig\":null,\"IPAddress\":\"\",\"IPPrefixLen\":0,\"IPv6Gateway\":\"\",\"Links\":null,\"MacAddress\":\"\",\"NetworkID\":\"\"},\"testnet2\":{\"Aliases\":null,\"DNSNames\":null,\"DriverOpts\":null,\"EndpointID\":\"\",\"Gateway\":\"\",\"GlobalIPv6Address\":\"\",\"GlobalIPv6PrefixLen\":0,\"GwPriority\":0,\"IPAMConfig\":null,\"IPAddress\":\"\",\"IPPrefixLen\":0,\"IPv6Gateway\":\"\",\"Links\":null,\"MacAddress\":\"\",\"NetworkID\":\"\"}}},\"OpenStdin\":false,\"StdinOnce\":false,\"Tty\":false,\"User\":\"\",\"Volumes\":null,\"WorkingDir\":\"\"}" method=POST module=api request-url=/v1.52/containers/create vars="map[version:1.52]"
time="2025-11-06T16:35:14.978989832Z" level=debug msg="container mounted via layerStore" container=e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc root=/var/lib/docker/overlay2/040486241f5f166500fca1ff6aa362a2a9078996fc1201f11b3a3b3a08acf471/merged storage-driver=overlay2
time="2025-11-06T16:35:14.982970971Z" level=debug msg="handling POST request" method=POST module=api request-url="/v1.52/containers/e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc/attach?stderr=1&stdout=1&stream=1" vars="map[name:e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc version:1.52]"
time="2025-11-06T16:35:14.983162199Z" level=debug msg="attach: stdout: begin"
time="2025-11-06T16:35:14.983188267Z" level=debug msg="attach: stderr: begin"
time="2025-11-06T16:35:14.983544094Z" level=debug msg="handling POST request" method=POST module=api request-url=/v1.52/containers/e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc/start vars="map[name:e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc version:1.52]"
time="2025-11-06T16:35:14.983946966Z" level=debug msg="container mounted via layerStore" container=e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc root=/var/lib/docker/overlay2/040486241f5f166500fca1ff6aa362a2a9078996fc1201f11b3a3b3a08acf471/merged storage-driver=overlay2
time="2025-11-06T16:35:14.988100365Z" level=debug msg="bundle dir created" bundle=/var/run/docker/containerd/e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc module=libcontainerd namespace=moby root=/var/lib/docker/overlay2/040486241f5f166500fca1ff6aa362a2a9078996fc1201f11b3a3b3a08acf471/merged
time="2025-11-06T16:35:15.002206282Z" level=info msg="connecting to shim e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc" address="unix:///run/containerd/s/f3cd55b35b86ac16345262a5130394fa70a2b6dc514446141ab4f4a92ee98e29" namespace=moby protocol=ttrpc version=3
time="2025-11-06T16:35:15.005334828Z" level=debug msg="loading plugin" id=io.containerd.event.v1.publisher runtime=io.containerd.runc.v2 type=io.containerd.event.v1
time="2025-11-06T16:35:15.005564176Z" level=debug msg="loading plugin" id=io.containerd.internal.v1.shutdown runtime=io.containerd.runc.v2 type=io.containerd.internal.v1
time="2025-11-06T16:35:15.005592820Z" level=debug msg="loading plugin" id=io.containerd.ttrpc.v1.task runtime=io.containerd.runc.v2 type=io.containerd.ttrpc.v1
time="2025-11-06T16:35:15.007947499Z" level=debug msg="registering ttrpc service" id=io.containerd.ttrpc.v1.task runtime=io.containerd.runc.v2
time="2025-11-06T16:35:15.008124980Z" level=debug msg="serving api on socket" socket="[inherited from parent]"
time="2025-11-06T16:35:15.008144046Z" level=debug msg="starting signal loop" namespace=moby path=/run/docker/containerd/daemon/io.containerd.runtime.v2.task/moby/e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc pid=91636 runtime=io.containerd.runc.v2
time="2025-11-06T16:35:15.064127196Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/create
time="2025-11-06T16:35:15.065320415Z" level=debug msg="sandbox set key processing took 1.018102ms for container e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc"
time="2025-11-06T16:35:15.065459395Z" level=debug msg="Assigning addresses for endpoint affectionate_moser's interface on network testnet1"
time="2025-11-06T16:35:15.065508436Z" level=debug msg="RequestAddress(LocalDefault/172.21.0.0/16, <nil>, map[com.docker.network.endpoint.name:affectionate_moser])"
time="2025-11-06T16:35:15.065530277Z" level=debug msg="Request address PoolID:172.21.0.0/16 Bits: 65536, Unselected: 65533, Sequence: (0xc0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:2 Serial:false PrefAddress:invalid IP "
time="2025-11-06T16:35:15.091214269Z" level=debug msg="/usr/sbin/iptables, [--wait -t raw -C PREROUTING -d 172.21.0.2 ! -i br-0a5f54bf74ce -j DROP]"
time="2025-11-06T16:35:15.093323297Z" level=debug msg="/usr/sbin/iptables, [--wait -t raw -A PREROUTING -d 172.21.0.2 ! -i br-0a5f54bf74ce -j DROP]"
time="2025-11-06T16:35:15.112577252Z" level=debug msg="bridge endpoint host link is up" hostifname=veth059c105 ifi=815
time="2025-11-06T16:35:15.116345122Z" level=debug msg="/usr/sbin/iptables, [--wait -t nat -C OUTPUT -d 127.0.0.11 -j DOCKER_OUTPUT]"
time="2025-11-06T16:35:15.117831112Z" level=debug msg="/usr/sbin/iptables, [--wait -t nat -N DOCKER_OUTPUT]"
time="2025-11-06T16:35:15.119514837Z" level=debug msg="/usr/sbin/iptables, [--wait -t nat -I OUTPUT -d 127.0.0.11 -j DOCKER_OUTPUT]"
time="2025-11-06T16:35:15.120728525Z" level=debug msg="/usr/sbin/iptables, [--wait -t nat -C POSTROUTING -d 127.0.0.11 -j DOCKER_POSTROUTING]"
time="2025-11-06T16:35:15.121933566Z" level=debug msg="/usr/sbin/iptables, [--wait -t nat -N DOCKER_POSTROUTING]"
time="2025-11-06T16:35:15.123435804Z" level=debug msg="/usr/sbin/iptables, [--wait -t nat -I POSTROUTING -d 127.0.0.11 -j DOCKER_POSTROUTING]"
time="2025-11-06T16:35:15.124996889Z" level=debug msg="/usr/sbin/iptables, [--wait -t nat -I DOCKER_OUTPUT -d 127.0.0.11 -p udp --dport 53 -j DNAT --to-destination 127.0.0.11:43589]"
time="2025-11-06T16:35:15.376589266Z" level=debug msg="/usr/sbin/iptables, [--wait -t nat -I DOCKER_POSTROUTING -s 127.0.0.11 -p udp --sport 43589 -j SNAT --to-source :53]"
time="2025-11-06T16:35:15.378912417Z" level=debug msg="/usr/sbin/iptables, [--wait -t nat -I DOCKER_OUTPUT -d 127.0.0.11 -p tcp --dport 53 -j DNAT --to-destination 127.0.0.11:43223]"
time="2025-11-06T16:35:15.380783634Z" level=debug msg="/usr/sbin/iptables, [--wait -t nat -I DOCKER_POSTROUTING -s 127.0.0.11 -p tcp --sport 43223 -j SNAT --to-source :53]"
time="2025-11-06T16:35:15.694986553Z" level=debug msg="link has been set to up" eid=b65b42455e35 ep=affectionate_moser net=testnet1 nid=0a5f54bf74ce
time="2025-11-06T16:35:15.707026710Z" level=debug msg="link update" eid=b65b42455e35 ep=affectionate_moser flags="deviceFlags(IFF_UP | IFF_BROADCAST | IFF_RUNNING | IFF_MULTICAST | IFF_LOWER_UP)" iface=eth0 ifi=2 net=testnet1 nid=0a5f54bf74ce
time="2025-11-06T16:35:15.707465971Z" level=debug msg="Bridge port is forwarding" eid=b65b42455e35 ep=affectionate_moser net=testnet1 nid=0a5f54bf74ce veth=vethd588049
time="2025-11-06T16:35:15.707690820Z" level=debug msg="Sending unsolicited ARP/NA" eid=b65b42455e35 ep=affectionate_moser iface=eth0 ifi=2 ip4=172.21.0.2/16 ip6="<nil>" mac="0e:a9:3b:28:4e:74" mcastRouteOk=true net=testnet1 nid=0a5f54bf74ce
time="2025-11-06T16:35:15.709604356Z" level=debug msg="b65b42455e35035d847804c5e1e018abcd1d5bf5cac272e4949862c051e2dc4c (0a5f54b).addSvcRecords(affectionate_moser, 172.21.0.2, <nil>, true) updateSvcRecord sid:b65b42455e35035d847804c5e1e018abcd1d5bf5cac272e4949862c051e2dc4c"
time="2025-11-06T16:35:15.709635985Z" level=debug msg="b65b42455e35035d847804c5e1e018abcd1d5bf5cac272e4949862c051e2dc4c (0a5f54b).addSvcRecords(e2d260ff80a7, 172.21.0.2, <nil>, false) updateSvcRecord sid:b65b42455e35035d847804c5e1e018abcd1d5bf5cac272e4949862c051e2dc4c"
time="2025-11-06T16:35:15.709654970Z" level=info msg="sbJoin: gwep4 ''->'b65b42455e35', gwep6 ''->''" eid=b65b42455e35 ep=affectionate_moser net=testnet1 nid=0a5f54bf74ce
time="2025-11-06T16:35:15.709671030Z" level=debug msg="Programming external connectivity on endpoint" eid=b65b42455e35 ep=affectionate_moser epid=b65b42455e35 gw4=b65b42455e35 gw6= net=testnet1 nid=0a5f54bf74ce
time="2025-11-06T16:35:15.713229558Z" level=debug msg="EnableService START" container=e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc
time="2025-11-06T16:35:15.713247241Z" level=debug msg="EnableService DONE" container=e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc
time="2025-11-06T16:35:15.713322061Z" level=debug msg="Assigning addresses for endpoint affectionate_moser's interface on network testnet2"
time="2025-11-06T16:35:15.713333322Z" level=debug msg="RequestAddress(LocalDefault/172.22.0.0/16, <nil>, map[com.docker.network.endpoint.name:affectionate_moser])"
time="2025-11-06T16:35:15.713352357Z" level=debug msg="Request address PoolID:172.22.0.0/16 Bits: 65536, Unselected: 65533, Sequence: (0xc0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:2 Serial:false PrefAddress:invalid IP "
time="2025-11-06T16:35:15.878030181Z" level=debug msg="/usr/sbin/iptables, [--wait -t raw -C PREROUTING -d 172.22.0.2 ! -i br-5c17e515e598 -j DROP]"
time="2025-11-06T16:35:15.879729193Z" level=debug msg="/usr/sbin/iptables, [--wait -t raw -A PREROUTING -d 172.22.0.2 ! -i br-5c17e515e598 -j DROP]"
time="2025-11-06T16:35:15.885668753Z" level=debug msg="bridge endpoint host link is up" hostifname=veth8adbcab ifi=816
time="2025-11-06T16:35:15.972307071Z" level=debug msg="handling DELETE request" method=DELETE module=api request-url=/v1.52/networks/testnet2 vars="map[id:testnet2 version:1.52]"
time="2025-11-06T16:35:15.972594578Z" level=debug msg="error response for DELETE request" error-response="error while removing network: network testnet2 has active endpoints (name:\"affectionate_moser\" id:\"ecd26e7ef2e4\")" method=DELETE module=api request-url=/v1.52/networks/testnet2 status=403 vars="map[id:testnet2 version:1.52]"
time="2025-11-06T16:35:15.973246888Z" level=debug msg="handling DELETE request" method=DELETE module=api request-url=/v1.52/networks/testnet1 vars="map[id:testnet1 version:1.52]"
time="2025-11-06T16:35:15.973376960Z" level=debug msg="error response for DELETE request" error-response="error while removing network: network testnet1 has active endpoints (name:\"affectionate_moser\" id:\"b65b42455e35\")" method=DELETE module=api request-url=/v1.52/networks/testnet1 status=403 vars="map[id:testnet1 version:1.52]"
time="2025-11-06T16:35:15.974398438Z" level=debug msg="handling GET request" method=GET module=api request-url="/v1.52/containers/json?all=1&filters=%7B%22status%22%3A%7B%22paused%22%3Atrue%7D%7D" vars="map[version:1.52]"
time="2025-11-06T16:35:15.974866612Z" level=debug msg="handling GET request" method=GET module=api request-url="/v1.52/containers/json?all=1" vars="map[version:1.52]"
time="2025-11-06T16:35:15.976186648Z" level=debug msg="handling DELETE request" method=DELETE module=api request-url="/v1.52/containers/e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc?force=1&v=1" vars="map[name:e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc version:1.52]"
time="2025-11-06T16:35:16.497006120Z" level=debug msg="link has been set to up" eid=ecd26e7ef2e4 ep=affectionate_moser net=testnet2 nid=5c17e515e598
time="2025-11-06T16:35:16.506880972Z" level=debug msg="link update" eid=ecd26e7ef2e4 ep=affectionate_moser flags="deviceFlags(IFF_UP | IFF_BROADCAST | IFF_RUNNING | IFF_MULTICAST | IFF_LOWER_UP)" iface=eth1 ifi=3 net=testnet2 nid=5c17e515e598
time="2025-11-06T16:35:16.507202042Z" level=debug msg="Bridge port is forwarding" eid=ecd26e7ef2e4 ep=affectionate_moser net=testnet2 nid=5c17e515e598 veth=veth1582b5d
time="2025-11-06T16:35:16.509946891Z" level=debug msg="Sending unsolicited ARP/NA" eid=ecd26e7ef2e4 ep=affectionate_moser iface=eth1 ifi=3 ip4=172.22.0.2/16 ip6="<nil>" mac="6a:a5:d5:d9:a8:64" mcastRouteOk=true net=testnet2 nid=5c17e515e598
time="2025-11-06T16:35:16.511933952Z" level=debug msg="ecd26e7ef2e46108528c315573c9be64cad25f8a1b9c7ed044f7f6ca8838f150 (5c17e51).addSvcRecords(affectionate_moser, 172.22.0.2, <nil>, true) updateSvcRecord sid:ecd26e7ef2e46108528c315573c9be64cad25f8a1b9c7ed044f7f6ca8838f150"
time="2025-11-06T16:35:16.511963106Z" level=debug msg="ecd26e7ef2e46108528c315573c9be64cad25f8a1b9c7ed044f7f6ca8838f150 (5c17e51).addSvcRecords(e2d260ff80a7, 172.22.0.2, <nil>, false) updateSvcRecord sid:ecd26e7ef2e46108528c315573c9be64cad25f8a1b9c7ed044f7f6ca8838f150"
time="2025-11-06T16:35:16.511977423Z" level=info msg="sbJoin: gwep4 'b65b42455e35'->'b65b42455e35', gwep6 ''->''" eid=ecd26e7ef2e4 ep=affectionate_moser net=testnet2 nid=5c17e515e598
time="2025-11-06T16:35:16.511991320Z" level=debug msg="Programming external connectivity on endpoint" eid=ecd26e7ef2e4 ep=affectionate_moser epid=ecd26e7ef2e4 gw4=b65b42455e35 gw6= net=testnet2 nid=5c17e515e598
time="2025-11-06T16:35:16.516465922Z" level=debug msg="EnableService START" container=e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc
time="2025-11-06T16:35:16.516525593Z" level=debug msg="EnableService DONE" container=e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc
time="2025-11-06T16:35:16.709129532Z" level=debug msg="Sending unsolicited ARP/NA" eid=b65b42455e35 ep=affectionate_moser iface=eth0 ifi=2 ip4=172.21.0.2/16 ip6="<nil>" mac="0e:a9:3b:28:4e:74" mcastRouteOk=true n=1 net=testnet1 nid=0a5f54bf74ce
time="2025-11-06T16:35:16.810284854Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/start
time="2025-11-06T16:35:16.814809319Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/exit
time="2025-11-06T16:35:16.817379400Z" level=debug msg="sending signal 9 (killed) to container" container=e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc signal=9
time="2025-11-06T16:35:16.830141006Z" level=debug msg="container kill failed because of 'container not found' or 'no such process'" action=kill container=e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc error="NotFound: process already finished: not found"
time="2025-11-06T16:35:16.839035653Z" level=info msg="shim disconnected" id=e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc namespace=moby
time="2025-11-06T16:35:16.839083903Z" level=info msg="cleaning up after shim disconnected" id=e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc namespace=moby
time="2025-11-06T16:35:16.839095925Z" level=info msg="cleaning up dead shim" id=e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc namespace=moby
time="2025-11-06T16:35:16.839449966Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/delete
time="2025-11-06T16:35:16.839524215Z" level=info msg="ignoring event" container=e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
time="2025-11-06T16:35:16.850539649Z" level=warning msg="warnings while cleaning up dead shim" id=e2d260ff80a763b94d1713f63c8ff987542d74fd4f67827116da8423800666dc namespace=moby warnings="time=\"2025-11-06T16:35:16Z\" level=debug msg=\"starting signal loop\" namespace=moby pid=91701 runtime=io.containerd.runc.v2\n"
time="2025-11-06T16:35:16.851850146Z" level=debug msg="attach: stdout: end"
time="2025-11-06T16:35:16.851851952Z" level=debug msg="attach: stderr: end"
time="2025-11-06T16:35:16.851937148Z" level=debug msg="attach done"
time="2025-11-06T16:35:16.857660044Z" level=debug msg="Unsolicited ARP/NA sends cancelled" eid=b65b42455e35 ep=affectionate_moser iface=eth0 ifi=2 ip4=172.21.0.2/16 ip6="<nil>" mac="0e:a9:3b:28:4e:74" mcastRouteOk=true net=testnet1 nid=0a5f54bf74ce
time="2025-11-06T16:35:17.186400964Z" level=debug msg="Programming external connectivity on endpoint" eid=b65b42455e35035d847804c5e1e018abcd1d5bf5cac272e4949862c051e2dc4c ep=affectionate_moser epid=ecd26e7ef2e4 gw4=ecd26e7ef2e4 gw6= net=testnet1 nid=0a5f54bf74ce292ab9154a7fd019273a50068a20c3dba16c5869fce922a28d2d
time="2025-11-06T16:35:17.190431757Z" level=debug msg="b65b42455e35035d847804c5e1e018abcd1d5bf5cac272e4949862c051e2dc4c (0a5f54b).deleteSvcRecords(affectionate_moser, 172.21.0.2, <nil>, true) updateSvcRecord sid:b65b42455e35035d847804c5e1e018abcd1d5bf5cac272e4949862c051e2dc4c "
time="2025-11-06T16:35:17.190462814Z" level=debug msg="b65b42455e35035d847804c5e1e018abcd1d5bf5cac272e4949862c051e2dc4c (0a5f54b).deleteSvcRecords(e2d260ff80a7, 172.21.0.2, <nil>, false) updateSvcRecord sid:b65b42455e35035d847804c5e1e018abcd1d5bf5cac272e4949862c051e2dc4c "
time="2025-11-06T16:35:17.190523327Z" level=debug msg="/usr/sbin/iptables, [--wait -t raw -C PREROUTING -d 172.21.0.2 ! -i br-0a5f54bf74ce -j DROP]"
time="2025-11-06T16:35:17.192256236Z" level=debug msg="/usr/sbin/iptables, [--wait -t raw -D PREROUTING -d 172.21.0.2 ! -i br-0a5f54bf74ce -j DROP]"
time="2025-11-06T16:35:17.545329085Z" level=debug msg="Sending unsolicited ARP/NA" eid=ecd26e7ef2e4 ep=affectionate_moser iface=eth1 ifi=3 ip4=172.22.0.2/16 ip6="<nil>" mac="6a:a5:d5:d9:a8:64" mcastRouteOk=true n=1 net=testnet2 nid=5c17e515e598
time="2025-11-06T16:35:17.554094610Z" level=debug msg="Releasing addresses for endpoint affectionate_moser's interface on network testnet1"
time="2025-11-06T16:35:17.554146487Z" level=debug msg="ReleaseAddress(LocalDefault/172.21.0.0/16, 172.21.0.2)"
time="2025-11-06T16:35:17.554195188Z" level=debug msg="Released address Address:172.21.0.2 Sequence:Bits: 65536, Unselected: 65533, Sequence: (0xc0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3"
time="2025-11-06T16:35:17.558774576Z" level=debug msg="Unsolicited ARP/NA sends cancelled" eid=ecd26e7ef2e4 ep=affectionate_moser iface=eth1 ifi=3 ip4=172.22.0.2/16 ip6="<nil>" mac="6a:a5:d5:d9:a8:64" mcastRouteOk=true net=testnet2 nid=5c17e515e598
time="2025-11-06T16:35:17.727462437Z" level=debug msg="ecd26e7ef2e46108528c315573c9be64cad25f8a1b9c7ed044f7f6ca8838f150 (5c17e51).deleteSvcRecords(affectionate_moser, 172.22.0.2, <nil>, true) updateSvcRecord sid:ecd26e7ef2e46108528c315573c9be64cad25f8a1b9c7ed044f7f6ca8838f150 "
time="2025-11-06T16:35:17.727528441Z" level=debug msg="ecd26e7ef2e46108528c315573c9be64cad25f8a1b9c7ed044f7f6ca8838f150 (5c17e51).deleteSvcRecords(e2d260ff80a7, 172.22.0.2, <nil>, false) updateSvcRecord sid:ecd26e7ef2e46108528c315573c9be64cad25f8a1b9c7ed044f7f6ca8838f150 "
time="2025-11-06T16:35:17.727550052Z" level=debug msg="/usr/sbin/iptables, [--wait -t raw -C PREROUTING -d 172.22.0.2 ! -i br-5c17e515e598 -j DROP]"
time="2025-11-06T16:35:17.729173816Z" level=debug msg="/usr/sbin/iptables, [--wait -t raw -D PREROUTING -d 172.22.0.2 ! -i br-5c17e515e598 -j DROP]"
time="2025-11-06T16:35:18.060407449Z" level=debug msg="Releasing addresses for endpoint affectionate_moser's interface on network testnet2"
time="2025-11-06T16:35:18.060448255Z" level=debug msg="ReleaseAddress(LocalDefault/172.22.0.0/16, 172.22.0.2)"
time="2025-11-06T16:35:18.060498539Z" level=debug msg="Released address Address:172.22.0.2 Sequence:Bits: 65536, Unselected: 65533, Sequence: (0xc0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3"
time="2025-11-06T16:35:18.070425697Z" level=debug msg="handling GET request" method=GET module=api request-url=/v1.52/images/json vars="map[version:1.52]"
time="2025-11-06T16:35:18.071602054Z" level=debug msg="handling GET request" method=GET module=api request-url=/v1.52/volumes vars="map[version:1.52]"
time="2025-11-06T16:35:18.071645855Z" level=debug msg=VolumeStore.Find ByType=service.CustomFilter ByValue=0x564e3c3cee60
time="2025-11-06T16:35:18.072337838Z" level=debug msg="handling GET request" method=GET module=api request-url=/v1.52/networks vars="map[version:1.52]"
time="2025-11-06T16:35:18.073260995Z" level=debug msg="handling DELETE request" method=DELETE module=api request-url=/v1.52/networks/0a5f54bf74ce292ab9154a7fd019273a50068a20c3dba16c5869fce922a28d2d vars="map[id:0a5f54bf74ce292ab9154a7fd019273a50068a20c3dba16c5869fce922a28d2d version:1.52]"
time="2025-11-06T16:35:18.074437814Z" level=debug msg="releasing IPv4 pools from network testnet1 (0a5f54bf74ce292ab9154a7fd019273a50068a20c3dba16c5869fce922a28d2d)"
time="2025-11-06T16:35:18.074461077Z" level=debug msg="ReleaseAddress(LocalDefault/172.21.0.0/16, 172.21.0.1)"
time="2025-11-06T16:35:18.074505240Z" level=debug msg="Released address Address:172.21.0.1 Sequence:Bits: 65536, Unselected: 65534, Sequence: (0x80000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3"
time="2025-11-06T16:35:18.074512624Z" level=debug msg="ReleasePool(LocalDefault/172.21.0.0/16)"
time="2025-11-06T16:35:18.074519998Z" level=debug msg="cleanupServiceDiscovery for network:0a5f54bf74ce292ab9154a7fd019273a50068a20c3dba16c5869fce922a28d2d"
time="2025-11-06T16:35:18.093137371Z" level=debug msg="/usr/sbin/iptables, [--wait -t nat -C POSTROUTING -s 172.21.0.0/16 ! -o br-0a5f54bf74ce -j MASQUERADE]"
time="2025-11-06T16:35:18.095093415Z" level=debug msg="/usr/sbin/iptables, [--wait -t nat -D POSTROUTING -s 172.21.0.0/16 ! -o br-0a5f54bf74ce -j MASQUERADE]"
time="2025-11-06T16:35:18.103058448Z" level=debug msg="/usr/sbin/iptables, [--wait -t nat -C POSTROUTING -m addrtype --src-type LOCAL -o br-0a5f54bf74ce -j MASQUERADE]"
time="2025-11-06T16:35:18.104969010Z" level=debug msg="/usr/sbin/iptables, [--wait -t filter -C DOCKER-FORWARD -i br-0a5f54bf74ce -o br-0a5f54bf74ce -j ACCEPT]"
time="2025-11-06T16:35:18.106353546Z" level=debug msg="/usr/sbin/iptables, [--wait -t filter -C DOCKER-FORWARD -i br-0a5f54bf74ce -o br-0a5f54bf74ce -j DROP]"
time="2025-11-06T16:35:18.107632075Z" level=debug msg="/usr/sbin/iptables, [--wait -t filter -C DOCKER-FORWARD -i br-0a5f54bf74ce -j ACCEPT]"
time="2025-11-06T16:35:18.109078058Z" level=debug msg="/usr/sbin/iptables, [--wait -t filter -D DOCKER-FORWARD -i br-0a5f54bf74ce -j ACCEPT]"
time="2025-11-06T16:35:18.115023274Z" level=debug msg="/usr/sbin/iptables, [--wait -t filter -C DOCKER ! -i br-0a5f54bf74ce -o br-0a5f54bf74ce -j DROP]"
time="2025-11-06T16:35:18.116420694Z" level=debug msg="/usr/sbin/iptables, [--wait -t filter -D DOCKER ! -i br-0a5f54bf74ce -o br-0a5f54bf74ce -j DROP]"
time="2025-11-06T16:35:18.124034190Z" level=debug msg="/usr/sbin/iptables, [--wait -t filter -C DOCKER-CT -o br-0a5f54bf74ce -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]"
time="2025-11-06T16:35:18.125531537Z" level=debug msg="/usr/sbin/iptables, [--wait -t filter -D DOCKER-CT -o br-0a5f54bf74ce -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]"
time="2025-11-06T16:35:18.135016091Z" level=debug msg="/usr/sbin/iptables, [--wait -t filter -C DOCKER-BRIDGE -o br-0a5f54bf74ce -j DOCKER]"
time="2025-11-06T16:35:18.137033491Z" level=debug msg="/usr/sbin/iptables, [--wait -t filter -D DOCKER-BRIDGE -o br-0a5f54bf74ce -j DOCKER]"
time="2025-11-06T16:35:18.148078046Z" level=debug msg="handling DELETE request" method=DELETE module=api request-url=/v1.52/networks/5c17e515e5987f334f06de2decd4a43305c2bdbe89795767c0804e7a5488c42b vars="map[id:5c17e515e5987f334f06de2decd4a43305c2bdbe89795767c0804e7a5488c42b version:1.52]"
time="2025-11-06T16:35:18.149859245Z" level=debug msg="releasing IPv4 pools from network testnet2 (5c17e515e5987f334f06de2decd4a43305c2bdbe89795767c0804e7a5488c42b)"
time="2025-11-06T16:35:18.149883830Z" level=debug msg="ReleaseAddress(LocalDefault/172.22.0.0/16, 172.22.0.1)"
time="2025-11-06T16:35:18.149914348Z" level=debug msg="Released address Address:172.22.0.1 Sequence:Bits: 65536, Unselected: 65534, Sequence: (0x80000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3"
time="2025-11-06T16:35:18.149924006Z" level=debug msg="ReleasePool(LocalDefault/172.22.0.0/16)"

The container create request is at 16:35:14.970. Then, 1s later - because the test uses a context with a 1s timeout ...

time="2025-11-06T16:35:15.972307071Z" level=debug msg="handling DELETE request" method=DELETE module=api request-url=/v1.52/networks/testnet2 vars="map[id:testnet2 version:1.52]"

... but the container was still starting at that point.

In that run, this test failed, also with a 1s limit on a RunAttach ...

=== FAIL: amd64.docker.docker.integration.container TestCreateWithCustomMACs (1.72s)
    create_test.go:773: assertion failed: error is not nil: Post "http://%2Frun%2Fdocker%2Ftmp.ytezVwgJlQ%2Fdocker.sock/v1.52/containers/fd69d60cb377471eaa4239c6882f253ade73de9a8ddaddda9e2079bb8637f281/start": context deadline exceeded

Then the test run hits a 10 minute timeout, "panic: test timed out after 10m0s".

Maybe new-Lima is slower, and we need to bump up the timeouts. Or, maybe the test runner's just having a bad day?

Originally posted by @robmry in moby/moby#51420 (comment)

Metadata

Metadata

Assignees

No one assigned

    Labels

    area/performanceexpertregressionUsed to work but has been broken

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions