Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We鈥檒l occasionally send you account related emails.

Already on GitHub? Sign in to your account

Flaky test: TestServicePlugin, TestCreateServiceSecretFileMode #37132

Closed
thaJeztah opened this issue May 23, 2018 · 8 comments 路 Fixed by #42960
Closed

Flaky test: TestServicePlugin, TestCreateServiceSecretFileMode #37132

thaJeztah opened this issue May 23, 2018 · 8 comments 路 Fixed by #42960
Labels
area/swarm area/testing kind/bug Bugs are bugs. The cause may or may not be known at triage time so debugging may be needed.

Comments

@thaJeztah
Copy link
Member

thaJeztah commented May 23, 2018

This has been failing on several PR's

#37086 was increasing the timeout for swarm tests (but that was removed in favor of changing the timeout on a test-by-test base (#37086 (comment)))

00:49:31 === RUN   TestServicePlugin
00:50:30 --- FAIL: TestServicePlugin (59.53s)
00:50:30 	daemon.go:285: [d1e7868f8b0ee] waiting for daemon to start
00:50:30 	daemon.go:317: [d1e7868f8b0ee] daemon started
00:50:30 	daemon.go:275: [d1e7868f8b0ee] exiting daemon
00:50:30 	daemon.go:285: [d828dcf4073c4] waiting for daemon to start
00:50:30 	daemon.go:317: [d828dcf4073c4] daemon started
00:50:30 	daemon.go:285: [d409f87ad25cc] waiting for daemon to start
00:50:30 	daemon.go:317: [d409f87ad25cc] daemon started
00:50:30 	daemon.go:285: [d3b90e73c9588] waiting for daemon to start
00:50:30 	daemon.go:317: [d3b90e73c9588] daemon started
00:50:30 	plugin_test.go:92: timeout hit after 30s: plugin "test" exists
00:50:30 	daemon.go:275: [d3b90e73c9588] exiting daemon
00:50:30 	daemon.go:275: [d409f87ad25cc] exiting daemon
00:50:30 	daemon.go:275: [d828dcf4073c4] exiting daemon
00:50:30 FAIL

Other failures observed (#42923):

=== RUN   TestCreateServiceSecretFileMode
    create_test.go:291: assertion failed: 3 (int) != 1 (int)
--- FAIL: TestCreateServiceSecretFileMode (14.33s)
@thaJeztah thaJeztah added kind/bug Bugs are bugs. The cause may or may not be known at triage time so debugging may be needed. area/testing area/swarm labels May 23, 2018
@arm64b
Copy link
Contributor

arm64b commented May 24, 2018

Adjusting the timeout value for this specific case or bump all the service timeout value? I don't think we leave this test case failure with timeout reason as it is (or just rebuild it to pass) does make sense to help us to figure out the performance issue, as I said, couple of factors including the logic complexity of the test case itself, system performance, density of workload when the test begin to run and the scheduling will have effect on the duration of a test case...
Do we have some track system to record those slowdown test case and have plan to investigate it?

@arm64b
Copy link
Contributor

arm64b commented May 24, 2018

https://jenkins.dockerproject.org/job/Docker-PRs/49551/console in #37141

01:40:58 === RUN TestCreateServiceSecretFileMode
01:41:31 --- FAIL: TestCreateServiceSecretFileMode (32.33s)
01:41:31 daemon.go:285: [d43073d4909b7] waiting for daemon to start
01:41:31 daemon.go:317: [d43073d4909b7] daemon started
01:41:31 create_test.go:190: timeout hit after 30s: task count at 1 waiting for 0
01:41:31 daemon.go:275: [d43073d4909b7] exiting daemon

@thaJeztah
Copy link
Member Author

Do we have some track system to record those slowdown test case and have plan to investigate it?

I don't think we have, currently, but having detailed metrics about tests (pass/failure to identify flaky ones, ones that fail on specific configurations, and time to complete) has been discussed frequently; don't think anyone had time yet to dive into that

@vdemeester ?

@arm64b
Copy link
Contributor

arm64b commented May 24, 2018

Understood. Now we have captured 2 service related test cases timeout: TestServicePlugin and TestCreateServiceSecretFileMode.

@vdemeester
Copy link
Member

I don't think we have, currently, but having detailed metrics about tests (pass/failure to identify flaky ones, ones that fail on specific configurations, and time to complete) has been discussed frequently; don't think anyone had time yet to dive into that

Yep, it's exactly that : we discussed (for a while now 馃槤), but so far didn't had time to dive into it 馃槶

@thaJeztah thaJeztah changed the title Flaky test: TestServicePlugin Flaky test: TestServicePlugin, TestCreateServiceSecretFileMode Jun 7, 2018
@olljanat
Copy link
Contributor

olljanat commented Jan 6, 2019

PowerPC on #38050 failed to this:

18:02:16 === RUN   TestCreateServiceSecretFileMode
18:02:48 --- FAIL: TestCreateServiceSecretFileMode (32.66s)
18:02:48     daemon.go:296: [d7533b76d05d6] waiting for daemon to start
18:02:48     daemon.go:328: [d7533b76d05d6] daemon started
18:02:48     create_test.go:296: timeout hit after 30s: task count at 1 waiting for 0
18:02:48     daemon.go:283: [d7533b76d05d6] exiting daemon

@thaJeztah
Copy link
Member Author

This is from an ARM64 failure;

docker version, docker info
+ docker version
Client: Docker Engine - Community
 Version:           20.10.10-rc1
 API version:       1.41
 Go version:        go1.16.9
 Git commit:        b485636
 Built:             Mon Oct 18 15:21:14 2021
 OS/Arch:           linux/arm64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.10-rc1
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.16.9
  Git commit:       9f5b26f
  Built:            Mon Oct 18 15:19:46 2021
  OS/Arch:          linux/arm64
  Experimental:     true
 containerd:
  Version:          1.4.11
  GitCommit:        5b46e404f6b9f661a205e28d59c982d3634148f8
 runc:
  Version:          1.0.2
  GitCommit:        v1.0.2-0-g52b36a2
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0
+ docker info
Client:
 Context:    default
 Debug Mode: false
 Plugins:
  app: Docker App (Docker Inc., v0.9.1-beta3)
  buildx: Build with BuildKit (Docker Inc., v0.6.3-docker)

Server:
 Containers: 0
  Running: 0
  Paused: 0
  Stopped: 0
 Images: 0
 Server Version: 20.10.10-rc1
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
  userxattr: false
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Cgroup Version: 1
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runtime.v1.linux runc io.containerd.runc.v2
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 5b46e404f6b9f661a205e28d59c982d3634148f8
 runc version: v1.0.2-0-g52b36a2
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: default
 Kernel Version: 5.11.0-1020-aws
 Operating System: Ubuntu 20.04.3 LTS
 OSType: linux
 Architecture: aarch64
 CPUs: 2
 Total Memory: 7.582GiB
 Name: ip-10-100-95-219
 ID: 2QJQ:GFB4:R5EH:OJUD:6QSX:VWJY:GI53:DJTV:GPSZ:ID5L:T7WP:MQDN
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: true
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: true
check-config.sh output
+ echo check-config.sh version: 2b0755b936416834e14208c6c37b36977e67ea35
check-config.sh version: 2b0755b936416834e14208c6c37b36977e67ea35
+ curl -fsSL -o /home/ubuntu/workspace/moby_PR-42960/check-config.sh https://raw.githubusercontent.com/moby/moby/2b0755b936416834e14208c6c37b36977e67ea35/contrib/check-config.sh
+ bash /home/ubuntu/workspace/moby_PR-42960/check-config.sh
warning: /proc/config.gz does not exist, searching other paths for kernel config ...
info: reading kernel config from /boot/config-5.11.0-1020-aws ...

Generally Necessary:
- cgroup hierarchy: properly mounted [/sys/fs/cgroup]
- apparmor: enabled and tools installed
- CONFIG_NAMESPACES: enabled
- CONFIG_NET_NS: enabled
- CONFIG_PID_NS: enabled
- CONFIG_IPC_NS: enabled
- CONFIG_UTS_NS: enabled
- CONFIG_CGROUPS: enabled
- CONFIG_CGROUP_CPUACCT: enabled
- CONFIG_CGROUP_DEVICE: enabled
- CONFIG_CGROUP_FREEZER: enabled
- CONFIG_CGROUP_SCHED: enabled
- CONFIG_CPUSETS: enabled
- CONFIG_MEMCG: enabled
- CONFIG_KEYS: enabled
- CONFIG_VETH: enabled (as module)
- CONFIG_BRIDGE: enabled (as module)
- CONFIG_BRIDGE_NETFILTER: enabled (as module)
- CONFIG_IP_NF_FILTER: enabled (as module)
- CONFIG_IP_NF_TARGET_MASQUERADE: enabled (as module)
- CONFIG_NETFILTER_XT_MATCH_ADDRTYPE: enabled (as module)
- CONFIG_NETFILTER_XT_MATCH_CONNTRACK: enabled (as module)
- CONFIG_NETFILTER_XT_MATCH_IPVS: enabled (as module)
- CONFIG_NETFILTER_XT_MARK: enabled (as module)
- CONFIG_IP_NF_NAT: enabled (as module)
- CONFIG_NF_NAT: enabled (as module)
- CONFIG_POSIX_MQUEUE: enabled

Optional Features:
- CONFIG_USER_NS: enabled
- CONFIG_SECCOMP: enabled
- CONFIG_SECCOMP_FILTER: enabled
- CONFIG_CGROUP_PIDS: enabled
- CONFIG_MEMCG_SWAP: enabled
    (cgroup swap accounting is currently enabled)
- CONFIG_BLK_CGROUP: enabled
- CONFIG_BLK_DEV_THROTTLING: enabled
- CONFIG_CGROUP_PERF: enabled
- CONFIG_CGROUP_HUGETLB: enabled
- CONFIG_NET_CLS_CGROUP: enabled (as module)
- CONFIG_CGROUP_NET_PRIO: enabled
- CONFIG_CFS_BANDWIDTH: enabled
- CONFIG_FAIR_GROUP_SCHED: enabled
- CONFIG_RT_GROUP_SCHED: missing
- CONFIG_IP_NF_TARGET_REDIRECT: enabled (as module)
- CONFIG_IP_VS: enabled (as module)
- CONFIG_IP_VS_NFCT: enabled
- CONFIG_IP_VS_PROTO_TCP: enabled
- CONFIG_IP_VS_PROTO_UDP: enabled
- CONFIG_IP_VS_RR: enabled (as module)
- CONFIG_SECURITY_SELINUX: enabled
- CONFIG_SECURITY_APPARMOR: enabled
- CONFIG_EXT4_FS: enabled
- CONFIG_EXT4_FS_POSIX_ACL: enabled
- CONFIG_EXT4_FS_SECURITY: enabled
- Network Drivers:
  - "overlay":
    - CONFIG_VXLAN: enabled (as module)
    - CONFIG_BRIDGE_VLAN_FILTERING: enabled
      Optional (for encrypted networks):
      - CONFIG_CRYPTO: enabled
      - CONFIG_CRYPTO_AEAD: enabled
      - CONFIG_CRYPTO_GCM: enabled
      - CONFIG_CRYPTO_SEQIV: enabled
      - CONFIG_CRYPTO_GHASH: enabled
      - CONFIG_XFRM: enabled
      - CONFIG_XFRM_USER: enabled (as module)
      - CONFIG_XFRM_ALGO: enabled (as module)
      - CONFIG_INET_ESP: enabled (as module)
  - "ipvlan":
    - CONFIG_IPVLAN: enabled (as module)
  - "macvlan":
    - CONFIG_MACVLAN: enabled (as module)
    - CONFIG_DUMMY: enabled (as module)
  - "ftp,tftp client in container":
    - CONFIG_NF_NAT_FTP: enabled (as module)
    - CONFIG_NF_CONNTRACK_FTP: enabled (as module)
    - CONFIG_NF_NAT_TFTP: enabled (as module)
    - CONFIG_NF_CONNTRACK_TFTP: enabled (as module)
- Storage Drivers:
  - "aufs":
    - CONFIG_AUFS_FS: missing
  - "btrfs":
    - CONFIG_BTRFS_FS: enabled (as module)
    - CONFIG_BTRFS_FS_POSIX_ACL: enabled
  - "devicemapper":
    - CONFIG_BLK_DEV_DM: enabled
    - CONFIG_DM_THIN_PROVISIONING: enabled (as module)
  - "overlay":
    - CONFIG_OVERLAY_FS: enabled (as module)
  - "zfs":
    - /dev/zfs: present
    - zfs command: missing
    - zpool command: missing

Limits:
- /proc/sys/kernel/keys/root_maxkeys: 1000000

+ true

Full logs of that test run;

time="2021-10-25T20:18:24.067549419Z" level=info msg="Starting up"
time="2021-10-25T20:18:24.067638003Z" level=warning msg="Running experimental build"
time="2021-10-25T20:18:24.068688073Z" level=debug msg="Listener created for HTTP on unix (/tmp/docker-integration/d89225fe74486.sock)"
time="2021-10-25T20:18:24.069191672Z" level=debug msg="Golang's threads limit set to 55530"
time="2021-10-25T20:18:24.069616574Z" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2021-10-25T20:18:24.069632337Z" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2021-10-25T20:18:24.069654959Z" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///var/run/docker/containerd/containerd.sock  <nil> 0 <nil>}] <nil> <nil>}" module=grpc
time="2021-10-25T20:18:24.069637096Z" level=debug msg="metrics API listening on /tmp/dxr/d89225fe74486/metrics.sock"
time="2021-10-25T20:18:24.069668095Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2021-10-25T20:18:24.070765502Z" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2021-10-25T20:18:24.070782110Z" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2021-10-25T20:18:24.070800079Z" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///var/run/docker/containerd/containerd.sock  <nil> 0 <nil>}] <nil> <nil>}" module=grpc
time="2021-10-25T20:18:24.070811247Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2021-10-25T20:18:24.071409042Z" level=debug msg="Using default logging driver json-file"
time="2021-10-25T20:18:24.071425945Z" level=debug msg="[graphdriver] trying provided driver: overlay2"
time="2021-10-25T20:18:24.071876554Z" level=debug msg="processing event stream" module=libcontainerd namespace=d89225fe74486p
time="2021-10-25T20:18:24.086906950Z" level=debug msg="backingFs=extfs, projectQuotaSupported=false, indexOff=\"index=off,\", userxattr=\"\"" storage-driver=overlay2
time="2021-10-25T20:18:24.086962894Z" level=debug msg="Initialized graph driver overlay2"
time="2021-10-25T20:18:24.087241619Z" level=debug msg="No quota support for local volumes in /go/src/github.com/docker/docker/bundles/test-integration/TestCreateServiceConfigFileMode/d89225fe74486/root/volumes: Filesystem does not support, or has not enabled quotas"
time="2021-10-25T20:18:24.104950332Z" level=warning msg="Your kernel does not support CPU realtime scheduler"
time="2021-10-25T20:18:24.104976367Z" level=warning msg="Your kernel does not support cgroup blkio weight"
time="2021-10-25T20:18:24.104986328Z" level=warning msg="Your kernel does not support cgroup blkio weight_device"
time="2021-10-25T20:18:24.105129937Z" level=debug msg="Max Concurrent Downloads: 3"
time="2021-10-25T20:18:24.105141384Z" level=debug msg="Max Concurrent Uploads: 5"
time="2021-10-25T20:18:24.105148251Z" level=debug msg="Max Download Attempts: 5"
time="2021-10-25T20:18:24.105169610Z" level=info msg="Loading containers: start."
time="2021-10-25T20:18:24.105215518Z" level=debug msg="Option Experimental: true"
time="2021-10-25T20:18:24.105224520Z" level=debug msg="Option DefaultDriver: bridge"
time="2021-10-25T20:18:24.105231026Z" level=debug msg="Option DefaultNetwork: bridge"
time="2021-10-25T20:18:24.105238247Z" level=debug msg="Network Control Plane MTU: 1500"
time="2021-10-25T20:18:24.105288874Z" level=debug msg="processing event stream" module=libcontainerd namespace=d89225fe74486
time="2021-10-25T20:18:24.131136673Z" level=info msg="Default bridge (docker0) is assigned with an IP address 172.18.0.0/16. Daemon option --bip can be used to set a preferred IP address"
time="2021-10-25T20:18:24.131173835Z" level=debug msg="Allocating IPv4 pools for network bridge (828c92eba036e192bece56792f8478c0e36b9f80e5b40ac3e15ef1f06db519d9)"
time="2021-10-25T20:18:24.131188227Z" level=debug msg="RequestPool(LocalDefault, 172.18.0.0/16, , map[], false)"
time="2021-10-25T20:18:24.131219374Z" level=debug msg="RequestAddress(LocalDefault/172.18.0.0/16, 172.18.0.1, map[RequestAddressType:com.docker.network.gateway])"
time="2021-10-25T20:18:24.131247773Z" level=debug msg="Request address PoolID:172.18.0.0/16 App: ipam/default/data, ID: LocalDefault/172.18.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65534, Sequence: (0x80000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:0 Serial:false PrefAddress:172.18.0.1 "
time="2021-10-25T20:18:24.143870666Z" level=info msg="Loading containers: done."
time="2021-10-25T20:18:24.155459710Z" level=info msg="Docker daemon" commit=9c659947caf72e620264f264a64c39ba501abc99 graphdriver=overlay2 version=dev
time="2021-10-25T20:18:24.155548188Z" level=info msg="Daemon has completed initialization"
time="2021-10-25T20:18:24.183424849Z" level=debug msg="Registering routers"
time="2021-10-25T20:18:24.183462938Z" level=debug msg="Registering GET, /containers/{name:.*}/checkpoints"
time="2021-10-25T20:18:24.183563625Z" level=debug msg="Registering POST, /containers/{name:.*}/checkpoints"
time="2021-10-25T20:18:24.183628135Z" level=debug msg="Registering DELETE, /containers/{name}/checkpoints/{checkpoint}"
time="2021-10-25T20:18:24.183739760Z" level=debug msg="Registering HEAD, /containers/{name:.*}/archive"
time="2021-10-25T20:18:24.183793315Z" level=debug msg="Registering GET, /containers/json"
time="2021-10-25T20:18:24.183839068Z" level=debug msg="Registering GET, /containers/{name:.*}/export"
time="2021-10-25T20:18:24.183890655Z" level=debug msg="Registering GET, /containers/{name:.*}/changes"
time="2021-10-25T20:18:24.183950167Z" level=debug msg="Registering GET, /containers/{name:.*}/json"
time="2021-10-25T20:18:24.184000892Z" level=debug msg="Registering GET, /containers/{name:.*}/top"
time="2021-10-25T20:18:24.184056606Z" level=debug msg="Registering GET, /containers/{name:.*}/logs"
time="2021-10-25T20:18:24.184110293Z" level=debug msg="Registering GET, /containers/{name:.*}/stats"
time="2021-10-25T20:18:24.184189228Z" level=debug msg="Registering GET, /containers/{name:.*}/attach/ws"
time="2021-10-25T20:18:24.184248085Z" level=debug msg="Registering GET, /exec/{id:.*}/json"
time="2021-10-25T20:18:24.184296004Z" level=debug msg="Registering GET, /containers/{name:.*}/archive"
time="2021-10-25T20:18:24.184353055Z" level=debug msg="Registering POST, /containers/create"
time="2021-10-25T20:18:24.184389544Z" level=debug msg="Registering POST, /containers/{name:.*}/kill"
time="2021-10-25T20:18:24.184448860Z" level=debug msg="Registering POST, /containers/{name:.*}/pause"
time="2021-10-25T20:18:24.184499388Z" level=debug msg="Registering POST, /containers/{name:.*}/unpause"
time="2021-10-25T20:18:24.184555479Z" level=debug msg="Registering POST, /containers/{name:.*}/restart"
time="2021-10-25T20:18:24.184607804Z" level=debug msg="Registering POST, /containers/{name:.*}/start"
time="2021-10-25T20:18:24.184656347Z" level=debug msg="Registering POST, /containers/{name:.*}/stop"
time="2021-10-25T20:18:24.184710460Z" level=debug msg="Registering POST, /containers/{name:.*}/wait"
time="2021-10-25T20:18:24.184758601Z" level=debug msg="Registering POST, /containers/{name:.*}/resize"
time="2021-10-25T20:18:24.184812756Z" level=debug msg="Registering POST, /containers/{name:.*}/attach"
time="2021-10-25T20:18:24.184865368Z" level=debug msg="Registering POST, /containers/{name:.*}/copy"
time="2021-10-25T20:18:24.184914977Z" level=debug msg="Registering POST, /containers/{name:.*}/exec"
time="2021-10-25T20:18:24.184959638Z" level=debug msg="Registering POST, /exec/{name:.*}/start"
time="2021-10-25T20:18:24.185014564Z" level=debug msg="Registering POST, /exec/{name:.*}/resize"
time="2021-10-25T20:18:24.185105159Z" level=debug msg="Registering POST, /containers/{name:.*}/rename"
time="2021-10-25T20:18:24.185157377Z" level=debug msg="Registering POST, /containers/{name:.*}/update"
time="2021-10-25T20:18:24.185210006Z" level=debug msg="Registering POST, /containers/prune"
time="2021-10-25T20:18:24.185249678Z" level=debug msg="Registering POST, /commit"
time="2021-10-25T20:18:24.185283148Z" level=debug msg="Registering PUT, /containers/{name:.*}/archive"
time="2021-10-25T20:18:24.185332223Z" level=debug msg="Registering DELETE, /containers/{name:.*}"
time="2021-10-25T20:18:24.185389061Z" level=debug msg="Registering GET, /images/json"
time="2021-10-25T20:18:24.185424196Z" level=debug msg="Registering GET, /images/search"
time="2021-10-25T20:18:24.185463065Z" level=debug msg="Registering GET, /images/get"
time="2021-10-25T20:18:24.185496723Z" level=debug msg="Registering GET, /images/{name:.*}/get"
time="2021-10-25T20:18:24.185545470Z" level=debug msg="Registering GET, /images/{name:.*}/history"
time="2021-10-25T20:18:24.185597517Z" level=debug msg="Registering GET, /images/{name:.*}/json"
time="2021-10-25T20:18:24.185639757Z" level=debug msg="Registering POST, /images/load"
time="2021-10-25T20:18:24.185678888Z" level=debug msg="Registering POST, /images/create"
time="2021-10-25T20:18:24.185722335Z" level=debug msg="Registering POST, /images/{name:.*}/push"
time="2021-10-25T20:18:24.185783005Z" level=debug msg="Registering POST, /images/{name:.*}/tag"
time="2021-10-25T20:18:24.185831310Z" level=debug msg="Registering POST, /images/prune"
time="2021-10-25T20:18:24.185873288Z" level=debug msg="Registering DELETE, /images/{name:.*}"
time="2021-10-25T20:18:24.185914675Z" level=debug msg="Registering OPTIONS, /{anyroute:.*}"
time="2021-10-25T20:18:24.185977913Z" level=debug msg="Registering GET, /_ping"
time="2021-10-25T20:18:24.186004662Z" level=debug msg="Registering HEAD, /_ping"
time="2021-10-25T20:18:24.186037795Z" level=debug msg="Registering GET, /events"
time="2021-10-25T20:18:24.186065841Z" level=debug msg="Registering GET, /info"
time="2021-10-25T20:18:24.186093928Z" level=debug msg="Registering GET, /version"
time="2021-10-25T20:18:24.186127840Z" level=debug msg="Registering GET, /system/df"
time="2021-10-25T20:18:24.186159004Z" level=debug msg="Registering POST, /auth"
time="2021-10-25T20:18:24.186184202Z" level=debug msg="Registering GET, /volumes"
time="2021-10-25T20:18:24.186219452Z" level=debug msg="Registering GET, /volumes/{name:.*}"
time="2021-10-25T20:18:24.186276421Z" level=debug msg="Registering POST, /volumes/create"
time="2021-10-25T20:18:24.186309907Z" level=debug msg="Registering POST, /volumes/prune"
time="2021-10-25T20:18:24.186345526Z" level=debug msg="Registering DELETE, /volumes/{name:.*}"
time="2021-10-25T20:18:24.186399525Z" level=debug msg="Registering POST, /build"
time="2021-10-25T20:18:24.186427579Z" level=debug msg="Registering POST, /build/prune"
time="2021-10-25T20:18:24.186473791Z" level=debug msg="Registering POST, /build/cancel"
time="2021-10-25T20:18:24.186518616Z" level=debug msg="Registering POST, /session"
time="2021-10-25T20:18:24.186551905Z" level=debug msg="Registering POST, /swarm/init"
time="2021-10-25T20:18:24.186583192Z" level=debug msg="Registering POST, /swarm/join"
time="2021-10-25T20:18:24.186616817Z" level=debug msg="Registering POST, /swarm/leave"
time="2021-10-25T20:18:24.186648219Z" level=debug msg="Registering GET, /swarm"
time="2021-10-25T20:18:24.186680851Z" level=debug msg="Registering GET, /swarm/unlockkey"
time="2021-10-25T20:18:24.186716241Z" level=debug msg="Registering POST, /swarm/update"
time="2021-10-25T20:18:24.186752713Z" level=debug msg="Registering POST, /swarm/unlock"
time="2021-10-25T20:18:24.186784271Z" level=debug msg="Registering GET, /services"
time="2021-10-25T20:18:24.186820415Z" level=debug msg="Registering GET, /services/{id}"
time="2021-10-25T20:18:24.186863255Z" level=debug msg="Registering POST, /services/create"
time="2021-10-25T20:18:24.186903551Z" level=debug msg="Registering POST, /services/{id}/update"
time="2021-10-25T20:18:24.186958346Z" level=debug msg="Registering DELETE, /services/{id}"
time="2021-10-25T20:18:24.187005797Z" level=debug msg="Registering GET, /services/{id}/logs"
time="2021-10-25T20:18:24.187075287Z" level=debug msg="Registering GET, /nodes"
time="2021-10-25T20:18:24.187107312Z" level=debug msg="Registering GET, /nodes/{id}"
time="2021-10-25T20:18:24.187155321Z" level=debug msg="Registering DELETE, /nodes/{id}"
time="2021-10-25T20:18:24.187201304Z" level=debug msg="Registering POST, /nodes/{id}/update"
time="2021-10-25T20:18:24.187273658Z" level=debug msg="Registering GET, /tasks"
time="2021-10-25T20:18:24.187303427Z" level=debug msg="Registering GET, /tasks/{id}"
time="2021-10-25T20:18:24.187345512Z" level=debug msg="Registering GET, /tasks/{id}/logs"
time="2021-10-25T20:18:24.187398427Z" level=debug msg="Registering GET, /secrets"
time="2021-10-25T20:18:24.187433809Z" level=debug msg="Registering POST, /secrets/create"
time="2021-10-25T20:18:24.187475270Z" level=debug msg="Registering DELETE, /secrets/{id}"
time="2021-10-25T20:18:24.187520653Z" level=debug msg="Registering GET, /secrets/{id}"
time="2021-10-25T20:18:24.187562919Z" level=debug msg="Registering POST, /secrets/{id}/update"
time="2021-10-25T20:18:24.187614587Z" level=debug msg="Registering GET, /configs"
time="2021-10-25T20:18:24.187646128Z" level=debug msg="Registering POST, /configs/create"
time="2021-10-25T20:18:24.187697001Z" level=debug msg="Registering DELETE, /configs/{id}"
time="2021-10-25T20:18:24.187745658Z" level=debug msg="Registering GET, /configs/{id}"
time="2021-10-25T20:18:24.187791592Z" level=debug msg="Registering POST, /configs/{id}/update"
time="2021-10-25T20:18:24.187838148Z" level=debug msg="Registering GET, /plugins"
time="2021-10-25T20:18:24.187866760Z" level=debug msg="Registering GET, /plugins/{name:.*}/json"
time="2021-10-25T20:18:24.187923770Z" level=debug msg="Registering GET, /plugins/privileges"
time="2021-10-25T20:18:24.187964436Z" level=debug msg="Registering DELETE, /plugins/{name:.*}"
time="2021-10-25T20:18:24.188014816Z" level=debug msg="Registering POST, /plugins/{name:.*}/enable"
time="2021-10-25T20:18:24.188062645Z" level=debug msg="Registering POST, /plugins/{name:.*}/disable"
time="2021-10-25T20:18:24.188112516Z" level=debug msg="Registering POST, /plugins/pull"
time="2021-10-25T20:18:24.188196588Z" level=debug msg="Registering POST, /plugins/{name:.*}/push"
time="2021-10-25T20:18:24.188252129Z" level=debug msg="Registering POST, /plugins/{name:.*}/upgrade"
time="2021-10-25T20:18:24.188300171Z" level=debug msg="Registering POST, /plugins/{name:.*}/set"
time="2021-10-25T20:18:24.188349362Z" level=debug msg="Registering POST, /plugins/create"
time="2021-10-25T20:18:24.188388140Z" level=debug msg="Registering GET, /distribution/{name:.*}/json"
time="2021-10-25T20:18:24.188447513Z" level=debug msg="Registering POST, /grpc"
time="2021-10-25T20:18:24.188476010Z" level=debug msg="Registering GET, /networks"
time="2021-10-25T20:18:24.188514419Z" level=debug msg="Registering GET, /networks/"
time="2021-10-25T20:18:24.188545927Z" level=debug msg="Registering GET, /networks/{id:.+}"
time="2021-10-25T20:18:24.188594544Z" level=debug msg="Registering POST, /networks/create"
time="2021-10-25T20:18:24.188632321Z" level=debug msg="Registering POST, /networks/{id:.*}/connect"
time="2021-10-25T20:18:24.188681257Z" level=debug msg="Registering POST, /networks/{id:.*}/disconnect"
time="2021-10-25T20:18:24.188731170Z" level=debug msg="Registering POST, /networks/prune"
time="2021-10-25T20:18:24.188770055Z" level=debug msg="Registering DELETE, /networks/{id:.*}"
time="2021-10-25T20:18:24.188954279Z" level=info msg="API listen on /tmp/docker-integration/d89225fe74486.sock"
time="2021-10-25T20:18:24.522276621Z" level=debug msg="Calling GET /_ping"
time="2021-10-25T20:18:24.522666290Z" level=debug msg="Calling GET /info"
time="2021-10-25T20:18:24.549335840Z" level=debug msg="Calling POST /v1.42/images/load?quiet=1"
time="2021-10-25T20:18:24.600564156Z" level=debug msg="Applying tar in /go/src/github.com/docker/docker/bundles/test-integration/TestCreateServiceConfigFileMode/d89225fe74486/root/overlay2/aa651687dffea7222bb1da53fda6d7f4dd955f11be2ee4281403f49b73c4edcd/diff" storage-driver=overlay2
time="2021-10-25T20:18:24.660523078Z" level=debug msg="Applied tar sha256:7ce37844ca75600dbcbe085858845c5b92b6109db3c8c1ae6eb887aab91ad04f to aa651687dffea7222bb1da53fda6d7f4dd955f11be2ee4281403f49b73c4edcd, size: 1384134"
time="2021-10-25T20:18:24.689340417Z" level=debug msg="Calling POST /v1.42/swarm/init"
time="2021-10-25T20:18:24.689432800Z" level=debug msg="form data: {\"AdvertiseAddr\":\"\",\"AutoLockManagers\":false,\"Availability\":\"\",\"DataPathAddr\":\"\",\"DataPathPort\":0,\"DefaultAddrPool\":null,\"ForceNewCluster\":false,\"ListenAddr\":\"0.0.0.0:2477\",\"Spec\":{\"CAConfig\":{},\"Dispatcher\":{},\"EncryptionConfig\":{\"AutoLockManagers\":false},\"Labels\":null,\"Orchestration\":{},\"Raft\":{\"ElectionTick\":0,\"HeartbeatTick\":0},\"TaskDefaults\":{}},\"SubnetSize\":0}"
time="2021-10-25T20:18:24.697170804Z" level=debug msg="generated CA key and certificate" module=node
time="2021-10-25T20:18:24.697209705Z" level=debug msg="no node credentials found in: /go/src/github.com/docker/docker/bundles/test-integration/TestCreateServiceConfigFileMode/d89225fe74486/root/swarm/certificates/swarm-node.crt" error="open /go/src/github.com/docker/docker/bundles/test-integration/TestCreateServiceConfigFileMode/d89225fe74486/root/swarm/certificates/swarm-node.key: no such file or directory" module=node
time="2021-10-25T20:18:24.704295365Z" level=debug msg="issued new TLS certificate" module=node/tls node.id=n6wmszz1qlkitmno35aa78prk node.role=swarm-manager
time="2021-10-25T20:18:24.704385188Z" level=debug msg="new node credentials generated: /go/src/github.com/docker/docker/bundles/test-integration/TestCreateServiceConfigFileMode/d89225fe74486/root/swarm/certificates/swarm-node.crt" module=node/tls node.id=n6wmszz1qlkitmno35aa78prk node.role=swarm-manager
time="2021-10-25T20:18:24.707833292Z" level=debug msg="next certificate renewal scheduled for 1241h35m35.292176915s from now" fields.time="2021-12-16 13:54:00.000000213 +0000 UTC m=+4469735.967748351" module=node/tls node.id=n6wmszz1qlkitmno35aa78prk node.role=swarm-manager
time="2021-10-25T20:18:24.710725817Z" level=info msg="parsed scheme: \"\"" module=grpc
time="2021-10-25T20:18:24.710759622Z" level=info msg="scheme \"\" not registered, fallback to default scheme" module=grpc
time="2021-10-25T20:18:24.710782655Z" level=info msg="ccResolverWrapper: sending update to cc: {[{/tmp/dxr/d89225fe74486/swarm/control.sock  <nil> 0 <nil>}] <nil> <nil>}" module=grpc
time="2021-10-25T20:18:24.710794388Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2021-10-25T20:18:24.710834233Z" level=info msg="blockingPicker: the picked transport is not ready, loop back to repick" module=grpc
time="2021-10-25T20:18:24.713770196Z" level=info msg="Listening for connections" addr="[::]:2477" module=node node.id=n6wmszz1qlkitmno35aa78prk proto=tcp
time="2021-10-25T20:18:24.713819469Z" level=info msg="Listening for local connections" addr=/tmp/dxr/d89225fe74486/swarm/control.sock module=node node.id=n6wmszz1qlkitmno35aa78prk proto=unix
time="2021-10-25T20:18:24.724630038Z" level=info msg="1d84fbe2352ae6b0 became follower at term 0" module=raft node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:24.724659741Z" level=info msg="newRaft 1d84fbe2352ae6b0 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]" module=raft node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:24.724671475Z" level=info msg="1d84fbe2352ae6b0 became follower at term 1" module=raft node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:24.725775987Z" level=info msg="1d84fbe2352ae6b0 is starting a new election at term 1" module=raft node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:24.725814339Z" level=info msg="1d84fbe2352ae6b0 became candidate at term 2" module=raft node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:24.725827073Z" level=info msg="1d84fbe2352ae6b0 received MsgVoteResp from 1d84fbe2352ae6b0 at term 2" module=raft node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:24.725839882Z" level=info msg="1d84fbe2352ae6b0 became leader at term 2" module=raft node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:24.725848891Z" level=info msg="raft.node: 1d84fbe2352ae6b0 elected leader 1d84fbe2352ae6b0 at term 2" module=raft node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:24.727209367Z" level=info msg="Creating default ingress network" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:24.728681361Z" level=info msg="leadership changed from not yet part of a raft cluster to n6wmszz1qlkitmno35aa78prk" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:24.728737773Z" level=info msg="dispatcher starting" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:24.731499062Z" level=debug msg="Root CA set successfully" cluster.id=mp7csa554ry9bf12hfs4ex4os method="(*Server).UpdateRootCA" module=ca node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:24.734832875Z" level=debug msg="RequestPool(GlobalDefault, , , map[], false)"
time="2021-10-25T20:18:24.734874295Z" level=debug msg="RequestAddress(GlobalDefault/10.0.0.0/24, <nil>, map[RequestAddressType:com.docker.network.gateway com.docker.network.ipam.serial:true])"
time="2021-10-25T20:18:24.734894734Z" level=debug msg="Request address PoolID:10.0.0.0/24 App: ipam/default/data, ID: GlobalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 254, Sequence: (0x80000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:0 Serial:true PrefAddress:<nil> "
time="2021-10-25T20:18:24.737615342Z" level=debug msg="RequestAddress(GlobalDefault/10.0.0.0/24, <nil>, map[com.docker.network.ipam.serial:true])"
time="2021-10-25T20:18:24.737642362Z" level=debug msg="Request address PoolID:10.0.0.0/24 App: ipam/default/data, ID: GlobalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 253, Sequence: (0xc0000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:2 Serial:true PrefAddress:<nil> "
time="2021-10-25T20:18:25.218619065Z" level=debug msg="(*Agent).run" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.224169387Z" level=info msg="manager selected by agent for new session: { }" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.224299120Z" level=info msg="waiting 0s before registering session" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.225175009Z" level=debug msg="(*session).start" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.232652702Z" level=debug msg="node status updated" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.235478469Z" level=info msg="worker n6wmszz1qlkitmno35aa78prk was successfully registered" method="(*Dispatcher).register"
time="2021-10-25T20:18:25.235739700Z" level=debug msg="(*session).heartbeat" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk session.id=b5qczs8bayj4bc2b5hmtxsqqq
time="2021-10-25T20:18:25.235772185Z" level=debug msg="(*session).listen" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk session.id=b5qczs8bayj4bc2b5hmtxsqqq
time="2021-10-25T20:18:25.235780103Z" level=debug msg="sending heartbeat to manager { } with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk session.id=b5qczs8bayj4bc2b5hmtxsqqq sessionID=b5qczs8bayj4bc2b5hmtxsqqq
time="2021-10-25T20:18:25.235762634Z" level=debug method="(*session).watch" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk session.id=b5qczs8bayj4bc2b5hmtxsqqq
time="2021-10-25T20:18:25.235738773Z" level=debug method="(*session).logSubscriptions" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk session.id=b5qczs8bayj4bc2b5hmtxsqqq
time="2021-10-25T20:18:25.236057400Z" level=debug msg="node registered" method="(*LogBroker).ListenSubscriptions" node=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.236121746Z" level=debug msg="received heartbeat from worker {[swarm-manager] mp7csa554ry9bf12hfs4ex4os n6wmszz1qlkitmno35aa78prk <nil> 127.0.0.1:2477}, expect next heartbeat in 4.799759416s" method="(*Dispatcher).Heartbeat"
time="2021-10-25T20:18:25.236192664Z" level=debug method="(*Dispatcher).Assignments" node.id=n6wmszz1qlkitmno35aa78prk node.session=b5qczs8bayj4bc2b5hmtxsqqq
time="2021-10-25T20:18:25.236327863Z" level=debug msg="heartbeat successful to manager { }, next heartbeat period: 4.799759416s" method="(*session).heartbeat" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk session.id=b5qczs8bayj4bc2b5hmtxsqqq sessionID=b5qczs8bayj4bc2b5hmtxsqqq
time="2021-10-25T20:18:25.238826428Z" level=debug msg="agent: registered" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.238847433Z" level=debug msg="(*worker).Assign" len(assignments)=0 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.238866633Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.238879590Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.238877612Z" level=info msg="initialized VXLAN UDP port to 4789 "
time="2021-10-25T20:18:25.238890437Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=0 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.238873034Z" level=info msg="Initializing Libnetwork Agent Listen-Addr=0.0.0.0 Local-addr=127.0.0.1 Adv-addr=127.0.0.1 Data-addr= Remote-addr-list=[] MTU=1500"
time="2021-10-25T20:18:25.239030796Z" level=debug msg="Control plane MTU: 1500 will initialize NetworkDB with: 1400"
time="2021-10-25T20:18:25.239065628Z" level=info msg="New memberlist node - Node:5469dc37a441 will use memberlist nodeID:9b2bebf66441 with config:&{NodeID:9b2bebf66441 Hostname:5469dc37a441 BindAddr:0.0.0.0 AdvertiseAddr:127.0.0.1 BindPort:0 Keys:[[187 150 27 229 167 230 165 57 59 133 201 135 189 36 159 95] [112 127 167 7 216 107 244 235 162 34 89 209 194 14 73 40] [57 204 200 35 77 163 221 152 71 178 57 210 19 169 143 158]] PacketBufferSize:1400 reapEntryInterval:1800000000000 reapNetworkInterval:1825000000000 rejoinClusterDuration:10000000000 rejoinClusterInterval:60000000000 StatsPrintPeriod:5m0s HealthPrintPeriod:1m0s}"
time="2021-10-25T20:18:25.239088053Z" level=debug msg="Encryption key 1: bb961"
time="2021-10-25T20:18:25.239094748Z" level=debug msg="Encryption key 2: 707fa"
time="2021-10-25T20:18:25.239100943Z" level=debug msg="Encryption key 3: 39ccc"
time="2021-10-25T20:18:25.239356538Z" level=info msg="Node 9b2bebf66441/127.0.0.1, joined gossip cluster"
time="2021-10-25T20:18:25.239421056Z" level=info msg="Node 9b2bebf66441/127.0.0.1, added to nodes list"
time="2021-10-25T20:18:25.239572386Z" level=debug msg="Initial encryption keys: [(key: a93af, tag: 0xe17) (key: 997db, tag: 0xe16) (key: 78b2b, tag: 0xe18)]"
time="2021-10-25T20:18:25.239731511Z" level=debug msg="Initial encryption keys: [(key: a93af, tag: 0xe17) (key: 997db, tag: 0xe16) (key: 78b2b, tag: 0xe18)]"
time="2021-10-25T20:18:25.239917040Z" level=debug msg="Allocating IPv4 pools for network ingress (ipnwxmo3pb9g4td9cfx1lziu2)"
time="2021-10-25T20:18:25.239933082Z" level=debug msg="RequestPool(LocalDefault, 10.0.0.0/24, , map[], false)"
time="2021-10-25T20:18:25.239955737Z" level=debug msg="RequestAddress(LocalDefault/10.0.0.0/24, 10.0.0.1, map[RequestAddressType:com.docker.network.gateway])"
time="2021-10-25T20:18:25.239979384Z" level=debug msg="Request address PoolID:10.0.0.0/24 App: ipam/default/data, ID: LocalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 254, Sequence: (0x80000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:0 Serial:false PrefAddress:10.0.0.1 "
time="2021-10-25T20:18:25.240018893Z" level=error msg="error reading the kernel parameter net.ipv4.neigh.default.gc_thresh1" error="open /proc/sys/net/ipv4/neigh/default/gc_thresh1: no such file or directory"
time="2021-10-25T20:18:25.240039595Z" level=error msg="error reading the kernel parameter net.ipv4.neigh.default.gc_thresh2" error="open /proc/sys/net/ipv4/neigh/default/gc_thresh2: no such file or directory"
time="2021-10-25T20:18:25.240056268Z" level=error msg="error reading the kernel parameter net.ipv4.neigh.default.gc_thresh3" error="open /proc/sys/net/ipv4/neigh/default/gc_thresh3: no such file or directory"
time="2021-10-25T20:18:25.240069413Z" level=debug msg="overlay: Received vxlan IDs: 4096"
time="2021-10-25T20:18:25.241334773Z" level=debug msg="Fail to initialize firewalld: Failed to connect to D-Bus system bus: dial unix /var/run/dbus/system_bus_socket: connect: no such file or directory, using raw iptables instead"
time="2021-10-25T20:18:25.242902851Z" level=debug msg="/usr/sbin/iptables, [--wait -t mangle -C OUTPUT -p udp --dport 4789 -m u32 --u32 0>>22&0x3C@12&0xFFFFFF00=1048576 -j MARK --set-mark 13681891]"
time="2021-10-25T20:18:25.244164224Z" level=debug msg="/usr/sbin/iptables, [--wait -t filter -C INPUT -m policy --dir in --pol ipsec -p udp --dport 4789 -m u32 --u32 0>>22&0x3C@12&0xFFFFFF00=1048576 -j ACCEPT]"
time="2021-10-25T20:18:25.245424096Z" level=debug msg="/usr/sbin/iptables, [--wait -t filter -C INPUT -p udp --dport 4789 -m u32 --u32 0>>22&0x3C@12&0xFFFFFF00=1048576 -j DROP]"
time="2021-10-25T20:18:25.246753376Z" level=debug msg="5469dc37a441(9b2bebf66441): joined network ipnwxmo3pb9g4td9cfx1lziu2"
time="2021-10-25T20:18:25.251378962Z" level=debug msg="Calling GET /v1.42/info"
time="2021-10-25T20:18:25.262646345Z" level=debug msg="Calling POST /v1.42/configs/create"
time="2021-10-25T20:18:25.262717124Z" level=debug msg="form data: {\"Data\":\"*****\",\"Labels\":null,\"Name\":\"TestConfig_TestCreateServiceConfigFileMode\"}"
time="2021-10-25T20:18:25.264695810Z" level=debug msg="config created" config.Name=TestConfig_TestCreateServiceConfigFileMode method=CreateConfig
time="2021-10-25T20:18:25.265383429Z" level=debug msg="Calling POST /v1.42/services/create"
time="2021-10-25T20:18:25.265480793Z" level=debug msg="form data: {\"Labels\":null,\"Mode\":{\"Replicated\":{\"Replicas\":1}},\"Name\":\"TestService_TestCreateServiceConfigFileMode\",\"TaskTemplate\":{\"ContainerSpec\":{\"Command\":[\"/bin/sh\",\"-c\",\"ls -l /etc/config || /bin/top\"],\"Configs\":[{\"ConfigID\":\"fx88vma7jp9eotidq119q6k74\",\"ConfigName\":\"TestConfig_TestCreateServiceConfigFileMode\",\"File\":{\"GID\":\"0\",\"Mode\":511,\"Name\":\"/etc/config\",\"UID\":\"0\"}}],\"Image\":\"busybox:latest\"},\"ForceUpdate\":0}}"
time="2021-10-25T20:18:25.267879918Z" level=debug msg="Service 1brvqsvnaaaj0mybfxc4zvkjt was scaled up from 0 to 1 instances" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.268609007Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:25.269521573Z" level=debug msg="task 2ln943bqdzq2hz09egfan8079 was marked pending allocation" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.269560983Z" level=debug msg="allocated task 2ln943bqdzq2hz09egfan8079, state update PENDING" method="(*Allocator).allocateTask" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.269674757Z" level=debug msg="committed allocated task 2ln943bqdzq2hz09egfan8079, state update {2021-10-25T20:18:25.269551678Z PENDING pending task scheduling  <nil> nil  (timestamp: nil Timestamp)}" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.271084539Z" level=debug msg="Task 2ln943bqdzq2hz09egfan8079 is already in allocated state PENDING" method="(*Allocator).doTaskAlloc" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.321235821Z" level=debug msg="assigning to node n6wmszz1qlkitmno35aa78prk" module=node node.id=n6wmszz1qlkitmno35aa78prk task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.322876024Z" level=debug msg="Task 2ln943bqdzq2hz09egfan8079 is already in allocated state ASSIGNED" method="(*Allocator).doTaskAlloc" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.335793111Z" level=error msg="error reading the kernel parameter net.ipv4.vs.conn_reuse_mode" error="open /proc/sys/net/ipv4/vs/conn_reuse_mode: no such file or directory"
time="2021-10-25T20:18:25.335828197Z" level=error msg="error reading the kernel parameter net.ipv4.vs.expire_nodest_conn" error="open /proc/sys/net/ipv4/vs/expire_nodest_conn: no such file or directory"
time="2021-10-25T20:18:25.335844624Z" level=error msg="error reading the kernel parameter net.ipv4.vs.expire_quiescent_template" error="open /proc/sys/net/ipv4/vs/expire_quiescent_template: no such file or directory"
time="2021-10-25T20:18:25.338074687Z" level=debug msg="Assigning addresses for endpoint ingress-endpoint's interface on network ingress"
time="2021-10-25T20:18:25.338097334Z" level=debug msg="RequestAddress(LocalDefault/10.0.0.0/24, 10.0.0.2, map[])"
time="2021-10-25T20:18:25.338117552Z" level=debug msg="Request address PoolID:10.0.0.0/24 App: ipam/default/data, ID: LocalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 253, Sequence: (0xc0000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:0 Serial:false PrefAddress:10.0.0.2 "
time="2021-10-25T20:18:25.340581999Z" level=debug msg="Assigning addresses for endpoint ingress-endpoint's interface on network ingress"
time="2021-10-25T20:18:25.369843436Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:25.424108919Z" level=debug msg="(*worker).Update" len(assignments)=2 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.424167390Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.424183341Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=1 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.424208736Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=1 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.424225721Z" level=debug msg=assigned module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.desiredstate=RUNNING task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.424318096Z" level=debug msg="state changed" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=RUNNING state.transition="ASSIGNED->ACCEPTED" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.424399846Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.424543077Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=RUNNING state.transition="ASSIGNED->ACCEPTED" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.431007614Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.431033084Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.431182707Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.435121881Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=RUNNING state.transition="ACCEPTED->PREPARING" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.435214970Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.435445144Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.436576488Z" level=debug msg="state for task 2ln943bqdzq2hz09egfan8079 updated to PREPARING" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="ASSIGNED->PREPARING" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.436676822Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="ASSIGNED->PREPARING" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.439656487Z" level=debug msg="Task 2ln943bqdzq2hz09egfan8079 is already in allocated state PREPARING" method="(*Allocator).doTaskAlloc" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.461243387Z" level=debug msg="container mounted via layerStore: &{/go/src/github.com/docker/docker/bundles/test-integration/TestCreateServiceConfigFileMode/d89225fe74486/root/overlay2/556694bce86421b153d985fa25bdb784f5d66301afab434cc83c2667d11ce257/merged 0xaaaabc801500 0xaaaabc801500}" container=3d5bcebd3bf5ea17f50382a74e92c3b2695ab0be261f0b126b29b92533103232
time="2021-10-25T20:18:25.471230098Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:25.477021959Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=RUNNING state.transition="PREPARING->READY" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.477142060Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.477412309Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.479199632Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=RUNNING state.transition="READY->STARTING" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.479298005Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.479528795Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.481669897Z" level=debug msg="container mounted via layerStore: &{/go/src/github.com/docker/docker/bundles/test-integration/TestCreateServiceConfigFileMode/d89225fe74486/root/overlay2/556694bce86421b153d985fa25bdb784f5d66301afab434cc83c2667d11ce257/merged 0xaaaabc801500 0xaaaabc801500}" container=3d5bcebd3bf5ea17f50382a74e92c3b2695ab0be261f0b126b29b92533103232
time="2021-10-25T20:18:25.481912133Z" level=debug msg="Assigning addresses for endpoint TestService_TestCreateServiceConfigFileMode.1.2ln943bqdzq2hz09egfan8079's interface on network bridge"
time="2021-10-25T20:18:25.481929979Z" level=debug msg="RequestAddress(LocalDefault/172.18.0.0/16, <nil>, map[])"
time="2021-10-25T20:18:25.481957090Z" level=debug msg="Request address PoolID:172.18.0.0/16 App: ipam/default/data, ID: LocalDefault/172.18.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65533, Sequence: (0xc0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:0 Serial:false PrefAddress:<nil> "
time="2021-10-25T20:18:25.507197267Z" level=debug msg="Assigning addresses for endpoint TestService_TestCreateServiceConfigFileMode.1.2ln943bqdzq2hz09egfan8079's interface on network bridge"
time="2021-10-25T20:18:25.518871377Z" level=debug msg="Programming external connectivity on endpoint TestService_TestCreateServiceConfigFileMode.1.2ln943bqdzq2hz09egfan8079 (a3c94d135ef359ff1af2abab603edb0dc57c2759708b90d8958185bbeafdf0d8)"
time="2021-10-25T20:18:25.526159864Z" level=debug msg="injecting config" name=/etc/config path=/go/src/github.com/docker/docker/bundles/test-integration/TestCreateServiceConfigFileMode/d89225fe74486/root/containers/3d5bcebd3bf5ea17f50382a74e92c3b2695ab0be261f0b126b29b92533103232/mounts/secrets/fx88vma7jp9eotidq119q6k74
time="2021-10-25T20:18:25.526354403Z" level=debug msg="bundle dir created" bundle=/tmp/dxr/d89225fe74486/containerd/3d5bcebd3bf5ea17f50382a74e92c3b2695ab0be261f0b126b29b92533103232 module=libcontainerd namespace=d89225fe74486 root=/go/src/github.com/docker/docker/bundles/test-integration/TestCreateServiceConfigFileMode/d89225fe74486/root/overlay2/556694bce86421b153d985fa25bdb784f5d66301afab434cc83c2667d11ce257/merged
time="2021-10-25T20:18:25.539960381Z" level=debug msg="state for task 2ln943bqdzq2hz09egfan8079 updated to STARTING" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="PREPARING->STARTING" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.540086841Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="PREPARING->STARTING" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:25.541714465Z" level=debug msg="Task 2ln943bqdzq2hz09egfan8079 is already in allocated state STARTING" method="(*Allocator).doTaskAlloc" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:25.568590266Z" level=debug msg="checkEncryption(ipnwxmo, <nil>, 4096, true)"
time="2021-10-25T20:18:25.574396010Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:25.676303084Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:25.733841086Z" level=debug msg="Allocating IPv4 pools for network docker_gwbridge (74e594475184aedfb41a165d241253327098fd4df3c91e4a886bed237f3ef6d4)"
time="2021-10-25T20:18:25.733870634Z" level=debug msg="RequestPool(LocalDefault, , , map[], false)"
time="2021-10-25T20:18:25.744418561Z" level=debug msg="RequestPool(LocalDefault, , , map[], false)"
time="2021-10-25T20:18:25.744549534Z" level=debug msg="RequestPool(LocalDefault, , , map[], false)"
time="2021-10-25T20:18:25.744628354Z" level=debug msg="RequestPool(LocalDefault, , , map[], false)"
time="2021-10-25T20:18:25.744700519Z" level=debug msg="RequestPool(LocalDefault, , , map[], false)"
time="2021-10-25T20:18:25.744773915Z" level=debug msg="RequestPool(LocalDefault, , , map[], false)"
time="2021-10-25T20:18:25.744843373Z" level=debug msg="RequestPool(LocalDefault, , , map[], false)"
time="2021-10-25T20:18:25.744914340Z" level=debug msg="ReleasePool(LocalDefault/172.23.0.0/16)"
time="2021-10-25T20:18:25.744926927Z" level=debug msg="ReleasePool(LocalDefault/172.22.0.0/16)"
time="2021-10-25T20:18:25.744935781Z" level=debug msg="ReleasePool(LocalDefault/172.21.0.0/16)"
time="2021-10-25T20:18:25.744945881Z" level=debug msg="ReleasePool(LocalDefault/172.20.0.0/16)"
time="2021-10-25T20:18:25.744954530Z" level=debug msg="ReleasePool(LocalDefault/172.19.0.0/16)"
time="2021-10-25T20:18:25.744962965Z" level=debug msg="ReleasePool(LocalDefault/172.17.0.0/16)"
time="2021-10-25T20:18:25.744978342Z" level=debug msg="RequestAddress(LocalDefault/172.24.0.0/16, <nil>, map[RequestAddressType:com.docker.network.gateway])"
time="2021-10-25T20:18:25.744996311Z" level=debug msg="Request address PoolID:172.24.0.0/16 App: ipam/default/data, ID: LocalDefault/172.24.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65534, Sequence: (0x80000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:0 Serial:false PrefAddress:<nil> "
time="2021-10-25T20:18:25.746431406Z" level=debug msg="Assigning address to bridge interface docker_gwbridge: 172.24.0.1/16"
time="2021-10-25T20:18:25.747780633Z" level=debug msg="sandbox set key processing took 98.310027ms for container 3d5bcebd3bf5ea17f50382a74e92c3b2695ab0be261f0b126b29b92533103232"
time="2021-10-25T20:18:25.766145123Z" level=debug msg=event module=libcontainerd namespace=d89225fe74486 topic=/tasks/create
time="2021-10-25T20:18:25.774529688Z" level=debug msg=event module=libcontainerd namespace=d89225fe74486 topic=/tasks/start
time="2021-10-25T20:18:25.776205444Z" level=debug msg=event module=libcontainerd namespace=d89225fe74486 topic=/tasks/exit
time="2021-10-25T20:18:25.777642926Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:25.781857273Z" level=debug msg="EnableService 3d5bcebd3bf5ea17f50382a74e92c3b2695ab0be261f0b126b29b92533103232 START"
time="2021-10-25T20:18:25.781878492Z" level=debug msg="EnableService 3d5bcebd3bf5ea17f50382a74e92c3b2695ab0be261f0b126b29b92533103232 DONE"
time="2021-10-25T20:18:25.790709382Z" level=debug msg=event module=libcontainerd namespace=d89225fe74486 topic=/tasks/delete
time="2021-10-25T20:18:25.790736189Z" level=info msg="ignoring event" container=3d5bcebd3bf5ea17f50382a74e92c3b2695ab0be261f0b126b29b92533103232 module=libcontainerd namespace=d89225fe74486 topic=/tasks/delete type="*events.TaskDelete"
time="2021-10-25T20:18:25.861586125Z" level=debug msg="/usr/sbin/iptables, [--wait -t filter -nL DOCKER-INGRESS]"
time="2021-10-25T20:18:25.862628868Z" level=debug msg="Revoking external connectivity on endpoint TestService_TestCreateServiceConfigFileMode.1.2ln943bqdzq2hz09egfan8079 (a3c94d135ef359ff1af2abab603edb0dc57c2759708b90d8958185bbeafdf0d8)"
time="2021-10-25T20:18:25.862779739Z" level=debug msg="Assigning addresses for endpoint gateway_ingress-sbox's interface on network docker_gwbridge"
time="2021-10-25T20:18:25.862803058Z" level=debug msg="RequestAddress(LocalDefault/172.24.0.0/16, <nil>, map[])"
time="2021-10-25T20:18:25.862826492Z" level=debug msg="Request address PoolID:172.24.0.0/16 App: ipam/default/data, ID: LocalDefault/172.24.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65533, Sequence: (0xc0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:2 Serial:false PrefAddress:<nil> "
time="2021-10-25T20:18:25.864797220Z" level=debug msg="DeleteConntrackEntries purged ipv4:0, ipv6:0"
time="2021-10-25T20:18:25.867708182Z" level=debug msg="Assigning addresses for endpoint gateway_ingress-sbox's interface on network docker_gwbridge"
time="2021-10-25T20:18:25.879803642Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:25.904667665Z" level=debug msg="Programming external connectivity on endpoint gateway_ingress-sbox (54f5bdddc5978b894672fec376c5f39cac93e8e89baaa92dffdbe48dbed3cbe3)"
time="2021-10-25T20:18:25.921321067Z" level=debug msg="EnableService ingress-sbox START"
time="2021-10-25T20:18:25.921341834Z" level=debug msg="addServiceInfoToCluster START for  3b6afbba06619c740442d6e47ee6cf4ed1a094673a67f5e1901c19c77e720f6c"
time="2021-10-25T20:18:25.921454714Z" level=debug msg="addContainerNameResolution 3b6afbba06619c740442d6e47ee6cf4ed1a094673a67f5e1901c19c77e720f6c ingress-endpoint"
time="2021-10-25T20:18:25.921497168Z" level=debug msg="addServiceInfoToCluster END for  3b6afbba06619c740442d6e47ee6cf4ed1a094673a67f5e1901c19c77e720f6c"
time="2021-10-25T20:18:25.921507179Z" level=debug msg="EnableService ingress-sbox DONE"
time="2021-10-25T20:18:25.921520143Z" level=debug msg="/usr/sbin/iptables, [--wait -t filter -nL DOCKER-INGRESS]"
time="2021-10-25T20:18:25.981195974Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:25.990687800Z" level=debug msg="Releasing addresses for endpoint TestService_TestCreateServiceConfigFileMode.1.2ln943bqdzq2hz09egfan8079's interface on network bridge"
time="2021-10-25T20:18:25.990715099Z" level=debug msg="ReleaseAddress(LocalDefault/172.18.0.0/16, 172.18.0.2)"
time="2021-10-25T20:18:25.990738558Z" level=debug msg="Released address PoolID:LocalDefault/172.18.0.0/16, Address:172.18.0.2 Sequence:App: ipam/default/data, ID: LocalDefault/172.18.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65532, Sequence: (0xe0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3"
time="2021-10-25T20:18:26.022898783Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=RUNNING state.transition="STARTING->RUNNING" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:26.023012582Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:26.023337486Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.026453138Z" level=debug msg="waiting on events" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:26.026538555Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=RUNNING state.transition="RUNNING->COMPLETE" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:26.026644740Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:26.026862056Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.028794375Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:26.029004463Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.045337139Z" level=debug msg="state for task 2ln943bqdzq2hz09egfan8079 updated to COMPLETE" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="STARTING->COMPLETE" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:26.045460785Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="STARTING->COMPLETE" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:26.050804728Z" level=debug msg="task zfwya0dmde5xw2v73qgin4p1z was marked pending allocation" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.050850776Z" level=debug msg="allocated task zfwya0dmde5xw2v73qgin4p1z, state update PENDING" method="(*Allocator).allocateTask" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.050954294Z" level=debug msg="committed allocated task zfwya0dmde5xw2v73qgin4p1z, state update {2021-10-25T20:18:26.050845656Z PENDING pending task scheduling  <nil> nil  (timestamp: nil Timestamp)}" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.052302906Z" level=debug msg="Task zfwya0dmde5xw2v73qgin4p1z is already in allocated state PENDING" method="(*Allocator).doTaskAlloc" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.082494366Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:26.102440976Z" level=debug msg="assigning to node n6wmszz1qlkitmno35aa78prk" module=node node.id=n6wmszz1qlkitmno35aa78prk task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:26.103967798Z" level=debug msg="Task zfwya0dmde5xw2v73qgin4p1z is already in allocated state ASSIGNED" method="(*Allocator).doTaskAlloc" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.183933990Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:26.205170306Z" level=debug msg="(*worker).Update" len(assignments)=3 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.205199878Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.205214098Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=1 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.205236227Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=2 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.205255124Z" level=debug msg=assigned module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.desiredstate=READY task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:26.205335249Z" level=debug msg="state changed" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=READY state.transition="ASSIGNED->ACCEPTED" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:26.205364500Z" level=debug msg=assigned module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.desiredstate=SHUTDOWN task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:26.205385334Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:26.205467091Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=READY state.transition="ASSIGNED->ACCEPTED" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:26.207848214Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.207869950Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:26.208065843Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.210030614Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=READY state.transition="ACCEPTED->PREPARING" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:26.210122587Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:26.210380602Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.211920790Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:26.212135342Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.232990046Z" level=debug msg="container mounted via layerStore: &{/go/src/github.com/docker/docker/bundles/test-integration/TestCreateServiceConfigFileMode/d89225fe74486/root/overlay2/630c6fc042113a201d58d69ee721d19450ac004f57268c54d82821cc77ccd2d8/merged 0xaaaabc801500 0xaaaabc801500}" container=bb7cc2266a02dd85ea713d7df0c891e25c188b2c68bf272b7100d3e8238a97a5
time="2021-10-25T20:18:26.247244834Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=READY state.transition="PREPARING->READY" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:26.247358707Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:26.247619405Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.249198051Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:26.249388455Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.250526125Z" level=debug msg="state for task zfwya0dmde5xw2v73qgin4p1z updated to READY" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="ASSIGNED->READY" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:26.250615875Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="ASSIGNED->READY" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:26.250643042Z" level=debug msg="state for task 2ln943bqdzq2hz09egfan8079 updated to COMPLETE" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="COMPLETE->COMPLETE" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:26.250687326Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="COMPLETE->COMPLETE" task.id=2ln943bqdzq2hz09egfan8079
time="2021-10-25T20:18:26.252331065Z" level=debug msg="Task zfwya0dmde5xw2v73qgin4p1z is already in allocated state READY" method="(*Allocator).doTaskAlloc" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:26.285396679Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:26.386634380Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:26.487974392Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:26.589423625Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:26.690887816Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:26.792429522Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:26.893892014Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:26.995243579Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:27.096655362Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:27.197966817Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:27.299256479Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:27.400773681Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:27.502268778Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:27.603748014Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:27.705166753Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:27.806495324Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:27.907925099Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:28.009270910Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:28.110631027Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:28.212063974Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:28.313393691Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:28.414759552Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:28.516055364Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:28.617385278Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:28.718580649Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:28.820008681Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:28.921391117Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:29.022686636Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:29.123951733Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:29.225239189Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:29.326682686Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:29.428160110Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:29.529546170Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:29.630911592Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:29.732319346Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:29.833711756Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:29.935021777Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:30.036316663Z" level=debug msg="sending heartbeat to manager { } with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk session.id=b5qczs8bayj4bc2b5hmtxsqqq sessionID=b5qczs8bayj4bc2b5hmtxsqqq
time="2021-10-25T20:18:30.036495284Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:30.036748392Z" level=debug msg="received heartbeat from worker {[swarm-manager] mp7csa554ry9bf12hfs4ex4os n6wmszz1qlkitmno35aa78prk <nil> 127.0.0.1:2477}, expect next heartbeat in 5.331047168s" method="(*Dispatcher).Heartbeat"
time="2021-10-25T20:18:30.036853436Z" level=debug msg="heartbeat successful to manager { }, next heartbeat period: 5.331047168s" method="(*session).heartbeat" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk session.id=b5qczs8bayj4bc2b5hmtxsqqq sessionID=b5qczs8bayj4bc2b5hmtxsqqq
time="2021-10-25T20:18:30.138100782Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:30.239408945Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:30.340772567Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:30.442183051Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:30.543465564Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:30.644894000Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:30.746377494Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:30.848060441Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:30.949465033Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:31.050879690Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:31.057034179Z" level=debug msg="Task zfwya0dmde5xw2v73qgin4p1z is already in allocated state READY" method="(*Allocator).doTaskAlloc" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.152293509Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:31.157599875Z" level=debug msg="(*worker).Update" len(assignments)=1 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.157626887Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.157638366Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.157648311Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=1 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.157664205Z" level=debug msg=assigned module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.desiredstate=RUNNING task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:31.157995698Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=RUNNING state.transition="READY->STARTING" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:31.165095445Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:31.165354765Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.173549088Z" level=debug msg="state for task zfwya0dmde5xw2v73qgin4p1z updated to STARTING" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="READY->STARTING" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:31.173647478Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="READY->STARTING" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:31.177781916Z" level=debug msg="container mounted via layerStore: &{/go/src/github.com/docker/docker/bundles/test-integration/TestCreateServiceConfigFileMode/d89225fe74486/root/overlay2/630c6fc042113a201d58d69ee721d19450ac004f57268c54d82821cc77ccd2d8/merged 0xaaaabc801500 0xaaaabc801500}" container=bb7cc2266a02dd85ea713d7df0c891e25c188b2c68bf272b7100d3e8238a97a5
time="2021-10-25T20:18:31.178039677Z" level=debug msg="Assigning addresses for endpoint TestService_TestCreateServiceConfigFileMode.1.zfwya0dmde5xw2v73qgin4p1z's interface on network bridge"
time="2021-10-25T20:18:31.178058664Z" level=debug msg="RequestAddress(LocalDefault/172.18.0.0/16, <nil>, map[])"
time="2021-10-25T20:18:31.178079095Z" level=debug msg="Request address PoolID:172.18.0.0/16 App: ipam/default/data, ID: LocalDefault/172.18.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65533, Sequence: (0xc0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3 Serial:false PrefAddress:<nil> "
time="2021-10-25T20:18:31.182484530Z" level=debug msg="Task zfwya0dmde5xw2v73qgin4p1z is already in allocated state STARTING" method="(*Allocator).doTaskAlloc" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.209998846Z" level=debug msg="Assigning addresses for endpoint TestService_TestCreateServiceConfigFileMode.1.zfwya0dmde5xw2v73qgin4p1z's interface on network bridge"
time="2021-10-25T20:18:31.250205296Z" level=debug msg="Programming external connectivity on endpoint TestService_TestCreateServiceConfigFileMode.1.zfwya0dmde5xw2v73qgin4p1z (04b78ac9774e1fab1eb52e006cc577226070faa9c43ca176cdb7cdc6b80592f5)"
time="2021-10-25T20:18:31.253775120Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:31.262619294Z" level=debug msg="injecting config" name=/etc/config path=/go/src/github.com/docker/docker/bundles/test-integration/TestCreateServiceConfigFileMode/d89225fe74486/root/containers/bb7cc2266a02dd85ea713d7df0c891e25c188b2c68bf272b7100d3e8238a97a5/mounts/secrets/fx88vma7jp9eotidq119q6k74
time="2021-10-25T20:18:31.262807885Z" level=debug msg="bundle dir created" bundle=/tmp/dxr/d89225fe74486/containerd/bb7cc2266a02dd85ea713d7df0c891e25c188b2c68bf272b7100d3e8238a97a5 module=libcontainerd namespace=d89225fe74486 root=/go/src/github.com/docker/docker/bundles/test-integration/TestCreateServiceConfigFileMode/d89225fe74486/root/overlay2/630c6fc042113a201d58d69ee721d19450ac004f57268c54d82821cc77ccd2d8/merged
time="2021-10-25T20:18:31.355219947Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:31.456616437Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:31.464401670Z" level=debug msg="sandbox set key processing took 87.975408ms for container bb7cc2266a02dd85ea713d7df0c891e25c188b2c68bf272b7100d3e8238a97a5"
time="2021-10-25T20:18:31.489231873Z" level=debug msg=event module=libcontainerd namespace=d89225fe74486 topic=/tasks/create
time="2021-10-25T20:18:31.499432726Z" level=debug msg=event module=libcontainerd namespace=d89225fe74486 topic=/tasks/start
time="2021-10-25T20:18:31.499467344Z" level=debug msg=event module=libcontainerd namespace=d89225fe74486 topic=/tasks/exit
time="2021-10-25T20:18:31.521070294Z" level=debug msg="EnableService bb7cc2266a02dd85ea713d7df0c891e25c188b2c68bf272b7100d3e8238a97a5 START"
time="2021-10-25T20:18:31.521093630Z" level=debug msg="EnableService bb7cc2266a02dd85ea713d7df0c891e25c188b2c68bf272b7100d3e8238a97a5 DONE"
time="2021-10-25T20:18:31.530300846Z" level=debug msg=event module=libcontainerd namespace=d89225fe74486 topic=/tasks/delete
time="2021-10-25T20:18:31.530333257Z" level=info msg="ignoring event" container=bb7cc2266a02dd85ea713d7df0c891e25c188b2c68bf272b7100d3e8238a97a5 module=libcontainerd namespace=d89225fe74486 topic=/tasks/delete type="*events.TaskDelete"
time="2021-10-25T20:18:31.538615246Z" level=debug msg="Revoking external connectivity on endpoint TestService_TestCreateServiceConfigFileMode.1.zfwya0dmde5xw2v73qgin4p1z (04b78ac9774e1fab1eb52e006cc577226070faa9c43ca176cdb7cdc6b80592f5)"
time="2021-10-25T20:18:31.540469739Z" level=debug msg="DeleteConntrackEntries purged ipv4:0, ipv6:0"
time="2021-10-25T20:18:31.558046503Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:31.659316246Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:31.671633110Z" level=debug msg="Releasing addresses for endpoint TestService_TestCreateServiceConfigFileMode.1.zfwya0dmde5xw2v73qgin4p1z's interface on network bridge"
time="2021-10-25T20:18:31.671657701Z" level=debug msg="ReleaseAddress(LocalDefault/172.18.0.0/16, 172.18.0.2)"
time="2021-10-25T20:18:31.671679921Z" level=debug msg="Released address PoolID:LocalDefault/172.18.0.0/16, Address:172.18.0.2 Sequence:App: ipam/default/data, ID: LocalDefault/172.18.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65532, Sequence: (0xe0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3"
time="2021-10-25T20:18:31.753978559Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=RUNNING state.transition="STARTING->RUNNING" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:31.754123210Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:31.754464402Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.760598149Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:31.760970414Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=RUNNING state.transition="RUNNING->COMPLETE" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:31.761194492Z" level=debug msg="waiting on events" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:31.761247654Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:31.761418218Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.767576990Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:31.767800084Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.786020790Z" level=debug msg="state for task zfwya0dmde5xw2v73qgin4p1z updated to COMPLETE" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="STARTING->COMPLETE" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:31.786122618Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="STARTING->COMPLETE" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:31.791660004Z" level=debug msg="task s90icgrhbdobhiwdlp7myfopy was marked pending allocation" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.791695451Z" level=debug msg="allocated task s90icgrhbdobhiwdlp7myfopy, state update PENDING" method="(*Allocator).allocateTask" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.791798567Z" level=debug msg="committed allocated task s90icgrhbdobhiwdlp7myfopy, state update {2021-10-25T20:18:31.791692202Z PENDING pending task scheduling  <nil> nil  (timestamp: nil Timestamp)}" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.794638605Z" level=debug msg="Task s90icgrhbdobhiwdlp7myfopy is already in allocated state PENDING" method="(*Allocator).doTaskAlloc" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.844816282Z" level=debug msg="assigning to node n6wmszz1qlkitmno35aa78prk" module=node node.id=n6wmszz1qlkitmno35aa78prk task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:31.851860536Z" level=debug msg="Task s90icgrhbdobhiwdlp7myfopy is already in allocated state ASSIGNED" method="(*Allocator).doTaskAlloc" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.861762740Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:31.953041022Z" level=debug msg="(*worker).Update" len(assignments)=3 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.953079759Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.953092059Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=1 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.953106262Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=2 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.953121885Z" level=debug msg=assigned module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.desiredstate=READY task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:31.953247975Z" level=debug msg="state changed" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=READY state.transition="ASSIGNED->ACCEPTED" task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:31.953294532Z" level=debug msg=assigned module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.desiredstate=SHUTDOWN task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:31.953377914Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=READY state.transition="ASSIGNED->ACCEPTED" task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:31.953423782Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:31.963123283Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:31.982374524Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.982407624Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:31.982673640Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:31.988835399Z" level=debug msg="state for task s90icgrhbdobhiwdlp7myfopy updated to ACCEPTED" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="ASSIGNED->ACCEPTED" task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:31.988933780Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="ASSIGNED->ACCEPTED" task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:31.997817832Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=READY state.transition="ACCEPTED->PREPARING" task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:31.998072475Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:31.998333460Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:32.003132321Z" level=debug msg="Task s90icgrhbdobhiwdlp7myfopy is already in allocated state ACCEPTED" method="(*Allocator).doTaskAlloc" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:32.024925497Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:32.025191020Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:32.064432681Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:32.069951656Z" level=debug msg="container mounted via layerStore: &{/go/src/github.com/docker/docker/bundles/test-integration/TestCreateServiceConfigFileMode/d89225fe74486/root/overlay2/cdc1b93617abb8ab9d77bcbd0ddb5f3787320bbff103a53f77a668dd9f861eaf/merged 0xaaaabc801500 0xaaaabc801500}" container=bf3a4865a81627529667b49ec22f75fdda57d509d5106a8d9d5f47daff0bb4fd
time="2021-10-25T20:18:32.103274195Z" level=debug msg="state for task s90icgrhbdobhiwdlp7myfopy updated to PREPARING" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="ACCEPTED->PREPARING" task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:32.103416663Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="ACCEPTED->PREPARING" task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:32.103457443Z" level=debug msg="state for task zfwya0dmde5xw2v73qgin4p1z updated to COMPLETE" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="COMPLETE->COMPLETE" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:32.103499282Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="COMPLETE->COMPLETE" task.id=zfwya0dmde5xw2v73qgin4p1z
time="2021-10-25T20:18:32.111266497Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=n6wmszz1qlkitmno35aa78prk service.id=1brvqsvnaaaj0mybfxc4zvkjt state.desired=READY state.transition="PREPARING->READY" task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:32.111384875Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:32.111721513Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:32.120007605Z" level=debug msg="Task s90icgrhbdobhiwdlp7myfopy is already in allocated state PREPARING" method="(*Allocator).doTaskAlloc" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:32.145929731Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:32.146237134Z" level=debug msg="task status reported" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:32.165769868Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:32.220012705Z" level=debug msg="state for task s90icgrhbdobhiwdlp7myfopy updated to READY" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="PREPARING->READY" task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:32.220121400Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk state.transition="PREPARING->READY" task.id=s90icgrhbdobhiwdlp7myfopy
time="2021-10-25T20:18:32.267259919Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:32.286013685Z" level=debug msg="Task s90icgrhbdobhiwdlp7myfopy is already in allocated state READY" method="(*Allocator).doTaskAlloc" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:32.368748551Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:32.470050349Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:32.571638182Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:32.673054690Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:32.774551986Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:32.876030706Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:32.977570744Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:33.079018456Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:33.180570315Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:33.282001515Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:33.383495296Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:33.484922360Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:33.586244601Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:33.687711486Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:33.789259808Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:33.890731665Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:33.992125842Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:34.093525380Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:34.194986148Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:34.296430391Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:34.397981335Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:34.499530933Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:34.601082977Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:34.702514978Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:34.804063337Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:34.905453786Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:35.006850438Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:35.108350892Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:35.209884084Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:35.311149366Z" level=debug msg="Calling GET /v1.42/tasks?filters=%7B%22service%22%3A%7B%221brvqsvnaaaj0mybfxc4zvkjt%22%3Atrue%7D%7D"
time="2021-10-25T20:18:35.311826262Z" level=info msg="Processing signal 'interrupt'"
time="2021-10-25T20:18:35.312427381Z" level=debug msg="(*worker).Assign" len(assignments)=0 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:35.312451898Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:35.312463427Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:35.312484646Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=0 module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:35.326837060Z" level=info msg="Stopping manager" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:35.326913180Z" level=info msg="dispatcher stopping" method="(*Dispatcher).Stop" module=dispatcher node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:35.326960041Z" level=info msg="dispatcher session dropped, marking node n6wmszz1qlkitmno35aa78prk down" method="(*Dispatcher).Session" node.id=n6wmszz1qlkitmno35aa78prk node.session=b5qczs8bayj4bc2b5hmtxsqqq
time="2021-10-25T20:18:35.326975664Z" level=error msg="failed to remove node" error="rpc error: code = Aborted desc = dispatcher is stopped" method="(*Dispatcher).Session" node.id=n6wmszz1qlkitmno35aa78prk node.session=b5qczs8bayj4bc2b5hmtxsqqq
time="2021-10-25T20:18:35.327010561Z" level=debug msg="error handling streaming rpc" error="rpc error: code = Aborted desc = node must disconnect" rpc=/docker.swarmkit.v1.Dispatcher/Session
time="2021-10-25T20:18:35.327028415Z" level=info msg="shutting down certificate renewal routine" module=node/tls node.id=n6wmszz1qlkitmno35aa78prk node.role=swarm-manager
time="2021-10-25T20:18:35.327047624Z" level=debug msg="(*Agent).run exited" module=node/agent node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:35.327206823Z" level=debug msg="error handling streaming rpc" error="context canceled" rpc=/docker.swarmkit.v1.Dispatcher/Assignments
time="2021-10-25T20:18:35.327336877Z" level=debug msg="error handling streaming rpc" error="context canceled" rpc=/docker.swarmkit.v1.Watch/Watch
time="2021-10-25T20:18:35.327504158Z" level=debug msg="stop transport"
time="2021-10-25T20:18:35.338102439Z" level=error msg="failed to receive changes from store watch API" error="rpc error: code = Unknown desc = context canceled"
time="2021-10-25T20:18:35.338178871Z" level=info msg="Manager shut down" module=node node.id=n6wmszz1qlkitmno35aa78prk
time="2021-10-25T20:18:35.338294016Z" level=warning msg="grpc: addrConn.createTransport failed to connect to {/tmp/dxr/d89225fe74486/swarm/control.sock  <nil> 0 <nil>}. Err :connection error: desc = \"transport: Error while dialing dial unix /tmp/dxr/d89225fe74486/swarm/control.sock: connect: no such file or directory\". Reconnecting..." module=grpc
time="2021-10-25T20:18:35.344622370Z" level=debug msg="daemon configured with a 15 seconds minimum shutdown timeout"
time="2021-10-25T20:18:35.344642211Z" level=debug msg="start clean shutdown of all containers with a 15 seconds timeout..."
time="2021-10-25T20:18:35.344713909Z" level=info msg="Node 9b2bebf66441/127.0.0.1, left gossip cluster"
time="2021-10-25T20:18:35.344733404Z" level=info msg="Node 9b2bebf66441 change state NodeActive --> NodeFailed"
time="2021-10-25T20:18:35.344751850Z" level=info msg="Node 9b2bebf66441/127.0.0.1, added to failed nodes list"
time="2021-10-25T20:18:35.344804913Z" level=debug msg="cleanupServiceDiscovery for all networks"
time="2021-10-25T20:18:35.344813250Z" level=debug msg="cleanupServiceBindings for "
time="2021-10-25T20:18:35.360617664Z" level=debug msg="found 0 orphan layers"
time="2021-10-25T20:18:35.361305702Z" level=debug msg="start clean shutdown of cluster resources..."
time="2021-10-25T20:18:35.361700844Z" level=debug msg="DisableService ingress-sbox START"
time="2021-10-25T20:18:35.361728012Z" level=debug msg="DisableService ingress-sbox DONE"
time="2021-10-25T20:18:35.590248733Z" level=debug msg="Revoking external connectivity on endpoint gateway_ingress-sbox (54f5bdddc5978b894672fec376c5f39cac93e8e89baaa92dffdbe48dbed3cbe3)"
time="2021-10-25T20:18:35.592009703Z" level=debug msg="DeleteConntrackEntries purged ipv4:0, ipv6:0"
time="2021-10-25T20:18:35.698432485Z" level=debug msg="Releasing addresses for endpoint gateway_ingress-sbox's interface on network docker_gwbridge"
time="2021-10-25T20:18:35.698462665Z" level=debug msg="ReleaseAddress(LocalDefault/172.24.0.0/16, 172.24.0.2)"
time="2021-10-25T20:18:35.698486394Z" level=debug msg="Released address PoolID:LocalDefault/172.24.0.0/16, Address:172.24.0.2 Sequence:App: ipam/default/data, ID: LocalDefault/172.24.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65532, Sequence: (0xe0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3"
time="2021-10-25T20:18:35.704210642Z" level=warning msg="Error (Unable to complete atomic operation, key modified) deleting object [endpoint ipnwxmo3pb9g4td9cfx1lziu2 3b6afbba06619c740442d6e47ee6cf4ed1a094673a67f5e1901c19c77e720f6c], retrying...."
time="2021-10-25T20:18:35.728207825Z" level=debug msg="Releasing addresses for endpoint ingress-endpoint's interface on network ingress"
time="2021-10-25T20:18:35.728244396Z" level=debug msg="ReleaseAddress(LocalDefault/10.0.0.0/24, 10.0.0.2)"
time="2021-10-25T20:18:35.728267510Z" level=debug msg="Released address PoolID:LocalDefault/10.0.0.0/24, Address:10.0.0.2 Sequence:App: ipam/default/data, ID: LocalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 252, Sequence: (0xe0000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:0"
time="2021-10-25T20:18:35.732106889Z" level=debug msg="releasing IPv4 pools from network ingress (ipnwxmo3pb9g4td9cfx1lziu2)"
time="2021-10-25T20:18:35.732126327Z" level=debug msg="ReleaseAddress(LocalDefault/10.0.0.0/24, 10.0.0.1)"
time="2021-10-25T20:18:35.732162635Z" level=debug msg="Released address PoolID:LocalDefault/10.0.0.0/24, Address:10.0.0.1 Sequence:App: ipam/default/data, ID: LocalDefault/10.0.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 253, Sequence: (0xc0000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:0"
time="2021-10-25T20:18:35.732176256Z" level=debug msg="ReleasePool(LocalDefault/10.0.0.0/24)"
time="2021-10-25T20:18:35.732234711Z" level=debug msg="cleanupServiceDiscovery for network:ipnwxmo3pb9g4td9cfx1lziu2"
time="2021-10-25T20:18:35.732243581Z" level=debug msg="cleanupServiceBindings for ipnwxmo3pb9g4td9cfx1lziu2"
time="2021-10-25T20:18:35.733084894Z" level=debug msg="Unix socket /tmp/dxr/d89225fe74486/libnetwork/9505799efa95.sock doesn't exist. cannot accept client connections"
time="2021-10-25T20:18:35.733120209Z" level=debug msg="Cleaning up old mountid : start."
time="2021-10-25T20:18:35.733151061Z" level=info msg="stopping event stream following graceful shutdown" error="<nil>" module=libcontainerd namespace=d89225fe74486
time="2021-10-25T20:18:35.733837237Z" level=debug msg="Cleaning up old mountid : done."
time="2021-10-25T20:18:35.734379541Z" level=debug msg="Clean shutdown succeeded"
time="2021-10-25T20:18:35.734399955Z" level=info msg="Daemon shutdown complete"

Errors from that log:

time="2021-10-25T20:18:25.240018893Z" level=error msg="error reading the kernel parameter net.ipv4.neigh.default.gc_thresh1" error="open /proc/sys/net/ipv4/neigh/default/gc_thresh1: no such file or directory"
time="2021-10-25T20:18:25.240039595Z" level=error msg="error reading the kernel parameter net.ipv4.neigh.default.gc_thresh2" error="open /proc/sys/net/ipv4/neigh/default/gc_thresh2: no such file or directory"
time="2021-10-25T20:18:25.240056268Z" level=error msg="error reading the kernel parameter net.ipv4.neigh.default.gc_thresh3" error="open /proc/sys/net/ipv4/neigh/default/gc_thresh3: no such file or directory"
time="2021-10-25T20:18:25.335793111Z" level=error msg="error reading the kernel parameter net.ipv4.vs.conn_reuse_mode" error="open /proc/sys/net/ipv4/vs/conn_reuse_mode: no such file or directory"
time="2021-10-25T20:18:25.335828197Z" level=error msg="error reading the kernel parameter net.ipv4.vs.expire_nodest_conn" error="open /proc/sys/net/ipv4/vs/expire_nodest_conn: no such file or directory"
time="2021-10-25T20:18:25.335844624Z" level=error msg="error reading the kernel parameter net.ipv4.vs.expire_quiescent_template" error="open /proc/sys/net/ipv4/vs/expire_quiescent_template: no such file or directory"
time="2021-10-25T20:18:35.326975664Z" level=error msg="failed to remove node" error="rpc error: code = Aborted desc = dispatcher is stopped" method="(*Dispatcher).Session" node.id=n6wmszz1qlkitmno35aa78prk node.session=b5qczs8bayj4bc2b5hmtxsqqq
time="2021-10-25T20:18:35.338102439Z" level=error msg="failed to receive changes from store watch API" error="rpc error: code = Unknown desc = context canceled"

The error reading the kernel parameter errors come from kernel.ApplyOSTweaks

func ApplyOSTweaks(osConfig map[string]*OSValue) {
for k, v := range osConfig {
// read the existing property from disk
oldv, err := readSystemProperty(k)
if err != nil {
logrus.WithError(err).Errorf("error reading the kernel parameter %s", k)
continue
}
if propertyIsValid(oldv, v.Value, v.CheckFn) {
// write new prop value to disk
if err := writeSystemProperty(k, v.Value); err != nil {
logrus.WithError(err).Errorf("error setting the kernel parameter %s = %s, (leaving as %s)", k, v.Value, oldv)
continue
}
logrus.Debugf("updated kernel parameter %s = %s (was %s)", k, v.Value, oldv)
}
}
}
And those errors only happen when reading the options, but no errors are logged for writing the options, because that part is skipped. (Note that there's a PR pending related to these tweaks; #42897)

Looking at those, they don't seem to be related, and just "warnings". Perhaps need to be looked into why they fail in our CI, but doesn't look related.

@thaJeztah
Copy link
Member Author

Hm... ok so perhaps I'm silly, but I think I see what's happening. If I'm right, that test was broken from the start (added in 65ee7ff / #36130), but may have worked in case we managed to get the logs.

I think what's wrong here is that the command that's used for the service will either exit immediately (if the secret is mounted correctly at /etc/config), or if that fails, will only contain output of /bin/top and keep running);

swarm.ServiceWithCommand([]string{"/bin/sh", "-c", "ls -l /etc/config || /bin/top"}),

Trying to run the test steps locally shows that this is the case;

echo 'CONFIG' | docker config create myconfig -

docker service create --config source=myconfig,target=/etc/config,mode=0777 --name myservice busybox sh -c 'ls -l /etc/config || /bin/top'

The above creates the service, but it keeps retrying, because each task exits immediately (followed by SwarmKit reconciling and starting a new task);

mjntpfkkyuuc1dpay4h00c4oo
overall progress: 0 out of 1 tasks
1/1: ready     [======================================>            ]
verify: Detected task failure
^COperation continuing in background.
Use `docker service ps mjntpfkkyuuc1dpay4h00c4oo` to check progress.

And, for sure; the tasks exit cleanly (no error), but do exit, so swarm just keeps up spinning new tasks;

docker service ps myservice --no-trunc
ID                          NAME              IMAGE                                                                                    NODE             DESIRED STATE   CURRENT STATE                     ERROR     PORTS
2wmcuv4vffnet8nybg3he4v9n   myservice.1       busybox:latest@sha256:f7ca5a32c10d51aeda3b4d01c61c6061f497893d7f6628b92f822f7117182a57   docker-desktop   Ready           Ready less than a second ago
5p8b006uec125iq2892lxay64    \_ myservice.1   busybox:latest@sha256:f7ca5a32c10d51aeda3b4d01c61c6061f497893d7f6628b92f822f7117182a57   docker-desktop   Shutdown        Complete less than a second ago
k8lpsvlak4b3nil0zfkexw61p    \_ myservice.1   busybox:latest@sha256:f7ca5a32c10d51aeda3b4d01c61c6061f497893d7f6628b92f822f7117182a57   docker-desktop   Shutdown        Complete 6 seconds ago
vsunl5pi7e2n9ol3p89kvj6pn    \_ myservice.1   busybox:latest@sha256:f7ca5a32c10d51aeda3b4d01c61c6061f497893d7f6628b92f822f7117182a57   docker-desktop   Shutdown        Complete 11 seconds ago
orxl8b6kt2l6dfznzzd4lij4s    \_ myservice.1   busybox:latest@sha256:f7ca5a32c10d51aeda3b4d01c61c6061f497893d7f6628b92f822f7117182a57   docker-desktop   Shutdown        Complete 17 seconds ago

So the test is now in a race-condition, and proceeds if it happens to find 1 healthy task, after which it continues, and picks the first task from the list of tasks (before #42960, that means "any task"; either running or exited)

And if we're able to get logs of that task, and it includes the -rwxrwxrwx, the test "passes".

Improving CI automation moved this from To do to Done Oct 27, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/swarm area/testing kind/bug Bugs are bugs. The cause may or may not be known at triage time so debugging may be needed.
Projects
Improving CI
  
Done
Development

Successfully merging a pull request may close this issue.

4 participants