nestybox / sysbox

An open-source, next-generation "runc" that empowers rootless containers to run workloads such as Systemd, Docker, Kubernetes, just like VMs.
Apache License 2.0
2.8k stars 155 forks source link

Mounting docker secrets failed when using sysbox-runc #308

Closed d-mankowski-samsung closed 3 years ago

d-mankowski-samsung commented 3 years ago

Hi, while trying to adjust Jenkins and its agents (running in containers in Swarm mode) to sysbox, I've encountered the following issue:

l4tc43p5sb8ixi9mt4ccvc7dk    \_ jenkins_jenkins.1   my_jenkins   test      Shutdown        Failed 7 seconds ago    "starting container failed: OCI runtime create failed: container_linux.go:392: starting container process caused: process_linux.go:592: container init caused: process_linux.go:563: handleReqOp caused: rootfs_init_linux.go:260: bind mounting /var/lib/docker/containers/3d02bd4c4f1470e105b7044bc2679be8c498055083e02c44587ff725066dcb29/mounts/secrets/h2ludz4aecvy42jrftlvvy84d to run/secrets/GITHUB_APP_KEY caused: bind-mount of /var/lib/docker/containers/3d02bd4c4f1470e105b7044bc2679be8c498055083e02c44587ff725066dcb29/mounts/secrets/h2ludz4aecvy42jrftlvvy84d to run/secrets/GITHUB_APP_KEY failed: exit status 32: unknown"

Container with Jenkins wasn't able to start after the deployment of docker service.

root@test:~# uname -a
Linux test 5.4.0-74-generic #83-Ubuntu SMP Sat May 8 02:35:39 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
root@test:~# lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 20.04.2 LTS
Release:        20.04
Codename:       focal

/etc/docker/daemon.json looks like this:

{
  "runtimes": {
    "sysbox-runc": {
      "path": "/usr/local/sbin/sysbox-runc"
    }
  },
  "bip": "172.20.0.1/16",
  "default-address-pools": [
    {
      "base": "172.25.0.0/16",
      "size": 24
    }
  ],
  "default-runtime": "sysbox-runc"
}

Related part of docker-compose looks like this (removed unnecessary bits):

version: "3.8"

services:
  jenkins:
    image: my_jenkins
      mode: replicated
      replicas: 1
    ports:
      - 8080:8080
    secrets:
      - GITHUB_APP_KEY

secrets:
  GITHUB_APP_KEY:
    external: true

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.5.1-docker)
  scan: Docker Scan (Docker Inc., v0.8.0)

Server:
 Containers: 7
  Running: 1
  Paused: 0
  Stopped: 6
 Images: 69
 Server Version: 20.10.7
 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: active
  NodeID: 5mlvwfqt0ekxik1dvzbpjsic0
  Is Manager: true
  ClusterID: c4aae50ann4iaohap5v5rp2pw
  Managers: 1
  Nodes: 1
  Default Address Pool: 10.0.0.0/8
  SubnetSize: 24
  Data Path Port: 4789
  Orchestration:
   Task History Retention Limit: 5
  Raft:
   Snapshot Interval: 10000
   Number of Old Snapshots to Retain: 0
   Heartbeat Tick: 1
   Election Tick: 10
  Dispatcher:
   Heartbeat Period: 5 seconds
  CA Configuration:
   Expiry Duration: 3 months
   Force Rotate: 0
  Autolock Managers: false
  Root Rotation In Progress: false
  Node Address: 10.0.0.102
  Manager Addresses:
   10.0.0.102:2377
 Runtimes: io.containerd.runtime.v1.linux runc sysbox-runc io.containerd.runc.v2
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: d71fcd7d8303cbf684402823e425e9dd2e99285d
 runc version: b9ee9c6314599f1b4a7f497e1f1f856fe433d3b7
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: default
 Kernel Version: 5.4.0-74-generic
 Operating System: Ubuntu 20.04.2 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 4
 Total Memory: 7.775GiB
 Name: test
 ID: MJOD:OIBM:DTA3:HIF2:RUM2:UNCS:S4YK:EIST:Z2YG:ZCSY:MNSK:O2ET
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false
 Default Address Pools:
   Base: 172.25.0.0/16, Size: 24

After removing "default-runtime": "sysbox-runc" from daemon.json and restarting docker.service, everything works fine, so it seems that this issue is sysbox-related.

Sysbox version:

root@test:~# /usr/local/sbin/sysbox-runc --version
sysbox-runc
        edition:        Community Edition (CE)
        version:        0.3.0
        commit:         df952e5276cb6e705e0be331e9a9fe88f372eab8
        built at:       Sat Mar 27 01:34:12 UTC 2021
        built by:       Rodny Molina
        oci-specs:      1.0.2-dev

A minimal (not) working example:

cat << EOF > docker-compose.yaml
version: "3.8"

services:
  test:
    image: alpine:latest
    deploy:
      mode: replicated
      replicas: 1
    secrets:
      - TEST_SECRET

secrets:
  TEST_SECRET:
    external: true
EOF

docker swarm init && printf test | docker secret create TEST_SECRET - &&  docker stack deploy -c docker-compose.yaml test && docker node ps --no-trunc

And logs from this example:

Logs from sysbox-fs.log:

root@test:/var/log# cat sysbox-fs.log
time="2021-06-06 12:34:39" level=info msg="Initiating sysbox-fs ..."
time="2021-06-06 12:34:39" level=info msg="Initializing with 'allow-immutable-remounts' knob disabled (default)"
time="2021-06-06 12:34:39" level=info msg="Initializing with 'allow-immutable-unmounts' knob enabled (default)"
time="2021-06-06 12:34:39" level=info msg="Listening on /run/sysbox/sysfs.sock"
time="2021-06-06 12:34:39" level=info msg="Ready ..."
time="2021-06-06 12:34:45" level=warning msg="sysbox-fs caught signal: terminated"
time="2021-06-06 12:34:45" level=info msg="Stopping (gracefully) ..."
time="2021-06-06 12:34:45" level=info msg="Exiting ..."
time="2021-06-06 12:34:45" level=info msg="Initiating sysbox-fs ..."
time="2021-06-06 12:34:45" level=info msg="Initializing with 'allow-immutable-remounts' knob disabled (default)"
time="2021-06-06 12:34:45" level=info msg="Initializing with 'allow-immutable-unmounts' knob enabled (default)"
time="2021-06-06 12:34:45" level=info msg="Listening on /run/sysbox/sysfs.sock"
time="2021-06-06 12:34:45" level=info msg="Ready ..."
time="2021-06-06 12:34:48" level=warning msg="sysbox-fs caught signal: terminated"
time="2021-06-06 12:34:48" level=info msg="Stopping (gracefully) ..."
time="2021-06-06 12:34:48" level=info msg="Exiting ..."
time="2021-06-06 12:34:49" level=info msg="Initiating sysbox-fs ..."
time="2021-06-06 12:34:49" level=info msg="Initializing with 'allow-immutable-remounts' knob disabled (default)"
time="2021-06-06 12:34:49" level=info msg="Initializing with 'allow-immutable-unmounts' knob enabled (default)"
time="2021-06-06 12:34:49" level=info msg="Listening on /run/sysbox/sysfs.sock"
time="2021-06-06 12:34:49" level=info msg="Ready ..."
time="2021-06-06 12:37:24" level=debug msg="Container pre-registration started: id = cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917"
time="2021-06-06 12:37:24" level=debug msg="Container pre-registration completed: id = cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917"
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x4 Node=0x1 Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x4)"
2021/06/06 12:37:24 FUSE: -> [ID=0x4] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Lookup [ID=0x6 Node=0x1 Uid=0 Gid=0 Pid=7147] "sys"
time="2021-06-06 12:37:24" level=debug msg="Requested Lookup() operation for entry sys (req ID=0x6)"
time="2021-06-06 12:37:24" level=debug msg="Executing Lookup() method on sys handler: /sys"
time="2021-06-06 12:37:24" level=debug msg="Requested Attr() operation for entry /sys"
2021/06/06 12:37:24 FUSE: -> [ID=0x6] Lookup 0x2 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0}
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x8 Node=0x2 Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /sys (Req ID=0x8)"
2021/06/06 12:37:24 FUSE: -> [ID=0x8] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Lookup [ID=0xa Node=0x2 Uid=0 Gid=0 Pid=7147] "module"
time="2021-06-06 12:37:24" level=debug msg="Requested Lookup() operation for entry module (req ID=0xa)"
time="2021-06-06 12:37:24" level=debug msg="Executing Lookup() method on sys handler: /sys/module"
time="2021-06-06 12:37:24" level=debug msg="Requested Attr() operation for entry /sys/module"
2021/06/06 12:37:24 FUSE: -> [ID=0xa] Lookup 0x3 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=2048 size=0 mode=drwxr-xr-x uid=0 gid=0}
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0xc Node=0x3 Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /sys/module (Req ID=0xc)"
2021/06/06 12:37:24 FUSE: -> [ID=0xc] Getattr valid=0s ino=2048 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Lookup [ID=0xe Node=0x3 Uid=0 Gid=0 Pid=7147] "nf_conntrack"
time="2021-06-06 12:37:24" level=debug msg="Requested Lookup() operation for entry nf_conntrack (req ID=0xe)"
time="2021-06-06 12:37:24" level=debug msg="Executing Lookup() method on sys handler: /sys/module/nf_conntrack"
time="2021-06-06 12:37:24" level=debug msg="Requested Attr() operation for entry /sys/module/nf_conntrack"
2021/06/06 12:37:24 FUSE: -> [ID=0xe] Lookup 0x4 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=81673 size=0 mode=drwxr-xr-x uid=0 gid=0}
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x10 Node=0x4 Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /sys/module/nf_conntrack (Req ID=0x10)"
2021/06/06 12:37:24 FUSE: -> [ID=0x10] Getattr valid=0s ino=81673 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Lookup [ID=0x12 Node=0x4 Uid=0 Gid=0 Pid=7147] "parameters"
time="2021-06-06 12:37:24" level=debug msg="Requested Lookup() operation for entry parameters (req ID=0x12)"
time="2021-06-06 12:37:24" level=debug msg="Executing Lookup() method on sys handler: /sys/module/nf_conntrack/parameters"
time="2021-06-06 12:37:24" level=debug msg="Requested Attr() operation for entry /sys/module/nf_conntrack/parameters"
2021/06/06 12:37:24 FUSE: -> [ID=0x12] Lookup 0x5 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=81675 size=0 mode=drwxr-xr-x uid=0 gid=0}
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x14 Node=0x5 Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /sys/module/nf_conntrack/parameters (Req ID=0x14)"
2021/06/06 12:37:24 FUSE: -> [ID=0x14] Getattr valid=0s ino=81675 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Lookup [ID=0x16 Node=0x5 Uid=0 Gid=0 Pid=7147] "hashsize"
time="2021-06-06 12:37:24" level=debug msg="Requested Lookup() operation for entry hashsize (req ID=0x16)"
time="2021-06-06 12:37:24" level=debug msg="Executing Lookup() method on nfConntrackHashSize handler"
time="2021-06-06 12:37:24" level=debug msg="Requested Attr() operation for entry /sys/module/nf_conntrack/parameters/hashsize"
2021/06/06 12:37:24 FUSE: -> [ID=0x16] Lookup 0x6 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=81678 size=4096 mode=-rw------- uid=0 gid=0}
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x18 Node=0x6 Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /sys/module/nf_conntrack/parameters/hashsize (Req ID=0x18)"
2021/06/06 12:37:24 FUSE: -> [ID=0x18] Getattr valid=0s ino=81678 size=4096 mode=-rw------- uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x1a Node=0x1 Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x1a)"
2021/06/06 12:37:24 FUSE: -> [ID=0x1a] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Lookup [ID=0x1c Node=0x1 Uid=0 Gid=0 Pid=7147] "proc"
time="2021-06-06 12:37:24" level=debug msg="Requested Lookup() operation for entry proc (req ID=0x1c)"
time="2021-06-06 12:37:24" level=debug msg="Executing Lookup() method on proc handler"
time="2021-06-06 12:37:24" level=debug msg="Requested Attr() operation for entry /proc"
2021/06/06 12:37:24 FUSE: -> [ID=0x1c] Lookup 0x7 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0}
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x1e Node=0x7 Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x1e)"
2021/06/06 12:37:24 FUSE: -> [ID=0x1e] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Lookup [ID=0x20 Node=0x7 Uid=0 Gid=0 Pid=7147] "swaps"
time="2021-06-06 12:37:24" level=debug msg="Requested Lookup() operation for entry swaps (req ID=0x20)"
time="2021-06-06 12:37:24" level=debug msg="Executing Lookup() method on procSwaps handler"
time="2021-06-06 12:37:24" level=debug msg="Requested Attr() operation for entry /proc/swaps"
2021/06/06 12:37:24 FUSE: -> [ID=0x20] Lookup 0x8 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=4026532071 size=0 mode=-r--r--r-- uid=0 gid=0}
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x22 Node=0x8 Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /proc/swaps (Req ID=0x22)"
2021/06/06 12:37:24 FUSE: -> [ID=0x22] Getattr valid=0s ino=4026532071 size=0 mode=-r--r--r-- uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x24 Node=0x1 Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x24)"
2021/06/06 12:37:24 FUSE: -> [ID=0x24] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x26 Node=0x7 Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x26)"
2021/06/06 12:37:24 FUSE: -> [ID=0x26] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Lookup [ID=0x28 Node=0x7 Uid=0 Gid=0 Pid=7147] "sys"
time="2021-06-06 12:37:24" level=debug msg="Requested Lookup() operation for entry sys (req ID=0x28)"
time="2021-06-06 12:37:24" level=debug msg="Executing Lookup() method for Req ID=0x28 on procSys handler"
time="2021-06-06 12:37:24" level=debug msg="Requested Attr() operation for entry /proc/sys"
2021/06/06 12:37:24 FUSE: -> [ID=0x28] Lookup 0x9 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=4026531854 size=0 mode=dr-xr-xr-x uid=0 gid=0}
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x2a Node=0x9 Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /proc/sys (Req ID=0x2a)"
2021/06/06 12:37:24 FUSE: -> [ID=0x2a] Getattr valid=0s ino=4026531854 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x2c Node=0x1 Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x2c)"
2021/06/06 12:37:24 FUSE: -> [ID=0x2c] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x2e Node=0x7 Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x2e)"
2021/06/06 12:37:24 FUSE: -> [ID=0x2e] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Lookup [ID=0x30 Node=0x7 Uid=0 Gid=0 Pid=7147] "uptime"
time="2021-06-06 12:37:24" level=debug msg="Requested Lookup() operation for entry uptime (req ID=0x30)"
time="2021-06-06 12:37:24" level=debug msg="Executing Lookup() method on procUptime handler"
time="2021-06-06 12:37:24" level=debug msg="Requested Attr() operation for entry /proc/uptime"
2021/06/06 12:37:24 FUSE: -> [ID=0x30] Lookup 0xa gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=4026532027 size=0 mode=-r--r--r-- uid=0 gid=0}
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x32 Node=0xa Uid=0 Gid=0 Pid=7147] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /proc/uptime (Req ID=0x32)"
2021/06/06 12:37:24 FUSE: -> [ID=0x32] Getattr valid=0s ino=4026532027 size=0 mode=-r--r--r-- uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x34 Node=0x1 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x34)"
2021/06/06 12:37:24 FUSE: -> [ID=0x34] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x36 Node=0x2 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /sys (Req ID=0x36)"
2021/06/06 12:37:24 FUSE: -> [ID=0x36] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x38 Node=0x3 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /sys/module (Req ID=0x38)"
2021/06/06 12:37:24 FUSE: -> [ID=0x38] Getattr valid=0s ino=2048 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x3a Node=0x4 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /sys/module/nf_conntrack (Req ID=0x3a)"
2021/06/06 12:37:24 FUSE: -> [ID=0x3a] Getattr valid=0s ino=81673 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x3c Node=0x5 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry /sys/module/nf_conntrack/parameters (Req ID=0x3c)"
2021/06/06 12:37:24 FUSE: -> [ID=0x3c] Getattr valid=0s ino=81675 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:24 FUSE: <- Getattr [ID=0x3e Node=0x1 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:24" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x3e)"
2021/06/06 12:37:25 FUSE: -> [ID=0x3e] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x40 Node=0x2 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry /sys (Req ID=0x40)"
2021/06/06 12:37:25 FUSE: -> [ID=0x40] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x42 Node=0x3 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry /sys/module (Req ID=0x42)"
2021/06/06 12:37:25 FUSE: -> [ID=0x42] Getattr valid=0s ino=2048 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x44 Node=0x4 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry /sys/module/nf_conntrack (Req ID=0x44)"
2021/06/06 12:37:25 FUSE: -> [ID=0x44] Getattr valid=0s ino=81673 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x46 Node=0x5 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry /sys/module/nf_conntrack/parameters (Req ID=0x46)"
2021/06/06 12:37:25 FUSE: -> [ID=0x46] Getattr valid=0s ino=81675 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x48 Node=0x1 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x48)"
2021/06/06 12:37:25 FUSE: -> [ID=0x48] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x4a Node=0x7 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x4a)"
2021/06/06 12:37:25 FUSE: -> [ID=0x4a] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x4c Node=0x1 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x4c)"
2021/06/06 12:37:25 FUSE: -> [ID=0x4c] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x4e Node=0x7 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x4e)"
2021/06/06 12:37:25 FUSE: -> [ID=0x4e] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x50 Node=0x1 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x50)"
2021/06/06 12:37:25 FUSE: -> [ID=0x50] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x52 Node=0x7 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x52)"
2021/06/06 12:37:25 FUSE: -> [ID=0x52] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x54 Node=0x9 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry /proc/sys (Req ID=0x54)"
2021/06/06 12:37:25 FUSE: -> [ID=0x54] Getattr valid=0s ino=4026531854 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x56 Node=0x1 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x56)"
2021/06/06 12:37:25 FUSE: -> [ID=0x56] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x58 Node=0x7 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x58)"
2021/06/06 12:37:25 FUSE: -> [ID=0x58] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x5a Node=0x1 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x5a)"
2021/06/06 12:37:25 FUSE: -> [ID=0x5a] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x5c Node=0x7 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x5c)"
2021/06/06 12:37:25 FUSE: -> [ID=0x5c] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x5e Node=0x1 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x5e)"
2021/06/06 12:37:25 FUSE: -> [ID=0x5e] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:25 FUSE: <- Getattr [ID=0x60 Node=0x7 Uid=0 Gid=0 Pid=7198] 0x0 fl=0
time="2021-06-06 12:37:25" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x60)"
2021/06/06 12:37:25 FUSE: -> [ID=0x60] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
time="2021-06-06 12:37:31" level=debug msg="Container pre-registration started: id = 15f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a"
time="2021-06-06 12:37:31" level=debug msg="Container pre-registration completed: id = 15f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a"
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x4 Node=0x1 Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x4)"
2021/06/06 12:37:31 FUSE: -> [ID=0x4] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Lookup [ID=0x6 Node=0x1 Uid=0 Gid=0 Pid=7292] "sys"
time="2021-06-06 12:37:31" level=debug msg="Requested Lookup() operation for entry sys (req ID=0x6)"
time="2021-06-06 12:37:31" level=debug msg="Executing Lookup() method on sys handler: /sys"
time="2021-06-06 12:37:31" level=debug msg="Requested Attr() operation for entry /sys"
2021/06/06 12:37:31 FUSE: -> [ID=0x6] Lookup 0x2 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0}
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x8 Node=0x2 Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /sys (Req ID=0x8)"
2021/06/06 12:37:31 FUSE: -> [ID=0x8] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Lookup [ID=0xa Node=0x2 Uid=0 Gid=0 Pid=7292] "module"
time="2021-06-06 12:37:31" level=debug msg="Requested Lookup() operation for entry module (req ID=0xa)"
time="2021-06-06 12:37:31" level=debug msg="Executing Lookup() method on sys handler: /sys/module"
time="2021-06-06 12:37:31" level=debug msg="Requested Attr() operation for entry /sys/module"
2021/06/06 12:37:31 FUSE: -> [ID=0xa] Lookup 0x3 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=2048 size=0 mode=drwxr-xr-x uid=0 gid=0}
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0xc Node=0x3 Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /sys/module (Req ID=0xc)"
2021/06/06 12:37:31 FUSE: -> [ID=0xc] Getattr valid=0s ino=2048 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Lookup [ID=0xe Node=0x3 Uid=0 Gid=0 Pid=7292] "nf_conntrack"
time="2021-06-06 12:37:31" level=debug msg="Requested Lookup() operation for entry nf_conntrack (req ID=0xe)"
time="2021-06-06 12:37:31" level=debug msg="Executing Lookup() method on sys handler: /sys/module/nf_conntrack"
time="2021-06-06 12:37:31" level=debug msg="Requested Attr() operation for entry /sys/module/nf_conntrack"
2021/06/06 12:37:31 FUSE: -> [ID=0xe] Lookup 0x4 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=81673 size=0 mode=drwxr-xr-x uid=0 gid=0}
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x10 Node=0x4 Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /sys/module/nf_conntrack (Req ID=0x10)"
2021/06/06 12:37:31 FUSE: -> [ID=0x10] Getattr valid=0s ino=81673 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Lookup [ID=0x12 Node=0x4 Uid=0 Gid=0 Pid=7292] "parameters"
time="2021-06-06 12:37:31" level=debug msg="Requested Lookup() operation for entry parameters (req ID=0x12)"
time="2021-06-06 12:37:31" level=debug msg="Executing Lookup() method on sys handler: /sys/module/nf_conntrack/parameters"
time="2021-06-06 12:37:31" level=debug msg="Requested Attr() operation for entry /sys/module/nf_conntrack/parameters"
2021/06/06 12:37:31 FUSE: -> [ID=0x12] Lookup 0x5 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=81675 size=0 mode=drwxr-xr-x uid=0 gid=0}
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x14 Node=0x5 Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /sys/module/nf_conntrack/parameters (Req ID=0x14)"
2021/06/06 12:37:31 FUSE: -> [ID=0x14] Getattr valid=0s ino=81675 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Lookup [ID=0x16 Node=0x5 Uid=0 Gid=0 Pid=7292] "hashsize"
time="2021-06-06 12:37:31" level=debug msg="Requested Lookup() operation for entry hashsize (req ID=0x16)"
time="2021-06-06 12:37:31" level=debug msg="Executing Lookup() method on nfConntrackHashSize handler"
time="2021-06-06 12:37:31" level=debug msg="Requested Attr() operation for entry /sys/module/nf_conntrack/parameters/hashsize"
2021/06/06 12:37:31 FUSE: -> [ID=0x16] Lookup 0x6 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=81678 size=4096 mode=-rw------- uid=0 gid=0}
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x18 Node=0x6 Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /sys/module/nf_conntrack/parameters/hashsize (Req ID=0x18)"
2021/06/06 12:37:31 FUSE: -> [ID=0x18] Getattr valid=0s ino=81678 size=4096 mode=-rw------- uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x1a Node=0x1 Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x1a)"
2021/06/06 12:37:31 FUSE: -> [ID=0x1a] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Lookup [ID=0x1c Node=0x1 Uid=0 Gid=0 Pid=7292] "proc"
time="2021-06-06 12:37:31" level=debug msg="Requested Lookup() operation for entry proc (req ID=0x1c)"
time="2021-06-06 12:37:31" level=debug msg="Executing Lookup() method on proc handler"
time="2021-06-06 12:37:31" level=debug msg="Requested Attr() operation for entry /proc"
2021/06/06 12:37:31 FUSE: -> [ID=0x1c] Lookup 0x7 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0}
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x1e Node=0x7 Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x1e)"
2021/06/06 12:37:31 FUSE: -> [ID=0x1e] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Lookup [ID=0x20 Node=0x7 Uid=0 Gid=0 Pid=7292] "swaps"
time="2021-06-06 12:37:31" level=debug msg="Requested Lookup() operation for entry swaps (req ID=0x20)"
time="2021-06-06 12:37:31" level=debug msg="Executing Lookup() method on procSwaps handler"
time="2021-06-06 12:37:31" level=debug msg="Requested Attr() operation for entry /proc/swaps"
2021/06/06 12:37:31 FUSE: -> [ID=0x20] Lookup 0x8 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=4026532071 size=0 mode=-r--r--r-- uid=0 gid=0}
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x22 Node=0x8 Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /proc/swaps (Req ID=0x22)"
2021/06/06 12:37:31 FUSE: -> [ID=0x22] Getattr valid=0s ino=4026532071 size=0 mode=-r--r--r-- uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x24 Node=0x1 Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x24)"
2021/06/06 12:37:31 FUSE: -> [ID=0x24] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x26 Node=0x7 Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x26)"
2021/06/06 12:37:31 FUSE: -> [ID=0x26] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Lookup [ID=0x28 Node=0x7 Uid=0 Gid=0 Pid=7292] "sys"
time="2021-06-06 12:37:31" level=debug msg="Requested Lookup() operation for entry sys (req ID=0x28)"
time="2021-06-06 12:37:31" level=debug msg="Executing Lookup() method for Req ID=0x28 on procSys handler"
time="2021-06-06 12:37:31" level=debug msg="Requested Attr() operation for entry /proc/sys"
2021/06/06 12:37:31 FUSE: -> [ID=0x28] Lookup 0x9 gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=4026531854 size=0 mode=dr-xr-xr-x uid=0 gid=0}
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x2a Node=0x9 Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /proc/sys (Req ID=0x2a)"
2021/06/06 12:37:31 FUSE: -> [ID=0x2a] Getattr valid=0s ino=4026531854 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x2c Node=0x1 Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x2c)"
2021/06/06 12:37:31 FUSE: -> [ID=0x2c] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x2e Node=0x7 Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x2e)"
2021/06/06 12:37:31 FUSE: -> [ID=0x2e] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Lookup [ID=0x30 Node=0x7 Uid=0 Gid=0 Pid=7292] "uptime"
time="2021-06-06 12:37:31" level=debug msg="Requested Lookup() operation for entry uptime (req ID=0x30)"
time="2021-06-06 12:37:31" level=debug msg="Executing Lookup() method on procUptime handler"
time="2021-06-06 12:37:31" level=debug msg="Requested Attr() operation for entry /proc/uptime"
2021/06/06 12:37:31 FUSE: -> [ID=0x30] Lookup 0xa gen=0 valid=2562047h47m16.854775807s attr={valid=0s ino=4026532027 size=0 mode=-r--r--r-- uid=0 gid=0}
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x32 Node=0xa Uid=0 Gid=0 Pid=7292] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /proc/uptime (Req ID=0x32)"
2021/06/06 12:37:31 FUSE: -> [ID=0x32] Getattr valid=0s ino=4026532027 size=0 mode=-r--r--r-- uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x34 Node=0x1 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x34)"
2021/06/06 12:37:31 FUSE: -> [ID=0x34] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x36 Node=0x2 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /sys (Req ID=0x36)"
2021/06/06 12:37:31 FUSE: -> [ID=0x36] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x38 Node=0x3 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /sys/module (Req ID=0x38)"
2021/06/06 12:37:31 FUSE: -> [ID=0x38] Getattr valid=0s ino=2048 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x3a Node=0x4 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /sys/module/nf_conntrack (Req ID=0x3a)"
2021/06/06 12:37:31 FUSE: -> [ID=0x3a] Getattr valid=0s ino=81673 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x3c Node=0x5 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /sys/module/nf_conntrack/parameters (Req ID=0x3c)"
2021/06/06 12:37:31 FUSE: -> [ID=0x3c] Getattr valid=0s ino=81675 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x3e Node=0x1 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x3e)"
2021/06/06 12:37:31 FUSE: -> [ID=0x3e] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x40 Node=0x2 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /sys (Req ID=0x40)"
2021/06/06 12:37:31 FUSE: -> [ID=0x40] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x42 Node=0x3 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /sys/module (Req ID=0x42)"
2021/06/06 12:37:31 FUSE: -> [ID=0x42] Getattr valid=0s ino=2048 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x44 Node=0x4 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /sys/module/nf_conntrack (Req ID=0x44)"
2021/06/06 12:37:31 FUSE: -> [ID=0x44] Getattr valid=0s ino=81673 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x46 Node=0x5 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /sys/module/nf_conntrack/parameters (Req ID=0x46)"
2021/06/06 12:37:31 FUSE: -> [ID=0x46] Getattr valid=0s ino=81675 size=0 mode=drwxr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x48 Node=0x1 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x48)"
2021/06/06 12:37:31 FUSE: -> [ID=0x48] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x4a Node=0x7 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x4a)"
2021/06/06 12:37:31 FUSE: -> [ID=0x4a] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x4c Node=0x1 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x4c)"
2021/06/06 12:37:31 FUSE: -> [ID=0x4c] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x4e Node=0x7 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x4e)"
2021/06/06 12:37:31 FUSE: -> [ID=0x4e] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x50 Node=0x1 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x50)"
2021/06/06 12:37:31 FUSE: -> [ID=0x50] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x52 Node=0x7 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:31" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x52)"
2021/06/06 12:37:31 FUSE: -> [ID=0x52] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:31 FUSE: <- Getattr [ID=0x54 Node=0x9 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:32" level=debug msg="Requested GetAttr() operation for entry /proc/sys (Req ID=0x54)"
2021/06/06 12:37:32 FUSE: -> [ID=0x54] Getattr valid=0s ino=4026531854 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:32 FUSE: <- Getattr [ID=0x56 Node=0x1 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:32" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x56)"
2021/06/06 12:37:32 FUSE: -> [ID=0x56] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:32 FUSE: <- Getattr [ID=0x58 Node=0x7 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:32" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x58)"
2021/06/06 12:37:32 FUSE: -> [ID=0x58] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:32 FUSE: <- Getattr [ID=0x5a Node=0x1 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:32" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x5a)"
2021/06/06 12:37:32 FUSE: -> [ID=0x5a] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:32 FUSE: <- Getattr [ID=0x5c Node=0x7 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:32" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x5c)"
2021/06/06 12:37:32 FUSE: -> [ID=0x5c] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0
2021/06/06 12:37:32 FUSE: <- Getattr [ID=0x5e Node=0x1 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:32" level=debug msg="Requested GetAttr() operation for entry / (Req ID=0x5e)"
2021/06/06 12:37:32 FUSE: -> [ID=0x5e] Getattr valid=0s ino=2 size=4096 mode=drw------- uid=0 gid=0
2021/06/06 12:37:32 FUSE: <- Getattr [ID=0x60 Node=0x7 Uid=0 Gid=0 Pid=7341] 0x0 fl=0
time="2021-06-06 12:37:32" level=debug msg="Requested GetAttr() operation for entry /proc (Req ID=0x60)"
2021/06/06 12:37:32 FUSE: -> [ID=0x60] Getattr valid=0s ino=1 size=0 mode=dr-xr-xr-x uid=0 gid=0

Logs from sysbox-mgr.log:

root@test:/var/log# cat sysbox-mgr.log
time="2021-06-06 12:34:39" level=info msg="Starting ..."
time="2021-06-06 12:34:39" level=info msg="Sysbox data root: /var/lib/sysbox"
time="2021-06-06 12:34:39" level=info msg="Sys container DNS aliasing enabled."
time="2021-06-06 12:34:39" level=info msg="Listening on /run/sysbox/sysmgr.sock"
time="2021-06-06 12:34:39" level=debug msg="rootfsMon starting ..."
time="2021-06-06 12:34:39" level=info msg="Ready ..."
time="2021-06-06 12:34:45" level=info msg="Caught OS signal: terminated"
time="2021-06-06 12:34:45" level=info msg="Stopping (gracefully) ..."
time="2021-06-06 12:34:45" level=debug msg="rootfsMon exiting ..."
time="2021-06-06 12:34:45" level=info msg=Stopped.
time="2021-06-06 12:34:45" level=info msg=Exiting.
time="2021-06-06 12:34:45" level=info msg="Starting ..."
time="2021-06-06 12:34:45" level=info msg="Sysbox data root: /var/lib/sysbox"
time="2021-06-06 12:34:45" level=info msg="Sys container DNS aliasing enabled."
time="2021-06-06 12:34:45" level=info msg="Listening on /run/sysbox/sysmgr.sock"
time="2021-06-06 12:34:45" level=info msg="Ready ..."
time="2021-06-06 12:34:45" level=debug msg="rootfsMon starting ..."
time="2021-06-06 12:34:48" level=info msg="Caught OS signal: terminated"
time="2021-06-06 12:34:48" level=info msg="Stopping (gracefully) ..."
time="2021-06-06 12:34:48" level=debug msg="rootfsMon exiting ..."
time="2021-06-06 12:34:48" level=info msg=Stopped.
time="2021-06-06 12:34:48" level=info msg=Exiting.
time="2021-06-06 12:34:48" level=info msg="Starting ..."
time="2021-06-06 12:34:48" level=info msg="Sysbox data root: /var/lib/sysbox"
time="2021-06-06 12:34:49" level=info msg="Sys container DNS aliasing enabled."
time="2021-06-06 12:34:49" level=info msg="Listening on /run/sysbox/sysmgr.sock"
time="2021-06-06 12:34:49" level=info msg="Ready ..."
time="2021-06-06 12:34:49" level=debug msg="rootfsMon starting ..."
time="2021-06-06 12:37:24" level=info msg="registered new container cde1a0629a6e"
time="2021-06-06 12:37:24" level=debug msg="Alloc(cde1a0629a6e, 65536) = {sysbox 165536 65536}, {sysbox 165536 65536}"
time="2021-06-06 12:37:24" level=debug msg="kubeletVolMgr: created volume for container cde1a0629a6e"
time="2021-06-06 12:37:24" level=debug msg="containerdVolMgr: created volume for container cde1a0629a6e"
time="2021-06-06 12:37:24" level=debug msg="dockerVolMgr: created volume for container cde1a0629a6e"
time="2021-06-06 12:37:24" level=debug msg="autoRemoveCheck: Docker query start for cde1a0629a6e"
time="2021-06-06 12:37:24" level=debug msg="marked shiftfs on /usr/src/linux-headers-5.4.0-74"
time="2021-06-06 12:37:24" level=debug msg="marked shiftfs on /usr/src/linux-headers-5.4.0-74-generic"
time="2021-06-06 12:37:24" level=debug msg="marked shiftfs on /var/lib/docker/containers/cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917"
time="2021-06-06 12:37:24" level=debug msg="marked shiftfs on /lib/modules/5.4.0-74-generic"
time="2021-06-06 12:37:24" level=debug msg="marked shiftfs on /var/lib/docker/overlay2/79d25ddbfc3264840b3b84cd3efd94dcf3a8c280946cef21981c39ed9fb91771/merged"
time="2021-06-06 12:37:25" level=debug msg="unmarked shiftfs on /usr/src/linux-headers-5.4.0-74"
time="2021-06-06 12:37:25" level=debug msg="unmarked shiftfs on /usr/src/linux-headers-5.4.0-74-generic"
time="2021-06-06 12:37:25" level=debug msg="unmarked shiftfs on /var/lib/docker/containers/cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917"
time="2021-06-06 12:37:25" level=debug msg="unmarked shiftfs on /lib/modules/5.4.0-74-generic"
time="2021-06-06 12:37:25" level=debug msg="unmarked shiftfs on /var/lib/docker/overlay2/79d25ddbfc3264840b3b84cd3efd94dcf3a8c280946cef21981c39ed9fb91771/merged"
time="2021-06-06 12:37:25" level=debug msg="kubeletVolMgr: sync'd-out volume for container cde1a0629a6e"
time="2021-06-06 12:37:25" level=debug msg="containerdVolMgr: sync'd-out volume for container cde1a0629a6e"
time="2021-06-06 12:37:25" level=debug msg="dockerVolMgr: sync'd-out volume for container cde1a0629a6e"
time="2021-06-06 12:37:25" level=debug msg="added fs watch on /var/lib/docker/overlay2/79d25ddbfc3264840b3b84cd3efd94dcf3a8c280946cef21981c39ed9fb91771"
time="2021-06-06 12:37:25" level=info msg="unregistered container cde1a0629a6e"
time="2021-06-06 12:37:25" level=debug msg="autoRemoveCheck: done for cde1a0629a6e (autoRemove = false)"
time="2021-06-06 12:37:31" level=info msg="registered new container 15f7f65a0152"
time="2021-06-06 12:37:31" level=debug msg="Alloc(15f7f65a0152, 65536) = {sysbox 165536 65536}, {sysbox 165536 65536}"
time="2021-06-06 12:37:31" level=debug msg="containerdVolMgr: created volume for container 15f7f65a0152"
time="2021-06-06 12:37:31" level=debug msg="dockerVolMgr: created volume for container 15f7f65a0152"
time="2021-06-06 12:37:31" level=debug msg="kubeletVolMgr: created volume for container 15f7f65a0152"
time="2021-06-06 12:37:31" level=debug msg="autoRemoveCheck: Docker query start for 15f7f65a0152"
time="2021-06-06 12:37:31" level=debug msg="marked shiftfs on /usr/src/linux-headers-5.4.0-74"
time="2021-06-06 12:37:31" level=debug msg="marked shiftfs on /usr/src/linux-headers-5.4.0-74-generic"
time="2021-06-06 12:37:31" level=debug msg="marked shiftfs on /var/lib/docker/containers/15f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a"
time="2021-06-06 12:37:31" level=debug msg="marked shiftfs on /lib/modules/5.4.0-74-generic"
time="2021-06-06 12:37:31" level=debug msg="marked shiftfs on /var/lib/docker/overlay2/51638de218f81920cb926885887ca0fcebfc5d3e801790cd00e6474aa1e3de04/merged"
time="2021-06-06 12:37:32" level=debug msg="unmarked shiftfs on /usr/src/linux-headers-5.4.0-74"
time="2021-06-06 12:37:32" level=debug msg="unmarked shiftfs on /usr/src/linux-headers-5.4.0-74-generic"
time="2021-06-06 12:37:32" level=debug msg="unmarked shiftfs on /var/lib/docker/containers/15f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a"
time="2021-06-06 12:37:32" level=debug msg="unmarked shiftfs on /lib/modules/5.4.0-74-generic"
time="2021-06-06 12:37:32" level=debug msg="unmarked shiftfs on /var/lib/docker/overlay2/51638de218f81920cb926885887ca0fcebfc5d3e801790cd00e6474aa1e3de04/merged"
time="2021-06-06 12:37:32" level=debug msg="containerdVolMgr: sync'd-out volume for container 15f7f65a0152"
time="2021-06-06 12:37:32" level=debug msg="dockerVolMgr: sync'd-out volume for container 15f7f65a0152"
time="2021-06-06 12:37:32" level=debug msg="kubeletVolMgr: sync'd-out volume for container 15f7f65a0152"
time="2021-06-06 12:37:32" level=debug msg="added fs watch on /var/lib/docker/overlay2/51638de218f81920cb926885887ca0fcebfc5d3e801790cd00e6474aa1e3de04"
time="2021-06-06 12:37:32" level=info msg="unregistered container 15f7f65a0152"
time="2021-06-06 12:37:32" level=debug msg="autoRemoveCheck: done for 15f7f65a0152 (autoRemove = false)"
time="2021-06-06 12:37:35" level=debug msg="rootfsMon: rm on /var/lib/docker/overlay2/79d25ddbfc3264840b3b84cd3efd94dcf3a8c280946cef21981c39ed9fb91771"
time="2021-06-06 12:37:35" level=debug msg="kubeletVolMgr: destroyed volume for container cde1a0629a6e"
time="2021-06-06 12:37:35" level=debug msg="containerdVolMgr: destroyed volume for container cde1a0629a6e"
time="2021-06-06 12:37:35" level=debug msg="dockerVolMgr: destroyed volume for container cde1a0629a6e"
time="2021-06-06 12:37:35" level=debug msg="Free(cde1a0629a6e)"
time="2021-06-06 12:37:35" level=info msg="released resources for container cde1a0629a6e"
time="2021-06-06 12:37:35" level=debug msg="rootfsMon: rm on /var/lib/docker/overlay2/51638de218f81920cb926885887ca0fcebfc5d3e801790cd00e6474aa1e3de04"
time="2021-06-06 12:37:35" level=debug msg="containerdVolMgr: destroyed volume for container 15f7f65a0152"
time="2021-06-06 12:37:35" level=debug msg="dockerVolMgr: destroyed volume for container 15f7f65a0152"
time="2021-06-06 12:37:35" level=debug msg="kubeletVolMgr: destroyed volume for container 15f7f65a0152"
time="2021-06-06 12:37:35" level=debug msg="Free(15f7f65a0152)"
time="2021-06-06 12:37:35" level=info msg="released resources for container 15f7f65a0152"root@test:/var/log# cat sysbox-mgr.log
time="2021-06-06 12:34:39" level=info msg="Starting ..."
time="2021-06-06 12:34:39" level=info msg="Sysbox data root: /var/lib/sysbox"
time="2021-06-06 12:34:39" level=info msg="Sys container DNS aliasing enabled."
time="2021-06-06 12:34:39" level=info msg="Listening on /run/sysbox/sysmgr.sock"
time="2021-06-06 12:34:39" level=debug msg="rootfsMon starting ..."
time="2021-06-06 12:34:39" level=info msg="Ready ..."
time="2021-06-06 12:34:45" level=info msg="Caught OS signal: terminated"
time="2021-06-06 12:34:45" level=info msg="Stopping (gracefully) ..."
time="2021-06-06 12:34:45" level=debug msg="rootfsMon exiting ..."
time="2021-06-06 12:34:45" level=info msg=Stopped.
time="2021-06-06 12:34:45" level=info msg=Exiting.
time="2021-06-06 12:34:45" level=info msg="Starting ..."
time="2021-06-06 12:34:45" level=info msg="Sysbox data root: /var/lib/sysbox"
time="2021-06-06 12:34:45" level=info msg="Sys container DNS aliasing enabled."
time="2021-06-06 12:34:45" level=info msg="Listening on /run/sysbox/sysmgr.sock"
time="2021-06-06 12:34:45" level=info msg="Ready ..."
time="2021-06-06 12:34:45" level=debug msg="rootfsMon starting ..."
time="2021-06-06 12:34:48" level=info msg="Caught OS signal: terminated"
time="2021-06-06 12:34:48" level=info msg="Stopping (gracefully) ..."
time="2021-06-06 12:34:48" level=debug msg="rootfsMon exiting ..."
time="2021-06-06 12:34:48" level=info msg=Stopped.
time="2021-06-06 12:34:48" level=info msg=Exiting.
time="2021-06-06 12:34:48" level=info msg="Starting ..."
time="2021-06-06 12:34:48" level=info msg="Sysbox data root: /var/lib/sysbox"
time="2021-06-06 12:34:49" level=info msg="Sys container DNS aliasing enabled."
time="2021-06-06 12:34:49" level=info msg="Listening on /run/sysbox/sysmgr.sock"
time="2021-06-06 12:34:49" level=info msg="Ready ..."
time="2021-06-06 12:34:49" level=debug msg="rootfsMon starting ..."
time="2021-06-06 12:37:24" level=info msg="registered new container cde1a0629a6e"
time="2021-06-06 12:37:24" level=debug msg="Alloc(cde1a0629a6e, 65536) = {sysbox 165536 65536}, {sysbox 165536 65536}"
time="2021-06-06 12:37:24" level=debug msg="kubeletVolMgr: created volume for container cde1a0629a6e"
time="2021-06-06 12:37:24" level=debug msg="containerdVolMgr: created volume for container cde1a0629a6e"
time="2021-06-06 12:37:24" level=debug msg="dockerVolMgr: created volume for container cde1a0629a6e"
time="2021-06-06 12:37:24" level=debug msg="autoRemoveCheck: Docker query start for cde1a0629a6e"
time="2021-06-06 12:37:24" level=debug msg="marked shiftfs on /usr/src/linux-headers-5.4.0-74"
time="2021-06-06 12:37:24" level=debug msg="marked shiftfs on /usr/src/linux-headers-5.4.0-74-generic"
time="2021-06-06 12:37:24" level=debug msg="marked shiftfs on /var/lib/docker/containers/cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917"
time="2021-06-06 12:37:24" level=debug msg="marked shiftfs on /lib/modules/5.4.0-74-generic"
time="2021-06-06 12:37:24" level=debug msg="marked shiftfs on /var/lib/docker/overlay2/79d25ddbfc3264840b3b84cd3efd94dcf3a8c280946cef21981c39ed9fb91771/merged"
time="2021-06-06 12:37:25" level=debug msg="unmarked shiftfs on /usr/src/linux-headers-5.4.0-74"
time="2021-06-06 12:37:25" level=debug msg="unmarked shiftfs on /usr/src/linux-headers-5.4.0-74-generic"
time="2021-06-06 12:37:25" level=debug msg="unmarked shiftfs on /var/lib/docker/containers/cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917"
time="2021-06-06 12:37:25" level=debug msg="unmarked shiftfs on /lib/modules/5.4.0-74-generic"
time="2021-06-06 12:37:25" level=debug msg="unmarked shiftfs on /var/lib/docker/overlay2/79d25ddbfc3264840b3b84cd3efd94dcf3a8c280946cef21981c39ed9fb91771/merged"
time="2021-06-06 12:37:25" level=debug msg="kubeletVolMgr: sync'd-out volume for container cde1a0629a6e"
time="2021-06-06 12:37:25" level=debug msg="containerdVolMgr: sync'd-out volume for container cde1a0629a6e"
time="2021-06-06 12:37:25" level=debug msg="dockerVolMgr: sync'd-out volume for container cde1a0629a6e"
time="2021-06-06 12:37:25" level=debug msg="added fs watch on /var/lib/docker/overlay2/79d25ddbfc3264840b3b84cd3efd94dcf3a8c280946cef21981c39ed9fb91771"
time="2021-06-06 12:37:25" level=info msg="unregistered container cde1a0629a6e"
time="2021-06-06 12:37:25" level=debug msg="autoRemoveCheck: done for cde1a0629a6e (autoRemove = false)"
time="2021-06-06 12:37:31" level=info msg="registered new container 15f7f65a0152"
time="2021-06-06 12:37:31" level=debug msg="Alloc(15f7f65a0152, 65536) = {sysbox 165536 65536}, {sysbox 165536 65536}"
time="2021-06-06 12:37:31" level=debug msg="containerdVolMgr: created volume for container 15f7f65a0152"
time="2021-06-06 12:37:31" level=debug msg="dockerVolMgr: created volume for container 15f7f65a0152"
time="2021-06-06 12:37:31" level=debug msg="kubeletVolMgr: created volume for container 15f7f65a0152"
time="2021-06-06 12:37:31" level=debug msg="autoRemoveCheck: Docker query start for 15f7f65a0152"
time="2021-06-06 12:37:31" level=debug msg="marked shiftfs on /usr/src/linux-headers-5.4.0-74"
time="2021-06-06 12:37:31" level=debug msg="marked shiftfs on /usr/src/linux-headers-5.4.0-74-generic"
time="2021-06-06 12:37:31" level=debug msg="marked shiftfs on /var/lib/docker/containers/15f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a"
time="2021-06-06 12:37:31" level=debug msg="marked shiftfs on /lib/modules/5.4.0-74-generic"
time="2021-06-06 12:37:31" level=debug msg="marked shiftfs on /var/lib/docker/overlay2/51638de218f81920cb926885887ca0fcebfc5d3e801790cd00e6474aa1e3de04/merged"
time="2021-06-06 12:37:32" level=debug msg="unmarked shiftfs on /usr/src/linux-headers-5.4.0-74"
time="2021-06-06 12:37:32" level=debug msg="unmarked shiftfs on /usr/src/linux-headers-5.4.0-74-generic"
time="2021-06-06 12:37:32" level=debug msg="unmarked shiftfs on /var/lib/docker/containers/15f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a"
time="2021-06-06 12:37:32" level=debug msg="unmarked shiftfs on /lib/modules/5.4.0-74-generic"
time="2021-06-06 12:37:32" level=debug msg="unmarked shiftfs on /var/lib/docker/overlay2/51638de218f81920cb926885887ca0fcebfc5d3e801790cd00e6474aa1e3de04/merged"
time="2021-06-06 12:37:32" level=debug msg="containerdVolMgr: sync'd-out volume for container 15f7f65a0152"
time="2021-06-06 12:37:32" level=debug msg="dockerVolMgr: sync'd-out volume for container 15f7f65a0152"
time="2021-06-06 12:37:32" level=debug msg="kubeletVolMgr: sync'd-out volume for container 15f7f65a0152"
time="2021-06-06 12:37:32" level=debug msg="added fs watch on /var/lib/docker/overlay2/51638de218f81920cb926885887ca0fcebfc5d3e801790cd00e6474aa1e3de04"
time="2021-06-06 12:37:32" level=info msg="unregistered container 15f7f65a0152"
time="2021-06-06 12:37:32" level=debug msg="autoRemoveCheck: done for 15f7f65a0152 (autoRemove = false)"
time="2021-06-06 12:37:35" level=debug msg="rootfsMon: rm on /var/lib/docker/overlay2/79d25ddbfc3264840b3b84cd3efd94dcf3a8c280946cef21981c39ed9fb91771"
time="2021-06-06 12:37:35" level=debug msg="kubeletVolMgr: destroyed volume for container cde1a0629a6e"
time="2021-06-06 12:37:35" level=debug msg="containerdVolMgr: destroyed volume for container cde1a0629a6e"
time="2021-06-06 12:37:35" level=debug msg="dockerVolMgr: destroyed volume for container cde1a0629a6e"
time="2021-06-06 12:37:35" level=debug msg="Free(cde1a0629a6e)"
time="2021-06-06 12:37:35" level=info msg="released resources for container cde1a0629a6e"
time="2021-06-06 12:37:35" level=debug msg="rootfsMon: rm on /var/lib/docker/overlay2/51638de218f81920cb926885887ca0fcebfc5d3e801790cd00e6474aa1e3de04"
time="2021-06-06 12:37:35" level=debug msg="containerdVolMgr: destroyed volume for container 15f7f65a0152"
time="2021-06-06 12:37:35" level=debug msg="dockerVolMgr: destroyed volume for container 15f7f65a0152"
time="2021-06-06 12:37:35" level=debug msg="kubeletVolMgr: destroyed volume for container 15f7f65a0152"
time="2021-06-06 12:37:35" level=debug msg="Free(15f7f65a0152)"
time="2021-06-06 12:37:35" level=info msg="released resources for container 15f7f65a0152"

And logs from Docker Daemon (after adding "debug": true to daemon.json):

root@test:~# grep dockerd /var/log/syslog
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.034231887Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/79d25ddbfc3264840b3b84cd3efd94dcf3a8c280946cef21981c39ed9fb91771/merged 0x560f4fe10440 0x560f4fe10440}" container=cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.115879897Z" level=debug msg="Creating service config in agent for t = &Task{ID:60wqekewd2bvqj30fkxtynd4b,Meta:Meta{Version:Version{Index:92,},CreatedAt:2021-06-06T12:37:23.060970997Z,UpdatedAt:2021-06-06T12:37:23.118639565Z,},Spec:TaskSpec{Runtime:&TaskSpec_Container{Container:&ContainerSpec{Image:alpine:latest@sha256:69e70a79f2d41ab5d637de98c1e0b055206ba40a8145e7bddb55ccc04e13cf8f,Labels:map[string]string{com.docker.stack.namespace: test,},Command:[],Args:[],Env:[],Dir:,User:,Mounts:[],StopGracePeriod:(duration: nil types.Duration),PullOptions:nil,Groups:[],Secrets:[&SecretReference{SecretID:er7pay1q0xyuycub7pm6ymzby,SecretName:TEST_SECRET,Target:&SecretReference_File{File:&FileTarget{Name:TEST_SECRET,UID:0,GID:0,Mode:-r--r--r--,},},}],TTY:false,Hostname:,DNSConfig:nil,Healthcheck:nil,Hosts:[],OpenStdin:false,ReadOnly:false,StopSignal:,Configs:[],Privileges:&Privileges{CredentialSpec:nil,SELinuxContext:nil,},Init:nil,Isolation:ISOLATION_DEFAULT,PidsLimit:0,Sysctls:map[string]string{},CapabilityAdd:[],CapabilityDrop:[],Ulimits:[],},},Resources:&ResourceRequirements{Limits:nil,Reservations:nil,SwapBytes:nil,MemorySwappiness:nil,},Restart:nil,Placement:&Placement{Constraints:[],Preferences:[],Platforms:[&Platform{Architecture:amd64,OS:linux,} &Platform{Architecture:,OS:linux,} &Platform{Architecture:,OS:linux,} &Platform{Architecture:arm64,OS:linux,} &Platform{Architecture:386,OS:linux,} &Platform{Architecture:ppc64le,OS:linux,} &Platform{Architecture:s390x,OS:linux,}],MaxReplicas:0,},LogDriver:nil,Networks:[&NetworkAttachmentConfig{Target:j2k7afr70xi1rnxj9enqhvajh,Aliases:[test],Addresses:[],DriverAttachmentOpts:map[string]string{},}],ForceUpdate:0,ResourceReferences:[],},ServiceID:ayxr14m1x66tg5nqkx6vnknoj,Slot:1,NodeID:jkgezfw4naz0ffuq33a7wekk1,Annotations:Annotations{Name:,Labels:map[string]string{},Indices:[],},ServiceAnnotations:Annotations{Name:test_test,Labels:map[string]string{com.docker.stack.image: alpine:latest,com.docker.stack.namespace: test,},Indices:[],},Status:TaskStatus{Timestamp:2021-06-06T12:37:23.118487941Z,State:ASSIGNED,Message:scheduler assigned task to node,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil types.Timestamp),},DesiredState:RUNNING,Networks:[&NetworkAttachment{Network:&Network{ID:j2k7afr70xi1rnxj9enqhvajh,Meta:Meta{Version:Version{Index:87,},CreatedAt:2021-06-06T12:37:21.018704424Z,UpdatedAt:2021-06-06T12:37:21.020832036Z,},Spec:NetworkSpec{Annotations:Annotations{Name:test_default,Labels:map[string]string{com.docker.stack.namespace: test,},Indices:[],},DriverConfig:&Driver{Name:overlay,Options:map[string]string{},},Ipv6Enabled:false,Internal:false,IPAM:nil,Attachable:false,Ingress:false,ConfigFrom:<nil>,},DriverState:&Driver{Name:overlay,Options:map[string]string{com.docker.network.driver.overlay.vxlanid_list: 4097,},},IPAM:&IPAMOptions{Driver:&Driver{Name:default,Options:map[string]string{},},Configs:[&IPAMConfig{Family:IPV4,Subnet:10.0.1.0/24,Range:,Gateway:10.0.1.1,Reserved:map[string]string{},}],},PendingDelete:false,},Addresses:[10.0.1.3/24],Aliases:[test],DriverAttachmentOpts:map[string]string{},}],Endpoint:&Endpoint{Spec:&EndpointSpec{Mode:VIP,Ports:[],},Ports:[],VirtualIPs:[&Endpoint_VirtualIP{NetworkID:j2k7afr70xi1rnxj9enqhvajh,Addr:10.0.1.2/24,}],},LogDriver:nil,SpecVersion:&Version{Index:0,},AssignedGenericResources:[],JobIteration:nil,}"
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.116004609Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj state.desired=RUNNING state.transition="PREPARING->READY" task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.116147121Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.116722990Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.124091124Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj state.desired=RUNNING state.transition="READY->STARTING" task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.124274325Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.124772712Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.135130630Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/79d25ddbfc3264840b3b84cd3efd94dcf3a8c280946cef21981c39ed9fb91771/merged 0x560f4fe10440 0x560f4fe10440}" container=cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.135524899Z" level=debug msg="Assigning addresses for endpoint test_test.1.60wqekewd2bvqj30fkxtynd4b's interface on network test_default"
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.135569373Z" level=debug msg="RequestAddress(LocalDefault/10.0.1.0/24, 10.0.1.3, map[])"
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.135591510Z" level=debug msg="Request address PoolID:10.0.1.0/24 App: ipam/default/data, ID: LocalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 252, Sequence: (0xc8000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:0 Serial:false PrefAddress:10.0.1.3 "
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.140078885Z" level=debug msg="Assigning addresses for endpoint test_test.1.60wqekewd2bvqj30fkxtynd4b's interface on network test_default"
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.186567809Z" level=debug msg="state for task 60wqekewd2bvqj30fkxtynd4b updated to STARTING" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="PREPARING->STARTING" task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.186802547Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="PREPARING->STARTING" task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.189387653Z" level=debug msg="Task 60wqekewd2bvqj30fkxtynd4b is already in allocated state STARTING" method="(*Allocator).doTaskAlloc" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.190733885Z" level=debug msg="checkEncryption(j2k7afr, <nil>, 4097, true)"
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.191549888Z" level=debug msg="Assigning addresses for endpoint gateway_3545238b8109's interface on network docker_gwbridge"
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.191678025Z" level=debug msg="RequestAddress(LocalDefault/172.25.0.0/24, <nil>, map[])"
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.191778223Z" level=debug msg="Request address PoolID:172.25.0.0/24 App: ipam/default/data, ID: LocalDefault/172.25.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 252, Sequence: (0xe0000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:3 Serial:false PrefAddress:<nil> "
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.204729506Z" level=debug msg="Assigning addresses for endpoint gateway_3545238b8109's interface on network docker_gwbridge"
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.211021052Z" level=debug msg="Programming external connectivity on endpoint gateway_3545238b8109 (655d48c4c9ebef72550b605778b0b4c956b62bdce6d2e7db49f37c8f403e98cb)"
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.224091373Z" level=debug msg="injecting secret" name=TEST_SECRET path=/var/lib/docker/containers/cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917/mounts/secrets/er7pay1q0xyuycub7pm6ymzby
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.224406080Z" level=debug msg="bundle dir created" bundle=/var/run/docker/containerd/cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917 module=libcontainerd namespace=moby root=/var/lib/docker/overlay2/79d25ddbfc3264840b3b84cd3efd94dcf3a8c280946cef21981c39ed9fb91771/merged
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.297284139Z" level=debug msg="Calling HEAD /_ping"
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.297937846Z" level=debug msg="Calling GET /v1.41/info"
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.308137740Z" level=debug msg="Calling HEAD /_ping"
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.308485892Z" level=debug msg="Calling GET /v1.41/info"
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.328595449Z" level=debug msg="Calling GET /v1.41/containers/cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917/json"
Jun  6 12:37:24 test dockerd[6605]: time="2021-06-06T12:37:24.331550997Z" level=debug msg="Calling GET /v1.41/containers/json?all=1&filters=%7B%22id%22%3A%7B%22cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917%22%3Atrue%7D%7D&limit=0"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.345338994Z" level=debug msg="Calling HEAD /_ping"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.348557736Z" level=debug msg="Calling GET /v1.41/info"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.367057952Z" level=debug msg="Calling GET /v1.41/containers/json?all=1&filters=%7B%22id%22%3A%7B%22cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917%22%3Atrue%7D%7D&limit=0"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.379160540Z" level=error msg="stream copy error: reading from a closed fifo"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.385870908Z" level=error msg="stream copy error: reading from a closed fifo"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.399098517Z" level=debug msg="deleteServiceInfoFromCluster from sbLeave START for test_test 3222cc37ef6aca5ddf00f02d9476e54560e0d2d02db43c0081d2b2b1be72f58c"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.399134574Z" level=warning msg="deleteServiceInfoFromCluster NetworkDB DeleteEntry failed for 3222cc37ef6aca5ddf00f02d9476e54560e0d2d02db43c0081d2b2b1be72f58c j2k7afr70xi1rnxj9enqhvajh err:cannot delete entry endpoint_table with network id j2k7afr70xi1rnxj9enqhvajh and key 3222cc37ef6aca5ddf00f02d9476e54560e0d2d02db43c0081d2b2b1be72f58c does not exist or is already being deleted"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.399154805Z" level=warning msg="rmServiceBinding deleteServiceInfoFromCluster test_test 3222cc37ef6aca5ddf00f02d9476e54560e0d2d02db43c0081d2b2b1be72f58c aborted c.serviceBindings[skey] !ok"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.399166252Z" level=debug msg="deleteServiceInfoFromCluster from sbLeave END for test_test 3222cc37ef6aca5ddf00f02d9476e54560e0d2d02db43c0081d2b2b1be72f58c"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.399377283Z" level=debug msg="Revoking external connectivity on endpoint gateway_3545238b8109 (655d48c4c9ebef72550b605778b0b4c956b62bdce6d2e7db49f37c8f403e98cb)"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.399565914Z" level=debug msg="checkEncryption(j2k7afr, 10.0.0.180, 0, true)"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.400894926Z" level=debug msg="DeleteConntrackEntries purged ipv4:0, ipv6:0"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.461532829Z" level=debug msg="Releasing addresses for endpoint gateway_3545238b8109's interface on network docker_gwbridge"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.461779565Z" level=debug msg="ReleaseAddress(LocalDefault/172.25.0.0/24, 172.25.0.3)"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.461965270Z" level=debug msg="Released address PoolID:LocalDefault/172.25.0.0/24, Address:172.25.0.3 Sequence:App: ipam/default/data, ID: LocalDefault/172.25.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 251, Sequence: (0xf0000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:4"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.514029833Z" level=debug msg="Releasing addresses for endpoint test_test.1.60wqekewd2bvqj30fkxtynd4b's interface on network test_default"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.514268917Z" level=debug msg="ReleaseAddress(LocalDefault/10.0.1.0/24, 10.0.1.3)"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.514411879Z" level=debug msg="Released address PoolID:LocalDefault/10.0.1.0/24, Address:10.0.1.3 Sequence:App: ipam/default/data, ID: LocalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 251, Sequence: (0xd8000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:0"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.835247361Z" level=error msg="cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917 cleanup: failed to delete container from containerd: no such container"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.835303325Z" level=error msg="fatal task error" error="starting container failed: OCI runtime create failed: container_linux.go:392: starting container process caused: process_linux.go:592: container init caused: process_linux.go:563: handleReqOp caused: rootfs_init_linux.go:260: bind mounting /var/lib/docker/containers/cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917/mounts/secrets/er7pay1q0xyuycub7pm6ymzby to run/secrets/TEST_SECRET caused: bind-mount of /var/lib/docker/containers/cde1a0629a6ed5c0acc10b91356e71f243c4e30c6376b4542c9702d5eed85917/mounts/secrets/er7pay1q0xyuycub7pm6ymzby to run/secrets/TEST_SECRET failed: exit status 32: unknown" module=node/agent/taskmanager node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.835679811Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj state.desired=RUNNING state.transition="STARTING->FAILED" task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.836978594Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.837716092Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.852453742Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.853026467Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.893724609Z" level=debug msg="state for task 60wqekewd2bvqj30fkxtynd4b updated to FAILED" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="STARTING->FAILED" task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.894024738Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="STARTING->FAILED" task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.898086440Z" level=debug msg="ReleaseAddress(GlobalDefault/10.0.1.0/24, 10.0.1.3)"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.898134585Z" level=debug msg="Released address PoolID:GlobalDefault/10.0.1.0/24, Address:10.0.1.3 Sequence:App: ipam/default/data, ID: GlobalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 250, Sequence: (0xf8000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:5"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.898200870Z" level=debug msg="ReleaseAddress(GlobalDefault/10.0.1.0/24, 10.0.1.4)"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.898219221Z" level=debug msg="Released address PoolID:GlobalDefault/10.0.1.0/24, Address:10.0.1.4 Sequence:App: ipam/default/data, ID: GlobalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 251, Sequence: (0xe8000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:5"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.904109815Z" level=debug msg="task lavfckhhvy22l0mnkebbkcr3p was marked pending allocation" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.904162327Z" level=debug msg="RequestAddress(GlobalDefault/10.0.1.0/24, <nil>, map[com.docker.network.ipam.serial:true])"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.904245175Z" level=debug msg="Request address PoolID:10.0.1.0/24 App: ipam/default/data, ID: GlobalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 252, Sequence: (0xe0000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:5 Serial:true PrefAddress:<nil> "
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.904292557Z" level=debug msg="allocated task lavfckhhvy22l0mnkebbkcr3p, state update PENDING" method="(*Allocator).allocateTask" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.904489667Z" level=debug msg="committed allocated task lavfckhhvy22l0mnkebbkcr3p, state update {2021-06-06T12:37:25.904289171Z PENDING pending task scheduling  <nil> nil  (timestamp: nil Timestamp)}" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.904615688Z" level=info msg="initialized VXLAN UDP port to 4789 "
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.906095675Z" level=debug msg="Task lavfckhhvy22l0mnkebbkcr3p is already in allocated state PENDING" method="(*Allocator).doTaskAlloc" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.914284614Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.914687777Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.577968039s" method="(*Dispatcher).Heartbeat"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.914826527Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.577968039s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.956211543Z" level=debug msg="assigning to node jkgezfw4naz0ffuq33a7wekk1" module=node node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.958662500Z" level=debug msg="RequestAddress(GlobalDefault/10.0.1.0/24, <nil>, map[com.docker.network.ipam.serial:true])"
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.958706503Z" level=debug msg="Request address PoolID:10.0.1.0/24 App: ipam/default/data, ID: GlobalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 251, Sequence: (0xe4000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:6 Serial:true PrefAddress:<nil> "
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.960194689Z" level=debug msg="Task lavfckhhvy22l0mnkebbkcr3p is already in allocated state ASSIGNED" method="(*Allocator).doTaskAlloc" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:25 test dockerd[6605]: time="2021-06-06T12:37:25.962592876Z" level=info msg="initialized VXLAN UDP port to 4789 "
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.059057809Z" level=debug msg="(*worker).Update" len(assignments)=3 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.059323078Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=1 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.059444299Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.059598072Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=2 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.059716931Z" level=debug msg=assigned module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.desiredstate=SHUTDOWN task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.059857094Z" level=debug msg=assigned module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.desiredstate=READY task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.060057008Z" level=debug msg="state changed" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj state.desired=READY state.transition="ASSIGNED->ACCEPTED" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.060292078Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.060429886Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj state.desired=READY state.transition="ASSIGNED->ACCEPTED" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.064655145Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.064682214Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.065041988Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.067225974Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.067665328Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.070186076Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj state.desired=READY state.transition="ACCEPTED->PREPARING" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.070337128Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.070684874Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.098384112Z" level=debug msg="state for task lavfckhhvy22l0mnkebbkcr3p updated to PREPARING" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="ASSIGNED->PREPARING" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.098563340Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="ASSIGNED->PREPARING" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.098604192Z" level=debug msg="state for task 60wqekewd2bvqj30fkxtynd4b updated to FAILED" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="FAILED->FAILED" task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.098648698Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="FAILED->FAILED" task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.186706477Z" level=debug msg="Task lavfckhhvy22l0mnkebbkcr3p is already in allocated state PREPARING" method="(*Allocator).doTaskAlloc" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.255894384Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/51638de218f81920cb926885887ca0fcebfc5d3e801790cd00e6474aa1e3de04/merged 0x560f4fe10440 0x560f4fe10440}" container=15f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.409688553Z" level=debug msg="Calling HEAD /_ping"
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.410604973Z" level=debug msg="Calling GET /v1.41/info"
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.421868957Z" level=debug msg="Creating service config in agent for t = &Task{ID:lavfckhhvy22l0mnkebbkcr3p,Meta:Meta{Version:Version{Index:100,},CreatedAt:2021-06-06T12:37:25.898292609Z,UpdatedAt:2021-06-06T12:37:25.956381335Z,},Spec:TaskSpec{Runtime:&TaskSpec_Container{Container:&ContainerSpec{Image:alpine:latest@sha256:69e70a79f2d41ab5d637de98c1e0b055206ba40a8145e7bddb55ccc04e13cf8f,Labels:map[string]string{com.docker.stack.namespace: test,},Command:[],Args:[],Env:[],Dir:,User:,Mounts:[],StopGracePeriod:(duration: nil types.Duration),PullOptions:nil,Groups:[],Secrets:[&SecretReference{SecretID:er7pay1q0xyuycub7pm6ymzby,SecretName:TEST_SECRET,Target:&SecretReference_File{File:&FileTarget{Name:TEST_SECRET,UID:0,GID:0,Mode:-r--r--r--,},},}],TTY:false,Hostname:,DNSConfig:nil,Healthcheck:nil,Hosts:[],OpenStdin:false,ReadOnly:false,StopSignal:,Configs:[],Privileges:&Privileges{CredentialSpec:nil,SELinuxContext:nil,},Init:nil,Isolation:ISOLATION_DEFAULT,PidsLimit:0,Sysctls:map[string]string{},CapabilityAdd:[],CapabilityDrop:[],Ulimits:[],},},Resources:&ResourceRequirements{Limits:nil,Reservations:nil,SwapBytes:nil,MemorySwappiness:nil,},Restart:nil,Placement:&Placement{Constraints:[],Preferences:[],Platforms:[&Platform{Architecture:amd64,OS:linux,} &Platform{Architecture:,OS:linux,} &Platform{Architecture:,OS:linux,} &Platform{Architecture:arm64,OS:linux,} &Platform{Architecture:386,OS:linux,} &Platform{Architecture:ppc64le,OS:linux,} &Platform{Architecture:s390x,OS:linux,}],MaxReplicas:0,},LogDriver:nil,Networks:[&NetworkAttachmentConfig{Target:j2k7afr70xi1rnxj9enqhvajh,Aliases:[test],Addresses:[],DriverAttachmentOpts:map[string]string{},}],ForceUpdate:0,ResourceReferences:[],},ServiceID:ayxr14m1x66tg5nqkx6vnknoj,Slot:1,NodeID:jkgezfw4naz0ffuq33a7wekk1,Annotations:Annotations{Name:,Labels:map[string]string{},Indices:[],},ServiceAnnotations:Annotations{Name:test_test,Labels:map[string]string{com.docker.stack.image: alpine:latest,com.docker.stack.namespace: test,},Indices:[],},Status:TaskStatus{Timestamp:2021-06-06T12:37:25.956266667Z,State:ASSIGNED,Message:scheduler assigned task to node,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil types.Timestamp),},DesiredState:READY,Networks:[&NetworkAttachment{Network:&Network{ID:j2k7afr70xi1rnxj9enqhvajh,Meta:Meta{Version:Version{Index:87,},CreatedAt:2021-06-06T12:37:21.018704424Z,UpdatedAt:2021-06-06T12:37:21.020832036Z,},Spec:NetworkSpec{Annotations:Annotations{Name:test_default,Labels:map[string]string{com.docker.stack.namespace: test,},Indices:[],},DriverConfig:&Driver{Name:overlay,Options:map[string]string{},},Ipv6Enabled:false,Internal:false,IPAM:nil,Attachable:false,Ingress:false,ConfigFrom:<nil>,},DriverState:&Driver{Name:overlay,Options:map[string]string{com.docker.network.driver.overlay.vxlanid_list: 4097,},},IPAM:&IPAMOptions{Driver:&Driver{Name:default,Options:map[string]string{},},Configs:[&IPAMConfig{Family:IPV4,Subnet:10.0.1.0/24,Range:,Gateway:10.0.1.1,Reserved:map[string]string{},}],},PendingDelete:false,},Addresses:[10.0.1.5/24],Aliases:[test],DriverAttachmentOpts:map[string]string{},}],Endpoint:&Endpoint{Spec:&EndpointSpec{Mode:VIP,Ports:[],},Ports:[],VirtualIPs:[&Endpoint_VirtualIP{NetworkID:j2k7afr70xi1rnxj9enqhvajh,Addr:10.0.1.2/24,}],},LogDriver:nil,SpecVersion:&Version{Index:0,},AssignedGenericResources:[],JobIteration:nil,}"
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.421968504Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj state.desired=READY state.transition="PREPARING->READY" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.422141723Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.422652816Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.429935500Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.430386296Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.434734304Z" level=debug msg="Calling GET /v1.41/nodes/jkgezfw4naz0ffuq33a7wekk1"
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.435686482Z" level=debug msg="Calling GET /v1.41/tasks?filters=%7B%22node%22%3A%7B%22jkgezfw4naz0ffuq33a7wekk1%22%3Atrue%7D%7D"
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.437485969Z" level=debug msg="Calling GET /v1.41/services/ayxr14m1x66tg5nqkx6vnknoj?insertDefaults=false"
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.438426334Z" level=debug msg="Calling GET /v1.41/nodes/jkgezfw4naz0ffuq33a7wekk1"
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.487097643Z" level=debug msg="state for task lavfckhhvy22l0mnkebbkcr3p updated to READY" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="PREPARING->READY" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.487247030Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="PREPARING->READY" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:26 test dockerd[6605]: time="2021-06-06T12:37:26.489107939Z" level=debug msg="Task lavfckhhvy22l0mnkebbkcr3p is already in allocated state READY" method="(*Allocator).doTaskAlloc" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:30 test dockerd[6605]: time="2021-06-06T12:37:30.493071876Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:37:30 test dockerd[6605]: time="2021-06-06T12:37:30.493582205Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.857522721s" method="(*Dispatcher).Heartbeat"
Jun  6 12:37:30 test dockerd[6605]: time="2021-06-06T12:37:30.493842706Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.857522721s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:37:30 test dockerd[6605]: time="2021-06-06T12:37:30.904566382Z" level=debug msg="Task lavfckhhvy22l0mnkebbkcr3p is already in allocated state READY" method="(*Allocator).doTaskAlloc" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.005026024Z" level=debug msg="(*worker).Update" len(assignments)=1 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.005065384Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.005078208Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.005087630Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=1 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.005105049Z" level=debug msg=assigned module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.desiredstate=RUNNING task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.005867692Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj state.desired=RUNNING state.transition="READY->STARTING" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.009543596Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.010061199Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.014653142Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/51638de218f81920cb926885887ca0fcebfc5d3e801790cd00e6474aa1e3de04/merged 0x560f4fe10440 0x560f4fe10440}" container=15f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.015135177Z" level=debug msg="Assigning addresses for endpoint test_test.1.lavfckhhvy22l0mnkebbkcr3p's interface on network test_default"
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.015249621Z" level=debug msg="RequestAddress(LocalDefault/10.0.1.0/24, 10.0.1.5, map[])"
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.015352022Z" level=debug msg="Request address PoolID:10.0.1.0/24 App: ipam/default/data, ID: LocalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 252, Sequence: (0xc8000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:0 Serial:false PrefAddress:10.0.1.5 "
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.018228312Z" level=debug msg="Assigning addresses for endpoint test_test.1.lavfckhhvy22l0mnkebbkcr3p's interface on network test_default"
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.097654191Z" level=debug msg="state for task lavfckhhvy22l0mnkebbkcr3p updated to STARTING" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="READY->STARTING" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.097785672Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="READY->STARTING" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.098294262Z" level=debug msg="checkEncryption(j2k7afr, <nil>, 4097, true)"
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.099087751Z" level=debug msg="Assigning addresses for endpoint gateway_0f4bc2ede937's interface on network docker_gwbridge"
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.099115105Z" level=debug msg="RequestAddress(LocalDefault/172.25.0.0/24, <nil>, map[])"
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.099136521Z" level=debug msg="Request address PoolID:172.25.0.0/24 App: ipam/default/data, ID: LocalDefault/172.25.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 252, Sequence: (0xe0000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:4 Serial:false PrefAddress:<nil> "
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.100488620Z" level=debug msg="Task lavfckhhvy22l0mnkebbkcr3p is already in allocated state STARTING" method="(*Allocator).doTaskAlloc" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.106258772Z" level=debug msg="Assigning addresses for endpoint gateway_0f4bc2ede937's interface on network docker_gwbridge"
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.112453072Z" level=debug msg="Programming external connectivity on endpoint gateway_0f4bc2ede937 (313d91f2d0c25b96ffd4500af74d413cb321f8816828a12d666d81a28bc1255d)"
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.120880757Z" level=debug msg="injecting secret" name=TEST_SECRET path=/var/lib/docker/containers/15f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a/mounts/secrets/er7pay1q0xyuycub7pm6ymzby
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.121219330Z" level=debug msg="bundle dir created" bundle=/var/run/docker/containerd/15f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a module=libcontainerd namespace=moby root=/var/lib/docker/overlay2/51638de218f81920cb926885887ca0fcebfc5d3e801790cd00e6474aa1e3de04/merged
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.179352679Z" level=debug msg="Calling HEAD /_ping"
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.180152863Z" level=debug msg="Calling GET /v1.41/info"
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.198490513Z" level=debug msg="Calling HEAD /_ping"
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.199008812Z" level=debug msg="Calling GET /v1.41/info"
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.204645863Z" level=debug msg="Calling GET /v1.41/containers/15f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a/json"
Jun  6 12:37:31 test dockerd[6605]: time="2021-06-06T12:37:31.219060608Z" level=debug msg="Calling GET /v1.41/containers/json?all=1&filters=%7B%22id%22%3A%7B%2215f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a%22%3Atrue%7D%7D&limit=0"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.190350609Z" level=debug msg="Calling HEAD /_ping"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.190701221Z" level=debug msg="Calling GET /v1.41/info"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.218476813Z" level=debug msg="Calling GET /v1.41/containers/json?all=1&filters=%7B%22id%22%3A%7B%2215f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a%22%3Atrue%7D%7D&limit=0"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.229807887Z" level=error msg="stream copy error: reading from a closed fifo"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.229925435Z" level=error msg="stream copy error: reading from a closed fifo"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.244406615Z" level=debug msg="deleteServiceInfoFromCluster from sbLeave START for test_test 7b655466fbbbb7085d883e39421968fccaeec9076417a7618c4e5d7e291ec52d"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.244448102Z" level=warning msg="deleteServiceInfoFromCluster NetworkDB DeleteEntry failed for 7b655466fbbbb7085d883e39421968fccaeec9076417a7618c4e5d7e291ec52d j2k7afr70xi1rnxj9enqhvajh err:cannot delete entry endpoint_table with network id j2k7afr70xi1rnxj9enqhvajh and key 7b655466fbbbb7085d883e39421968fccaeec9076417a7618c4e5d7e291ec52d does not exist or is already being deleted"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.244512026Z" level=warning msg="rmServiceBinding deleteServiceInfoFromCluster test_test 7b655466fbbbb7085d883e39421968fccaeec9076417a7618c4e5d7e291ec52d aborted c.serviceBindings[skey] !ok"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.244522952Z" level=debug msg="deleteServiceInfoFromCluster from sbLeave END for test_test 7b655466fbbbb7085d883e39421968fccaeec9076417a7618c4e5d7e291ec52d"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.244518703Z" level=debug msg="checkEncryption(j2k7afr, 10.0.0.180, 0, true)"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.244760971Z" level=debug msg="Revoking external connectivity on endpoint gateway_0f4bc2ede937 (313d91f2d0c25b96ffd4500af74d413cb321f8816828a12d666d81a28bc1255d)"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.251919534Z" level=debug msg="DeleteConntrackEntries purged ipv4:0, ipv6:0"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.260989749Z" level=debug msg="Calling HEAD /_ping"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.261589854Z" level=debug msg="Calling GET /v1.41/services?filters=%7B%22label%22%3A%7B%22com.docker.stack.namespace%22%3Atrue%7D%7D"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.312282955Z" level=debug msg="Releasing addresses for endpoint gateway_0f4bc2ede937's interface on network docker_gwbridge"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.312328321Z" level=debug msg="ReleaseAddress(LocalDefault/172.25.0.0/24, 172.25.0.3)"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.312370280Z" level=debug msg="Released address PoolID:LocalDefault/172.25.0.0/24, Address:172.25.0.3 Sequence:App: ipam/default/data, ID: LocalDefault/172.25.0.0/24, DBIndex: 0x0, Bits: 256, Unselected: 251, Sequence: (0xf0000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:4"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.361935772Z" level=debug msg="Releasing addresses for endpoint test_test.1.lavfckhhvy22l0mnkebbkcr3p's interface on network test_default"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.361988763Z" level=debug msg="ReleaseAddress(LocalDefault/10.0.1.0/24, 10.0.1.5)"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.362016420Z" level=debug msg="Released address PoolID:LocalDefault/10.0.1.0/24, Address:10.0.1.5 Sequence:App: ipam/default/data, ID: LocalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 251, Sequence: (0xcc000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:0"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.713703555Z" level=error msg="15f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a cleanup: failed to delete container from containerd: no such container"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.713775459Z" level=error msg="fatal task error" error="starting container failed: OCI runtime create failed: container_linux.go:392: starting container process caused: process_linux.go:592: container init caused: process_linux.go:563: handleReqOp caused: rootfs_init_linux.go:260: bind mounting /var/lib/docker/containers/15f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a/mounts/secrets/er7pay1q0xyuycub7pm6ymzby to run/secrets/TEST_SECRET caused: bind-mount of /var/lib/docker/containers/15f7f65a0152a9fba12a42871b6c622e23318867c10f32ca97e97911a82a6d1a/mounts/secrets/er7pay1q0xyuycub7pm6ymzby to run/secrets/TEST_SECRET failed: exit status 32: unknown" module=node/agent/taskmanager node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.714213290Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj state.desired=RUNNING state.transition="STARTING->FAILED" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.714424831Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.715282946Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.724333402Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.724937305Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.803427440Z" level=debug msg="state for task lavfckhhvy22l0mnkebbkcr3p updated to FAILED" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="STARTING->FAILED" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.803613357Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="STARTING->FAILED" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.805731642Z" level=debug msg="ReleaseAddress(GlobalDefault/10.0.1.0/24, 10.0.1.5)"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.805779336Z" level=debug msg="Released address PoolID:GlobalDefault/10.0.1.0/24, Address:10.0.1.5 Sequence:App: ipam/default/data, ID: GlobalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 250, Sequence: (0xe6000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:7"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.805872080Z" level=debug msg="ReleaseAddress(GlobalDefault/10.0.1.0/24, 10.0.1.6)"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.805886629Z" level=debug msg="Released address PoolID:GlobalDefault/10.0.1.0/24, Address:10.0.1.6 Sequence:App: ipam/default/data, ID: GlobalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 251, Sequence: (0xe2000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:7"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.812284602Z" level=debug msg="task frcoj7l6zbb6h1y9613eievvp was marked pending allocation" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.812346453Z" level=debug msg="RequestAddress(GlobalDefault/10.0.1.0/24, <nil>, map[com.docker.network.ipam.serial:true])"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.812375256Z" level=debug msg="Request address PoolID:10.0.1.0/24 App: ipam/default/data, ID: GlobalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 252, Sequence: (0xe0000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:7 Serial:true PrefAddress:<nil> "
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.812393767Z" level=debug msg="allocated task frcoj7l6zbb6h1y9613eievvp, state update PENDING" method="(*Allocator).allocateTask" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.812504134Z" level=debug msg="committed allocated task frcoj7l6zbb6h1y9613eievvp, state update {2021-06-06T12:37:32.812390746Z PENDING pending task scheduling  <nil> nil  (timestamp: nil Timestamp)}" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.812884515Z" level=info msg="initialized VXLAN UDP port to 4789 "
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.813719323Z" level=debug msg="Task frcoj7l6zbb6h1y9613eievvp is already in allocated state PENDING" method="(*Allocator).doTaskAlloc" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.863807843Z" level=debug msg="assigning to node jkgezfw4naz0ffuq33a7wekk1" module=node node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.868015685Z" level=debug msg="RequestAddress(GlobalDefault/10.0.1.0/24, <nil>, map[com.docker.network.ipam.serial:true])"
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.868058913Z" level=debug msg="Request address PoolID:10.0.1.0/24 App: ipam/default/data, ID: GlobalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 251, Sequence: (0xe1000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:8 Serial:true PrefAddress:<nil> "
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.869847976Z" level=debug msg="Task frcoj7l6zbb6h1y9613eievvp is already in allocated state ASSIGNED" method="(*Allocator).doTaskAlloc" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.870214513Z" level=info msg="initialized VXLAN UDP port to 4789 "
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.968470917Z" level=debug msg="(*worker).Update" len(assignments)=3 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.968515113Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=1 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.968534384Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.968545348Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=2 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.968574747Z" level=debug msg=assigned module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.desiredstate=SHUTDOWN task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.968622264Z" level=debug msg=assigned module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.desiredstate=READY task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.968704395Z" level=debug msg="state changed" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj state.desired=READY state.transition="ASSIGNED->ACCEPTED" task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.968879447Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.969134978Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj state.desired=READY state.transition="ASSIGNED->ACCEPTED" task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.974077147Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.974108949Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.974548779Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.976205043Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj state.desired=READY state.transition="ACCEPTED->PREPARING" task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.976240548Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.976651761Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.979800599Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:32 test dockerd[6605]: time="2021-06-06T12:37:32.980230355Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.010860705Z" level=debug msg="state for task frcoj7l6zbb6h1y9613eievvp updated to PREPARING" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="ASSIGNED->PREPARING" task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.010993131Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="ASSIGNED->PREPARING" task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.011033292Z" level=debug msg="state for task lavfckhhvy22l0mnkebbkcr3p updated to FAILED" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="FAILED->FAILED" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.011090896Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="FAILED->FAILED" task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.045282834Z" level=debug msg="Calling HEAD /_ping"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.046091276Z" level=debug msg="Calling GET /v1.41/services?filters=%7B%22label%22%3A%7B%22com.docker.stack.namespace%3Dtest%22%3Atrue%7D%7D"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.047797139Z" level=debug msg="Calling GET /v1.41/networks?filters=%7B%22label%22%3A%7B%22com.docker.stack.namespace%3Dtest%22%3Atrue%7D%7D"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.048857528Z" level=debug msg="Calling GET /v1.41/secrets?filters=%7B%22label%22%3A%7B%22com.docker.stack.namespace%3Dtest%22%3Atrue%7D%7D"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.049342056Z" level=debug msg="Calling GET /v1.41/configs?filters=%7B%22label%22%3A%7B%22com.docker.stack.namespace%3Dtest%22%3Atrue%7D%7D"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.050210270Z" level=debug msg="Calling DELETE /v1.41/services/ayxr14m1x66tg5nqkx6vnknoj"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.092453310Z" level=debug msg="Task frcoj7l6zbb6h1y9613eievvp is already in allocated state PREPARING" method="(*Allocator).doTaskAlloc" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.130927326Z" level=debug msg="ReleaseAddress(GlobalDefault/10.0.1.0/24, 10.0.1.2)"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.130984799Z" level=debug msg="Released address PoolID:GlobalDefault/10.0.1.0/24, Address:10.0.1.2 Sequence:App: ipam/default/data, ID: GlobalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 250, Sequence: (0xe1800000, 1)->(0x0, 6)->(0x1, 1)->end Curr:9"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.131752762Z" level=debug msg="Calling DELETE /v1.41/networks/j2k7afr70xi1rnxj9enqhvajh"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.139414795Z" level=debug msg="Task frcoj7l6zbb6h1y9613eievvp is already in allocated state PREPARING" method="(*Allocator).doTaskAlloc" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.142164871Z" level=debug msg="ReleaseAddress(GlobalDefault/10.0.1.0/24, 10.0.1.8)"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.142203670Z" level=debug msg="Released address PoolID:GlobalDefault/10.0.1.0/24, Address:10.0.1.8 Sequence:App: ipam/default/data, ID: GlobalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 251, Sequence: (0xc1800000, 1)->(0x0, 6)->(0x1, 1)->end Curr:9"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.148452438Z" level=debug msg="ReleaseAddress(GlobalDefault/10.0.1.0/24, 10.0.1.1)"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.148492210Z" level=debug msg="Released address PoolID:GlobalDefault/10.0.1.0/24, Address:10.0.1.1 Sequence:App: ipam/default/data, ID: GlobalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 252, Sequence: (0xc1000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:9"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.148503669Z" level=debug msg="ReleasePool(GlobalDefault/10.0.1.0/24)"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.148588368Z" level=error msg="Failed to allocate network resources for node jkgezfw4naz0ffuq33a7wekk1" error="could not find network allocator state for network j2k7afr70xi1rnxj9enqhvajh" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.149134241Z" level=info msg="initialized VXLAN UDP port to 4789 "
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.151211202Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/1f8ee305dbe18f9e7fa39acbfa3a1c1f44a3b0dbb04744f34f8fa1a54d1e9375/merged 0x560f4fe10440 0x560f4fe10440}" container=9f66ff3374357e2beabed754209e588484bc49bb9202078fcb791528c17284e5
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.240045012Z" level=debug msg="(*worker).Update" len(assignments)=3 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.240135958Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.240152200Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.240163174Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=3 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.240181934Z" level=debug msg=assigned module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.desiredstate=REMOVE task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.240247918Z" level=debug msg=assigned module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.desiredstate=REMOVE task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.240276814Z" level=debug msg=assigned module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.desiredstate=REMOVE task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.358312055Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.358352252Z" level=error msg="Failed to allocate network resources for node jkgezfw4naz0ffuq33a7wekk1" error="could not find network allocator state for network j2k7afr70xi1rnxj9enqhvajh" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.358420285Z" level=error msg="Failed to allocate network resources for node jkgezfw4naz0ffuq33a7wekk1" error="could not find network allocator state for network j2k7afr70xi1rnxj9enqhvajh" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.358723506Z" level=debug msg="cannot find target task in store" method="(*Dispatcher).UpdateTaskStatus" node.id=jkgezfw4naz0ffuq33a7wekk1 node.session=uy233vcekub0ln1omabs8hcat task.id=lavfckhhvy22l0mnkebbkcr3p
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.358877024Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.393069502Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.393488834Z" level=debug msg="cannot find target task in store" method="(*Dispatcher).UpdateTaskStatus" node.id=jkgezfw4naz0ffuq33a7wekk1 node.session=uy233vcekub0ln1omabs8hcat task.id=60wqekewd2bvqj30fkxtynd4b
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.393657157Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.412314685Z" level=debug msg="Creating service config in agent for t = &Task{ID:frcoj7l6zbb6h1y9613eievvp,Meta:Meta{Version:Version{Index:110,},CreatedAt:2021-06-06T12:37:32.806104995Z,UpdatedAt:2021-06-06T12:37:32.863983328Z,},Spec:TaskSpec{Runtime:&TaskSpec_Container{Container:&ContainerSpec{Image:alpine:latest@sha256:69e70a79f2d41ab5d637de98c1e0b055206ba40a8145e7bddb55ccc04e13cf8f,Labels:map[string]string{com.docker.stack.namespace: test,},Command:[],Args:[],Env:[],Dir:,User:,Mounts:[],StopGracePeriod:(duration: nil types.Duration),PullOptions:nil,Groups:[],Secrets:[&SecretReference{SecretID:er7pay1q0xyuycub7pm6ymzby,SecretName:TEST_SECRET,Target:&SecretReference_File{File:&FileTarget{Name:TEST_SECRET,UID:0,GID:0,Mode:-r--r--r--,},},}],TTY:false,Hostname:,DNSConfig:nil,Healthcheck:nil,Hosts:[],OpenStdin:false,ReadOnly:false,StopSignal:,Configs:[],Privileges:&Privileges{CredentialSpec:nil,SELinuxContext:nil,},Init:nil,Isolation:ISOLATION_DEFAULT,PidsLimit:0,Sysctls:map[string]string{},CapabilityAdd:[],CapabilityDrop:[],Ulimits:[],},},Resources:&ResourceRequirements{Limits:nil,Reservations:nil,SwapBytes:nil,MemorySwappiness:nil,},Restart:nil,Placement:&Placement{Constraints:[],Preferences:[],Platforms:[&Platform{Architecture:amd64,OS:linux,} &Platform{Architecture:,OS:linux,} &Platform{Architecture:,OS:linux,} &Platform{Architecture:arm64,OS:linux,} &Platform{Architecture:386,OS:linux,} &Platform{Architecture:ppc64le,OS:linux,} &Platform{Architecture:s390x,OS:linux,}],MaxReplicas:0,},LogDriver:nil,Networks:[&NetworkAttachmentConfig{Target:j2k7afr70xi1rnxj9enqhvajh,Aliases:[test],Addresses:[],DriverAttachmentOpts:map[string]string{},}],ForceUpdate:0,ResourceReferences:[],},ServiceID:ayxr14m1x66tg5nqkx6vnknoj,Slot:1,NodeID:jkgezfw4naz0ffuq33a7wekk1,Annotations:Annotations{Name:,Labels:map[string]string{},Indices:[],},ServiceAnnotations:Annotations{Name:test_test,Labels:map[string]string{com.docker.stack.image: alpine:latest,com.docker.stack.namespace: test,},Indices:[],},Status:TaskStatus{Timestamp:2021-06-06T12:37:32.86389946Z,State:ASSIGNED,Message:scheduler assigned task to node,Err:,RuntimeStatus:<nil>,PortStatus:nil,AppliedBy:,AppliedAt:(timestamp: nil types.Timestamp),},DesiredState:READY,Networks:[&NetworkAttachment{Network:&Network{ID:j2k7afr70xi1rnxj9enqhvajh,Meta:Meta{Version:Version{Index:87,},CreatedAt:2021-06-06T12:37:21.018704424Z,UpdatedAt:2021-06-06T12:37:21.020832036Z,},Spec:NetworkSpec{Annotations:Annotations{Name:test_default,Labels:map[string]string{com.docker.stack.namespace: test,},Indices:[],},DriverConfig:&Driver{Name:overlay,Options:map[string]string{},},Ipv6Enabled:false,Internal:false,IPAM:nil,Attachable:false,Ingress:false,ConfigFrom:<nil>,},DriverState:&Driver{Name:overlay,Options:map[string]string{com.docker.network.driver.overlay.vxlanid_list: 4097,},},IPAM:&IPAMOptions{Driver:&Driver{Name:default,Options:map[string]string{},},Configs:[&IPAMConfig{Family:IPV4,Subnet:10.0.1.0/24,Range:,Gateway:10.0.1.1,Reserved:map[string]string{},}],},PendingDelete:false,},Addresses:[10.0.1.7/24],Aliases:[test],DriverAttachmentOpts:map[string]string{},}],Endpoint:&Endpoint{Spec:&EndpointSpec{Mode:VIP,Ports:[],},Ports:[],VirtualIPs:[&Endpoint_VirtualIP{NetworkID:j2k7afr70xi1rnxj9enqhvajh,Addr:10.0.1.2/24,}],},LogDriver:nil,SpecVersion:&Version{Index:0,},AssignedGenericResources:[],JobIteration:nil,}"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.412432832Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj state.desired=READY state.transition="PREPARING->READY" task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.412730982Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.413240583Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.418439692Z" level=debug msg="Could not find network sandbox for container test_test.1.frcoj7l6zbb6h1y9613eievvp on service binding deactivation request"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.458859817Z" level=debug msg="(*worker).Update" len(assignments)=2 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.458897475Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.458910509Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.458920967Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=2 len(updatedTasks)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.459138733Z" level=debug msg="Could not find network sandbox for container test_test.1.60wqekewd2bvqj30fkxtynd4b on service binding deactivation request"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.459194458Z" level=debug msg="Could not find network sandbox for container test_test.1.lavfckhhvy22l0mnkebbkcr3p on service binding deactivation request"
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.492875567Z" level=debug msg="state for task frcoj7l6zbb6h1y9613eievvp updated to READY" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="PREPARING->READY" task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.493008892Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="PREPARING->READY" task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.497097630Z" level=error msg="Failed to allocate network resources for node jkgezfw4naz0ffuq33a7wekk1" error="could not find network allocator state for network j2k7afr70xi1rnxj9enqhvajh" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:33 test dockerd[6605]: time="2021-06-06T12:37:33.497133893Z" level=debug msg="Task frcoj7l6zbb6h1y9613eievvp is already in allocated state READY" method="(*Allocator).doTaskAlloc" module=node node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.351585632Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.352533435Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.967293308s" method="(*Dispatcher).Heartbeat"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.352773151Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.967293308s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.418974113Z" level=debug msg="DisableService lb-test_default START"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.419060708Z" level=debug msg="DisableService lb-test_default DONE"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.610080811Z" level=debug msg="Remove interface veth79539e6 failed: Link not found"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.610316406Z" level=debug msg="Remove interface veth5e5638a failed: Link not found"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.690343170Z" level=warning msg="Error (Unable to complete atomic operation, key modified) deleting object [endpoint j2k7afr70xi1rnxj9enqhvajh 510e74c462c019b73eae28ac8de0335bcbcdfecf75e7484aae79e8a1a348d483], retrying...."
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.729958910Z" level=debug msg="Releasing addresses for endpoint test_default-endpoint's interface on network test_default"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.730183509Z" level=debug msg="ReleaseAddress(LocalDefault/10.0.1.0/24, 10.0.1.4)"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.730305157Z" level=debug msg="Released address PoolID:LocalDefault/10.0.1.0/24, Address:10.0.1.4 Sequence:App: ipam/default/data, ID: LocalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 252, Sequence: (0xc8000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:0"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.734025685Z" level=debug msg="releasing IPv4 pools from network test_default (j2k7afr70xi1rnxj9enqhvajh)"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.734156746Z" level=debug msg="ReleaseAddress(LocalDefault/10.0.1.0/24, 10.0.1.1)"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.734243939Z" level=debug msg="Released address PoolID:LocalDefault/10.0.1.0/24, Address:10.0.1.1 Sequence:App: ipam/default/data, ID: LocalDefault/10.0.1.0/24, DBIndex: 0x0, Bits: 256, Unselected: 253, Sequence: (0xc0000000, 1)->(0x0, 6)->(0x1, 1)->end Curr:0"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.734326569Z" level=debug msg="ReleasePool(LocalDefault/10.0.1.0/24)"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.734520131Z" level=debug msg="test(63c1ed8c7f77): leaving network j2k7afr70xi1rnxj9enqhvajh"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.734622316Z" level=debug msg="cleanupServiceDiscovery for network:j2k7afr70xi1rnxj9enqhvajh"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.734694758Z" level=debug msg="cleanupServiceBindings for j2k7afr70xi1rnxj9enqhvajh"
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.735030006Z" level=error msg="network test_default remove failed: error while removing network: unknown network test_default id j2k7afr70xi1rnxj9enqhvajh" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.735146148Z" level=debug msg="shutdown failed on removal" error="error while removing network: unknown network test_default id j2k7afr70xi1rnxj9enqhvajh" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.735266562Z" level=error msg="network test_default remove failed: error while removing network: unknown network test_default id j2k7afr70xi1rnxj9enqhvajh" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.735297444Z" level=debug msg="shutdown failed on removal" error="error while removing network: unknown network test_default id j2k7afr70xi1rnxj9enqhvajh" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.735918319Z" level=debug msg="state changed" module=node/agent/taskmanager node.id=jkgezfw4naz0ffuq33a7wekk1 service.id=ayxr14m1x66tg5nqkx6vnknoj state.desired=REMOVE state.transition="READY->SHUTDOWN" task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.736143463Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.736705746Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.742834336Z" level=debug msg="(*Agent).UpdateTaskStatus" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.743162629Z" level=debug msg="task status reported" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.801666818Z" level=debug msg="state for task frcoj7l6zbb6h1y9613eievvp updated to SHUTDOWN" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="READY->SHUTDOWN" task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.801948679Z" level=debug msg="dispatcher committed status update to store" method="(*Dispatcher).processUpdates" module=dispatcher node.id=jkgezfw4naz0ffuq33a7wekk1 state.transition="READY->SHUTDOWN" task.id=frcoj7l6zbb6h1y9613eievvp
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.904534650Z" level=debug msg="(*worker).Update" len(assignments)=1 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.904583193Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=1 len(updatedSecrets)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.904597716Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:35 test dockerd[6605]: time="2021-06-06T12:37:35.904608093Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:36 test dockerd[6605]: time="2021-06-06T12:37:36.156809053Z" level=debug msg="(*worker).Update" len(assignments)=2 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:36 test dockerd[6605]: time="2021-06-06T12:37:36.156852139Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=1 len(updatedSecrets)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:36 test dockerd[6605]: time="2021-06-06T12:37:36.156864643Z" level=debug msg="(*worker).reconcileConfigs" len(removedConfigs)=0 len(updatedConfigs)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:36 test dockerd[6605]: time="2021-06-06T12:37:36.156875037Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=1 len(updatedTasks)=0 module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1
Jun  6 12:37:36 test dockerd[6605]: time="2021-06-06T12:37:36.157068104Z" level=debug msg="Could not find network sandbox for container test_test.1.frcoj7l6zbb6h1y9613eievvp on service binding deactivation request"
Jun  6 12:37:40 test dockerd[6605]: time="2021-06-06T12:37:40.320340736Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:37:40 test dockerd[6605]: time="2021-06-06T12:37:40.320807695Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.500776904s" method="(*Dispatcher).Heartbeat"
Jun  6 12:37:40 test dockerd[6605]: time="2021-06-06T12:37:40.320995223Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.500776904s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:37:44 test dockerd[6605]: time="2021-06-06T12:37:44.822119389Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:37:44 test dockerd[6605]: time="2021-06-06T12:37:44.823608128Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.987729524s" method="(*Dispatcher).Heartbeat"
Jun  6 12:37:44 test dockerd[6605]: time="2021-06-06T12:37:44.823832496Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.987729524s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:37:49 test dockerd[6605]: time="2021-06-06T12:37:49.811816095Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:37:49 test dockerd[6605]: time="2021-06-06T12:37:49.812277897Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 5.398450155s" method="(*Dispatcher).Heartbeat"
Jun  6 12:37:49 test dockerd[6605]: time="2021-06-06T12:37:49.812469109Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 5.398450155s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:37:55 test dockerd[6605]: time="2021-06-06T12:37:55.211229351Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:37:55 test dockerd[6605]: time="2021-06-06T12:37:55.211954239Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 5.02561796s" method="(*Dispatcher).Heartbeat"
Jun  6 12:37:55 test dockerd[6605]: time="2021-06-06T12:37:55.212218989Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 5.02561796s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:00 test dockerd[6605]: time="2021-06-06T12:38:00.238038950Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:00 test dockerd[6605]: time="2021-06-06T12:38:00.238569010Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.754590882s" method="(*Dispatcher).Heartbeat"
Jun  6 12:38:00 test dockerd[6605]: time="2021-06-06T12:38:00.238836682Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.754590882s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:04 test dockerd[6605]: time="2021-06-06T12:38:04.993874280Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:04 test dockerd[6605]: time="2021-06-06T12:38:04.994361288Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 5.279596722s" method="(*Dispatcher).Heartbeat"
Jun  6 12:38:04 test dockerd[6605]: time="2021-06-06T12:38:04.994567341Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 5.279596722s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:10 test dockerd[6605]: time="2021-06-06T12:38:10.274433151Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:10 test dockerd[6605]: time="2021-06-06T12:38:10.274941617Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.541509603s" method="(*Dispatcher).Heartbeat"
Jun  6 12:38:10 test dockerd[6605]: time="2021-06-06T12:38:10.275058041Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.541509603s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:14 test dockerd[6605]: time="2021-06-06T12:38:14.816748860Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:14 test dockerd[6605]: time="2021-06-06T12:38:14.817182333Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 5.120626411s" method="(*Dispatcher).Heartbeat"
Jun  6 12:38:14 test dockerd[6605]: time="2021-06-06T12:38:14.817296924Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 5.120626411s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:19 test dockerd[6605]: time="2021-06-06T12:38:19.938333779Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:19 test dockerd[6605]: time="2021-06-06T12:38:19.939395542Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.784953764s" method="(*Dispatcher).Heartbeat"
Jun  6 12:38:19 test dockerd[6605]: time="2021-06-06T12:38:19.939619953Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.784953764s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:24 test dockerd[6605]: time="2021-06-06T12:38:24.724779438Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:24 test dockerd[6605]: time="2021-06-06T12:38:24.725490922Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 5.274490642s" method="(*Dispatcher).Heartbeat"
Jun  6 12:38:24 test dockerd[6605]: time="2021-06-06T12:38:24.725741127Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 5.274490642s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:30 test dockerd[6605]: time="2021-06-06T12:38:30.000564538Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:30 test dockerd[6605]: time="2021-06-06T12:38:30.001013242Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.604570972s" method="(*Dispatcher).Heartbeat"
Jun  6 12:38:30 test dockerd[6605]: time="2021-06-06T12:38:30.001232345Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.604570972s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:34 test dockerd[6605]: time="2021-06-06T12:38:34.606073877Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:34 test dockerd[6605]: time="2021-06-06T12:38:34.606477281Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.848092788s" method="(*Dispatcher).Heartbeat"
Jun  6 12:38:34 test dockerd[6605]: time="2021-06-06T12:38:34.606606997Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.848092788s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:39 test dockerd[6605]: time="2021-06-06T12:38:39.454962999Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:39 test dockerd[6605]: time="2021-06-06T12:38:39.455677232Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 5.215996066s" method="(*Dispatcher).Heartbeat"
Jun  6 12:38:39 test dockerd[6605]: time="2021-06-06T12:38:39.455789545Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 5.215996066s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:44 test dockerd[6605]: time="2021-06-06T12:38:44.672056216Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:44 test dockerd[6605]: time="2021-06-06T12:38:44.672499826Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 5.027341712s" method="(*Dispatcher).Heartbeat"
Jun  6 12:38:44 test dockerd[6605]: time="2021-06-06T12:38:44.672635365Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 5.027341712s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:49 test dockerd[6605]: time="2021-06-06T12:38:49.700194055Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:49 test dockerd[6605]: time="2021-06-06T12:38:49.700657237Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 5.482129907s" method="(*Dispatcher).Heartbeat"
Jun  6 12:38:49 test dockerd[6605]: time="2021-06-06T12:38:49.700874716Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 5.482129907s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:55 test dockerd[6605]: time="2021-06-06T12:38:55.183297702Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:55 test dockerd[6605]: time="2021-06-06T12:38:55.183819233Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.752122177s" method="(*Dispatcher).Heartbeat"
Jun  6 12:38:55 test dockerd[6605]: time="2021-06-06T12:38:55.184187563Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.752122177s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:59 test dockerd[6605]: time="2021-06-06T12:38:59.936560095Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:38:59 test dockerd[6605]: time="2021-06-06T12:38:59.937005426Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.547564927s" method="(*Dispatcher).Heartbeat"
Jun  6 12:38:59 test dockerd[6605]: time="2021-06-06T12:38:59.937133626Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.547564927s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:39:04 test dockerd[6605]: time="2021-06-06T12:39:04.484938338Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:39:04 test dockerd[6605]: time="2021-06-06T12:39:04.485475536Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.505018528s" method="(*Dispatcher).Heartbeat"
Jun  6 12:39:04 test dockerd[6605]: time="2021-06-06T12:39:04.485672237Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.505018528s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:39:08 test dockerd[6605]: time="2021-06-06T12:39:08.991115384Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:39:08 test dockerd[6605]: time="2021-06-06T12:39:08.991642282Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.973947445s" method="(*Dispatcher).Heartbeat"
Jun  6 12:39:08 test dockerd[6605]: time="2021-06-06T12:39:08.991820101Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.973947445s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:39:13 test dockerd[6605]: time="2021-06-06T12:39:13.966031473Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:39:13 test dockerd[6605]: time="2021-06-06T12:39:13.966540295Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.782935185s" method="(*Dispatcher).Heartbeat"
Jun  6 12:39:13 test dockerd[6605]: time="2021-06-06T12:39:13.966661667Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.782935185s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:39:18 test dockerd[6605]: time="2021-06-06T12:39:18.749823175Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:39:18 test dockerd[6605]: time="2021-06-06T12:39:18.750277091Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.734025284s" method="(*Dispatcher).Heartbeat"
Jun  6 12:39:18 test dockerd[6605]: time="2021-06-06T12:39:18.750598158Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.734025284s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:39:23 test dockerd[6605]: time="2021-06-06T12:39:23.484913565Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:39:23 test dockerd[6605]: time="2021-06-06T12:39:23.485392418Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.584243237s" method="(*Dispatcher).Heartbeat"
Jun  6 12:39:23 test dockerd[6605]: time="2021-06-06T12:39:23.485718430Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.584243237s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:39:28 test dockerd[6605]: time="2021-06-06T12:39:28.070347048Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:39:28 test dockerd[6605]: time="2021-06-06T12:39:28.070867378Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.558223817s" method="(*Dispatcher).Heartbeat"
Jun  6 12:39:28 test dockerd[6605]: time="2021-06-06T12:39:28.071251036Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.558223817s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:39:32 test dockerd[6605]: time="2021-06-06T12:39:32.629788488Z" level=debug msg="sending heartbeat to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377} with timeout 5s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
Jun  6 12:39:32 test dockerd[6605]: time="2021-06-06T12:39:32.630353201Z" level=debug msg="received heartbeat from worker {[swarm-manager] rpszcdn919k6utwuhde5ybjzf jkgezfw4naz0ffuq33a7wekk1 <nil> 10.0.0.180:49508}, expect next heartbeat in 4.943584769s" method="(*Dispatcher).Heartbeat"
Jun  6 12:39:32 test dockerd[6605]: time="2021-06-06T12:39:32.630582258Z" level=debug msg="heartbeat successful to manager {jkgezfw4naz0ffuq33a7wekk1 10.0.0.180:2377}, next heartbeat period: 4.943584769s" method="(*session).heartbeat" module=node/agent node.id=jkgezfw4naz0ffuq33a7wekk1 session.id=uy233vcekub0ln1omabs8hcat sessionID=uy233vcekub0ln1omabs8hcat
root@test:~# docker node ps --no-trunc
ID                          NAME              IMAGE                                                                                   NODE      DESIRED STATE   CURRENT STATE                   ERROR

                                                                                                                          PORTS
nymcysce4evbu7p68n5j4wpsx   test_test.1       alpine:latest@sha256:69e70a79f2d41ab5d637de98c1e0b055206ba40a8145e7bddb55ccc04e13cf8f   test      Ready           Ready less than a second ago

slb36ggjsz77o2qdzt7pt5qbb    \_ test_test.1   alpine:latest@sha256:69e70a79f2d41ab5d637de98c1e0b055206ba40a8145e7bddb55ccc04e13cf8f   test      Shutdown        Failed less than a second ago   "starting container failed: OCI runtime create failed: container_linux.go:392: starting container process caused: process_linux.go:592: container init caused: process_linux.go:563: handleReqOp caused: rootfs_init_linux.go:260: bind mounting /var/lib/docker/containers/fc7e3fdf81938b665e03c1d3e91c7a8cde3f8cde4bc26f2cab28a51d662028b7/mounts/secrets/er7pay1q0xyuycub7pm6ymzby to run/secrets/TEST_SECRET caused: bind-mount of /var/lib/docker/containers/fc7e3fdf81938b665e03c1d3e91c7a8cde3f8cde4bc26f2cab28a51d662028b7/mounts/secrets/er7pay1q0xyuycub7pm6ymzby to run/secrets/TEST_SECRET failed: exit status 32: unknown"
repqwewz1daettee5337tkpmg    \_ test_test.1   alpine:latest@sha256:69e70a79f2d41ab5d637de98c1e0b055206ba40a8145e7bddb55ccc04e13cf8f   test      Shutdown        Failed 7 seconds ago            "starting container failed: OCI runtime create failed: container_linux.go:392: starting container process caused: process_linux.go:592: container init caused: process_linux.go:563: handleReqOp caused: rootfs_init_linux.go:260: bind mounting /var/lib/docker/containers/34f7711ed818a1dd848945f8b52fed6f1fbbb1a307a8959fbdcba90b0a037a0f/mounts/secrets/er7pay1q0xyuycub7pm6ymzby to run/secrets/TEST_SECRET caused: bind-mount of /var/lib/docker/containers/34f7711ed818a1dd848945f8b52fed6f1fbbb1a307a8959fbdcba90b0a037a0f/mounts/secrets/er7pay1q0xyuycub7pm6ymzby to run/secrets/TEST_SECRET failed: exit status 32: unknown"
v3dijk5zira0l5eo8mxykr76a    \_ test_test.1   alpine:latest@sha256:69e70a79f2d41ab5d637de98c1e0b055206ba40a8145e7bddb55ccc04e13cf8f   test      Shutdown        Failed 14 seconds ago           "starting container failed: OCI runtime create failed: container_linux.go:392: starting container process caused: process_linux.go:592: container init caused: process_linux.go:563: handleReqOp caused: rootfs_init_linux.go:260: bind mounting /var/lib/docker/containers/58f9ade7b0937d6ca1075d6c85f1db0877e3aa39f14502eae4598c0564283105/mounts/secrets/er7pay1q0xyuycub7pm6ymzby to run/secrets/TEST_SECRET caused: bind-mount of /var/lib/docker/containers/58f9ade7b0937d6ca1075d6c85f1db0877e3aa39f14502eae4598c0564283105/mounts/secrets/er7pay1q0xyuycub7pm6ymzby to run/secrets/TEST_SECRET failed: exit status 32: unknown"
25zdl7tjxhbysjir8nk646ri6    \_ test_test.1   alpine:latest@sha256:69e70a79f2d41ab5d637de98c1e0b055206ba40a8145e7bddb55ccc04e13cf8f   test      Shutdown        Failed 21 seconds ago           "starting container failed: OCI runtime create failed: container_linux.go:392: starting container process caused: process_linux.go:592: container init caused: process_linux.go:563: handleReqOp caused: rootfs_init_linux.go:260: bind mounting /var/lib/docker/containers/647ce1bf15276ba1fd9e1e20145bdd312bae18fb4a5e6cda73a72514dd45cb45/mounts/secrets/er7pay1q0xyuycub7pm6ymzby to run/secrets/TEST_SECRET caused: bind-mount of /var/lib/docker/containers/647ce1bf15276ba1fd9e1e20145bdd312bae18fb4a5e6cda73a72514dd45cb45/mounts/secrets/er7pay1q0xyuycub7pm6ymzby to run/secrets/TEST_SECRET failed: exit status 32: unknown"
ctalledo commented 3 years ago

Hi @d-mankowski-samsung , thanks for filing this issue and for all the info provided. Let me try to reproduce it and will get back to you a bit later today.

ctalledo commented 3 years ago

Hi @d-mankowski-samsung,

I was able to repro the problem with Sysbox v0.3.0 using the detailed steps you provided for the minimal (non-working) example. Thanks.

It seems Sysbox is hitting a problem when creating the container and mounting the secrets file to it:

 "starting container failed: OCI runtime create failed: container_linux.go:392: starting container process caused: process_linux.go:592: container init caused: process_linux.go:563: handleReqOp caused:                                                                                                                      
rootfs_init_linux.go:260: bind mounting /var/lib/docker/containers/144717a2a438c64bc49a23986b7849c522aade6618e91936594122cb4e5e281c/mounts/secrets/u7wh58bsppve3r48hcl4wclaw to run/secrets/TEST_SECRET caused:                                                                                                               
bind-mount of /var/lib/docker/containers/144717a2a438c64bc49a23986b7849c522aade6618e91936594122cb4e5e281c/mounts/secrets/u7wh58bsppve3r48hcl4wclaw to run/secrets/TEST_SECRET failed: exit status 32: unknown"

We recently did some fixes in the way Sysbox sets up container mounts, and I can confirm that with the top-of-tree Sysbox I no longer see the problem:

cat << EOF > docker-compose.yaml                                                                                                                                                                                                                                                                                              
version: "3.8"                                                                                                                                                                                                                                                                                                                

services:                                                                                                                                                                                                                                                                                                                     
  test:                                                                                                                                                                                                                                                                                                                       
    image: alpine:latest                                                                                                                                                                                                                                                                                                      
    command: 'tail -f /dev/null'                                                                                                                                                                                                                                                                                              
    deploy:                                                                                                                                                                                                                                                                                                                   
      mode: replicated                                                                                                                                                                                                                                                                                                        
      replicas: 1                                                                                                                                                                                                                                                                                                             
    secrets:                                                                                                                                                                                                                                                                                                                  
      - TEST_SECRET                                                                                                                                                                                                                                                                                                           

secrets:                                                                                                                                                                                                                                                                                                                      
  TEST_SECRET:                                                                                                                                                                                                                                                                                                                
    external: true                                                                                                                                                                                                                                                                                                            
EOF

$ docker stack deploy -c docker-compose.yaml test                                                                                                                                                                                                                              [72/6436]
Creating network test_default                                                                                                                                                                                                                                                                                                 
Creating service test_test

$ docker node ps --no-trunc
ID                          NAME          IMAGE                                                                                   NODE      DESIRED STATE   CURRENT STATE           ERROR     PORTS
p5ipw6lzrbk9kcz7t2y75trwd   test_test.1   alpine:latest@sha256:69e70a79f2d41ab5d637de98c1e0b055206ba40a8145e7bddb55ccc04e13cf8f   focal     Running         Running 4 minutes ago 

$ docker exec test_test.1.p5ipw6lzrbk9kcz7t2y75trwd cat /run/secrets/TEST_SECRET
test

Would you mind trying with the top-of-tree Sysbox? That requires building Sysbox from source, as described here). It's pretty easy as the build occurs entirely within a build container which carries all build dependencies.

Otherwise, the next release of Sysbox (scheduled in a couple of weeks) will carry the fix.

If you need this urgently, ping me via the Sysbox slack and I can provide further help.

d-mankowski-samsung commented 3 years ago

Thanks for your response, @ctalledo. I will try the top-of-tree version this week, maybe even tomorrow if I have some spare time. I've also encountered another issue while trying to mount directory from host to container, but before reporting another issue I will try to reproduce it on updated version of Sysbox first.

ctalledo commented 3 years ago

Thanks for your response, @ctalledo. I will try the top-of-tree version this week, maybe even tomorrow if I have some spare time. I've also encountered another issue while trying to mount directory from host to container, but before reporting another issue I will try to reproduce it on updated version of Sysbox first.

Sounds good, thanks. Let me know if you hit any issues please.

d-mankowski-samsung commented 3 years ago

@ctalledo I can confirm that mounting secrets in the top-of-tree version works fine. However, I've encountered problem with mounting directory from host (in both v0.3.0 and top-of-tree), so I will create another issue and close this one.