Skip to content

[v1.6.0-rc] Regression / change in behavior in exit code in containerd v1.6.0-rc.XX #6429

Closed
#6465
Closed
[v1.6.0-rc] Regression / change in behavior in exit code in containerd v1.6.0-rc.XX#6429
#6465
Labels
kind/bug
Milestone
1.6
@thaJeztah

Description

@thaJeztah
thaJeztah
opened on Jan 11, 2022

Description

Relates to moby/moby#42942 - we observed a regression / change in behavior in containerd v1.6.0

Steps to reproduce the issue

Preparations

To reproduce; first do a regular install of docker; I tried this on a Ubuntu 20.04 machine (but the issue reproduced running docker-in-docker on Docker Desktop as well);

curl -fsSL https://get.docker.com | sh

Stop the service, and enable debugging on the docker daemon (to get more details);

systemctl stop docker

mkdir -p /etc/docker/ && echo '{"debug":true}' > /etc/docker/daemon.json

systemctl start docker

Pull a busybox image;

docekr pull busybox

Behavior on containerd v1.4.12 (and v1.5.9)

Start a container with a faulty command that doesn't exist;

docker run --name error-values --init=false busybox toto
# docker: Error response from daemon: OCI runtime create failed: container_linux.go:380: starting container process caused: exec: "toto": executable file not found in $PATH: unknown.

Check the container's exit-code:

docker inspect -f '{{.State.ExitCode}}' error-values
127

Logs for dockerd and containerd

journalctl -n 50 --no-pager -xu docker.service
Details 
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.273867631Z" level=debug msg="Calling POST /v1.41/containers/create?name=error-values"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.274157114Z" level=debug msg="form data: {\"AttachStderr\":true,\"AttachStdin\":false,\"AttachStdout\":true,\"Cmd\":[\"toto\"],\"Domainname\":\"\",\"Entrypoint\":null,\"Env\":null,\"HostConfig\":{\"AutoRemove\":false,\"Binds\":null,\"BlkioDeviceReadBps\":null,\"BlkioDeviceReadIOps\":null,\"BlkioDeviceWriteBps\":null,\"BlkioDeviceWriteIOps\":null,\"BlkioWeight\":0,\"BlkioWeightDevice\":[],\"CapAdd\":null,\"CapDrop\":null,\"Cgroup\":\"\",\"CgroupParent\":\"\",\"CgroupnsMode\":\"\",\"ConsoleSize\":[0,0],\"ContainerIDFile\":\"\",\"CpuCount\":0,\"CpuPercent\":0,\"CpuPeriod\":0,\"CpuQuota\":0,\"CpuRealtimePeriod\":0,\"CpuRealtimeRuntime\":0,\"CpuShares\":0,\"CpusetCpus\":\"\",\"CpusetMems\":\"\",\"DeviceCgroupRules\":null,\"DeviceRequests\":null,\"Devices\":[],\"Dns\":[],\"DnsOptions\":[],\"DnsSearch\":[],\"ExtraHosts\":null,\"GroupAdd\":null,\"IOMaximumBandwidth\":0,\"IOMaximumIOps\":0,\"Init\":false,\"IpcMode\":\"\",\"Isolation\":\"\",\"KernelMemory\":0,\"KernelMemoryTCP\":0,\"Links\":null,\"LogConfig\":{\"Config\":{},\"Type\":\"\"},\"MaskedPaths\":null,\"Memory\":0,\"MemoryReservation\":0,\"MemorySwap\":0,\"MemorySwappiness\":-1,\"NanoCpus\":0,\"NetworkMode\":\"default\",\"OomKillDisable\":false,\"OomScoreAdj\":0,\"PidMode\":\"\",\"PidsLimit\":0,\"PortBindings\":{},\"Privileged\":false,\"PublishAllPorts\":false,\"ReadonlyPaths\":null,\"ReadonlyRootfs\":false,\"RestartPolicy\":{\"MaximumRetryCount\":0,\"Name\":\"no\"},\"SecurityOpt\":null,\"ShmSize\":0,\"UTSMode\":\"\",\"Ulimits\":null,\"UsernsMode\":\"\",\"VolumeDriver\":\"\",\"VolumesFrom\":null},\"Hostname\":\"\",\"Image\":\"busybox\",\"Labels\":{},\"NetworkingConfig\":{\"EndpointsConfig\":{}},\"OnBuild\":null,\"OpenStdin\":false,\"Platform\":null,\"StdinOnce\":false,\"Tty\":false,\"User\":\"\",\"Volumes\":{},\"WorkingDir\":\"\"}"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.305494679Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/2e361797833cbf24e5eea3a461e5c4a4d71fd7d500de0ea015b20aab0d5796b9/merged 0x557766d41fc0 0x557766d41fc0}" container=3fa72cf5766f4b2ff930a1275e79f7345444309e658fcc79d66af9d92a7e85c5
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.315690937Z" level=debug msg="Calling POST /v1.41/containers/3fa72cf5766f4b2ff930a1275e79f7345444309e658fcc79d66af9d92a7e85c5/attach?stderr=1&stdout=1&stream=1"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.316408815Z" level=debug msg="attach: stdout: begin"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.316654246Z" level=debug msg="attach: stderr: begin"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.317081894Z" level=debug msg="Calling POST /v1.41/containers/3fa72cf5766f4b2ff930a1275e79f7345444309e658fcc79d66af9d92a7e85c5/wait?condition=next-exit"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.317712286Z" level=debug msg="Calling POST /v1.41/containers/3fa72cf5766f4b2ff930a1275e79f7345444309e658fcc79d66af9d92a7e85c5/start"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.323475472Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/2e361797833cbf24e5eea3a461e5c4a4d71fd7d500de0ea015b20aab0d5796b9/merged 0x557766d41fc0 0x557766d41fc0}" container=3fa72cf5766f4b2ff930a1275e79f7345444309e658fcc79d66af9d92a7e85c5
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.324331674Z" level=debug msg="Assigning addresses for endpoint error-values's interface on network bridge"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.324545988Z" level=debug msg="RequestAddress(LocalDefault/172.17.0.0/16, <nil>, map[])"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.324720685Z" level=debug msg="Request address PoolID:172.17.0.0/16 App: ipam/default/data, ID: LocalDefault/172.17.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65533, Sequence: (0xc0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:0 Serial:false PrefAddress:<nil> "
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.356571232Z" level=debug msg="Assigning addresses for endpoint error-values's interface on network bridge"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.362347216Z" level=debug msg="Programming external connectivity on endpoint error-values (84abc7c57b8198f1d24593bbc1ed5c8fa852e65de11f99654fa7d2e0181d1b0b)"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.363771185Z" level=debug msg="EnableService 3fa72cf5766f4b2ff930a1275e79f7345444309e658fcc79d66af9d92a7e85c5 START"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.363990235Z" level=debug msg="EnableService 3fa72cf5766f4b2ff930a1275e79f7345444309e658fcc79d66af9d92a7e85c5 DONE"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.370103529Z" level=debug msg="bundle dir created" bundle=/var/run/docker/containerd/3fa72cf5766f4b2ff930a1275e79f7345444309e658fcc79d66af9d92a7e85c5 module=libcontainerd namespace=moby root=/var/lib/docker/overlay2/2e361797833cbf24e5eea3a461e5c4a4d71fd7d500de0ea015b20aab0d5796b9/merged
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.711527553Z" level=debug msg="sandbox set key processing took 116.679106ms for container 3fa72cf5766f4b2ff930a1275e79f7345444309e658fcc79d66af9d92a7e85c5"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.753162733Z" level=error msg="stream copy error: reading from a closed fifo"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.762742364Z" level=error msg="stream copy error: reading from a closed fifo"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.763235103Z" level=debug msg="attach: stdout: end"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.763416931Z" level=debug msg="attach: stderr: end"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.763579829Z" level=debug msg="attach done"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.793700584Z" level=debug msg="Revoking external connectivity on endpoint error-values (84abc7c57b8198f1d24593bbc1ed5c8fa852e65de11f99654fa7d2e0181d1b0b)"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.795500980Z" level=debug msg="DeleteConntrackEntries purged ipv4:0, ipv6:0"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.836064804Z" level=debug msg="Releasing addresses for endpoint error-values's interface on network bridge"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.836109948Z" level=debug msg="ReleaseAddress(LocalDefault/172.17.0.0/16, 172.17.0.2)"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.836152405Z" level=debug msg="Released address PoolID:LocalDefault/172.17.0.0/16, Address:172.17.0.2 Sequence:App: ipam/default/data, ID: LocalDefault/172.17.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65532, Sequence: (0xe0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[4423]: time="2022-01-11T13:10:48.850775540Z" level=error msg="3fa72cf5766f4b2ff930a1275e79f7345444309e658fcc79d66af9d92a7e85c5 cleanup: failed to delete container from containerd: no such container"

journalctl -n 50 --no-pager -xu containerd.service
Details 
Jan 11 12:07:00 ubuntu-s-1vcpu-2gb-ams3-01 containerd[2335]: time="2022-01-11T12:07:00.864205152Z" level=info msg="containerd successfully booted in 0.124683s"
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 containerd[2335]: time="2022-01-11T13:10:48.393034321Z" level=info msg="starting signal loop" namespace=moby path=/run/containerd/io.containerd.runtime.v2.task/moby/3fa72cf5766f4b2ff930a1275e79f7345444309e658fcc79d66af9d92a7e85c5 pid=4604
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 containerd[2335]: time="2022-01-11T13:10:48.751338783Z" level=info msg="shim disconnected" id=3fa72cf5766f4b2ff930a1275e79f7345444309e658fcc79d66af9d92a7e85c5
Jan 11 13:10:48 ubuntu-s-1vcpu-2gb-ams3-01 containerd[2335]: time="2022-01-11T13:10:48.757570360Z" level=error msg="copy shim log" error="read /proc/self/fd/12: file already closed"

Remove the container

docker rm error-values

Install containerd v1.6.0-rc.XX

Stop the docker and containerd services:

systemctl stop docker containerd

Download the latest v1.6.0-rc of containerd and install it (overwriting the existing containerd binaries)

curl -O -fsSL https://github.com/containerd/containerd/releases/download/v1.6.0-beta.5/containerd-1.6.0-beta.5-linux-amd64.tar.gz

tar -xvzf containerd-1.6.0-beta.5-linux-amd64.tar.gz

cp bin/containerd* /usr/bin/

Start the docker service and verify the new version is installed;

systemctl start docker

docker version
Details 
Client: Docker Engine - Community
 Version:           20.10.12
 API version:       1.41
 Go version:        go1.16.12
 Git commit:        e91ed57
 Built:             Mon Dec 13 11:45:33 2021
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.12
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.16.12
  Git commit:       459d0df
  Built:            Mon Dec 13 11:43:42 2021
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.6.0-beta.5
  GitCommit:        857b35de6c6d40962d24dc1e561e8446e9f3197f.m
 runc:
  Version:          1.0.2
  GitCommit:        v1.0.2-0-g52b36a2
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

Behavior on containerd v1.6.0

Repeat the steps;

Start a container with a faulty command that doesn't exist;

docker run --name error-values --init=false busybox toto
docker: Error response from daemon: failed to create shim task: OCI runtime create failed: container_linux.go:380: starting container process caused: exec: "toto": executable file not found in $PATH: unknown.

Check the container's exit-code:

docker inspect -f '{{.State.ExitCode}}' error-values
137

Notice that the exit code changed to 137

Also check that the 137 exit code is not due to the container being "OOM-killed" (which usually produces this exit code);

docker inspect -f '{{json .State}}' error-values | jq .
{
  "Status": "created",
  "Running": false,
  "Paused": false,
  "Restarting": false,
  "OOMKilled": false,
  "Dead": false,
  "Pid": 0,
  "ExitCode": 137,
  "Error": "failed to create shim task: OCI runtime create failed: container_linux.go:380: starting container process caused: exec: \"toto\": executable file not found in $PATH: unknown",
  "StartedAt": "0001-01-01T00:00:00Z",
  "FinishedAt": "2022-01-11T13:25:49.512697109Z"
}

docker and containerd logs:

journalctl -n 50 --no-pager -xu docker.service
Details 
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.891280977Z" level=debug msg="Calling POST /v1.41/containers/create?name=error-values"
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.892010977Z" level=debug msg="form data: {\"AttachStderr\":true,\"AttachStdin\":false,\"AttachStdout\":true,\"Cmd\":[\"toto\"],\"Domainname\":\"\",\"Entrypoint\":null,\"Env\":null,\"HostConfig\":{\"AutoRemove\":false,\"Binds\":null,\"BlkioDeviceReadBps\":null,\"BlkioDeviceReadIOps\":null,\"BlkioDeviceWriteBps\":null,\"BlkioDeviceWriteIOps\":null,\"BlkioWeight\":0,\"BlkioWeightDevice\":[],\"CapAdd\":null,\"CapDrop\":null,\"Cgroup\":\"\",\"CgroupParent\":\"\",\"CgroupnsMode\":\"\",\"ConsoleSize\":[0,0],\"ContainerIDFile\":\"\",\"CpuCount\":0,\"CpuPercent\":0,\"CpuPeriod\":0,\"CpuQuota\":0,\"CpuRealtimePeriod\":0,\"CpuRealtimeRuntime\":0,\"CpuShares\":0,\"CpusetCpus\":\"\",\"CpusetMems\":\"\",\"DeviceCgroupRules\":null,\"DeviceRequests\":null,\"Devices\":[],\"Dns\":[],\"DnsOptions\":[],\"DnsSearch\":[],\"ExtraHosts\":null,\"GroupAdd\":null,\"IOMaximumBandwidth\":0,\"IOMaximumIOps\":0,\"Init\":false,\"IpcMode\":\"\",\"Isolation\":\"\",\"KernelMemory\":0,\"KernelMemoryTCP\":0,\"Links\":null,\"LogConfig\":{\"Config\":{},\"Type\":\"\"},\"MaskedPaths\":null,\"Memory\":0,\"MemoryReservation\":0,\"MemorySwap\":0,\"MemorySwappiness\":-1,\"NanoCpus\":0,\"NetworkMode\":\"default\",\"OomKillDisable\":false,\"OomScoreAdj\":0,\"PidMode\":\"\",\"PidsLimit\":0,\"PortBindings\":{},\"Privileged\":false,\"PublishAllPorts\":false,\"ReadonlyPaths\":null,\"ReadonlyRootfs\":false,\"RestartPolicy\":{\"MaximumRetryCount\":0,\"Name\":\"no\"},\"SecurityOpt\":null,\"ShmSize\":0,\"UTSMode\":\"\",\"Ulimits\":null,\"UsernsMode\":\"\",\"VolumeDriver\":\"\",\"VolumesFrom\":null},\"Hostname\":\"\",\"Image\":\"busybox\",\"Labels\":{},\"NetworkingConfig\":{\"EndpointsConfig\":{}},\"OnBuild\":null,\"OpenStdin\":false,\"Platform\":null,\"StdinOnce\":false,\"Tty\":false,\"User\":\"\",\"Volumes\":{},\"WorkingDir\":\"\"}"
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.925538805Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/815f711f846ccbe81c074836e42387cb57b46007d141deac8eb7f9c1ee6961f3/merged 0x55a5db200fc0 0x55a5db200fc0}" container=666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.935857798Z" level=debug msg="Calling POST /v1.41/containers/666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121/attach?stderr=1&stdout=1&stream=1"
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.936567790Z" level=debug msg="attach: stdout: begin"
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.936895130Z" level=debug msg="attach: stderr: begin"
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.937258188Z" level=debug msg="Calling POST /v1.41/containers/666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121/wait?condition=next-exit"
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.937971915Z" level=debug msg="Calling POST /v1.41/containers/666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121/start"
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.943903770Z" level=debug msg="container mounted via layerStore: &{/var/lib/docker/overlay2/815f711f846ccbe81c074836e42387cb57b46007d141deac8eb7f9c1ee6961f3/merged 0x55a5db200fc0 0x55a5db200fc0}" container=666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.944569646Z" level=debug msg="Assigning addresses for endpoint error-values's interface on network bridge"
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.944834904Z" level=debug msg="RequestAddress(LocalDefault/172.17.0.0/16, <nil>, map[])"
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.945002016Z" level=debug msg="Request address PoolID:172.17.0.0/16 App: ipam/default/data, ID: LocalDefault/172.17.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65533, Sequence: (0xc0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:0 Serial:false PrefAddress:<nil> "
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.973950042Z" level=debug msg="Assigning addresses for endpoint error-values's interface on network bridge"
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.981282515Z" level=debug msg="Programming external connectivity on endpoint error-values (f183cdde2b07caa5195c416919e0a6c8868333e342a8ea1dac73f2e5c22fd6cb)"
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.982483644Z" level=debug msg="EnableService 666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121 START"
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.982769195Z" level=debug msg="EnableService 666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121 DONE"
Jan 11 13:25:48 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:48.986692766Z" level=debug msg="bundle dir created" bundle=/var/run/docker/containerd/666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121 module=libcontainerd namespace=moby root=/var/lib/docker/overlay2/815f711f846ccbe81c074836e42387cb57b46007d141deac8eb7f9c1ee6961f3/merged
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.447384056Z" level=debug msg="sandbox set key processing took 167.995565ms for container 666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.516572938Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/exit
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.516626463Z" level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/delete
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.516636630Z" level=info msg="ignoring event" container=666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121 module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.517115349Z" level=error msg="stream copy error: reading from a closed fifo"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.522668103Z" level=error msg="stream copy error: reading from a closed fifo"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.523793464Z" level=debug msg="attach: stdout: end"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.523960525Z" level=debug msg="attach: stderr: end"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.524110646Z" level=debug msg="attach done"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.531909490Z" level=debug msg="Revoking external connectivity on endpoint error-values (f183cdde2b07caa5195c416919e0a6c8868333e342a8ea1dac73f2e5c22fd6cb)"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.532422607Z" level=debug msg="DeleteConntrackEntries purged ipv4:0, ipv6:0"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.561792986Z" level=debug msg="Releasing addresses for endpoint error-values's interface on network bridge"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.562155373Z" level=debug msg="ReleaseAddress(LocalDefault/172.17.0.0/16, 172.17.0.2)"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.562363428Z" level=debug msg="Released address PoolID:LocalDefault/172.17.0.0/16, Address:172.17.0.2 Sequence:App: ipam/default/data, ID: LocalDefault/172.17.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65532, Sequence: (0xe0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.576526805Z" level=error msg="666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121 cleanup: failed to delete container from containerd: no such container"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.580186300Z" level=warning msg="error locating sandbox id da26632e5a31e42e5b13c3ca8f6f6881beb1cabe79f3ac671923e44984d9cfcb: sandbox da26632e5a31e42e5b13c3ca8f6f6881beb1cabe79f3ac671923e44984d9cfcb not found"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.580504529Z" level=debug msg="Failed to unmount 815f711f846ccbe81c074836e42387cb57b46007d141deac8eb7f9c1ee6961f3 overlay: /var/lib/docker/overlay2/815f711f846ccbe81c074836e42387cb57b46007d141deac8eb7f9c1ee6961f3/merged - no such file or directory" storage-driver=overlay2
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 dockerd[5037]: time="2022-01-11T13:25:49.581226372Z" level=error msg="666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121 cleanup: failed to delete container from containerd: no such container"

journalctl -n 50 --no-pager -xu containerd.service
Details 
Jan 11 13:23:46 ubuntu-s-1vcpu-2gb-ams3-01 containerd[5025]: time="2022-01-11T13:23:46.517860288Z" level=info msg="containerd successfully booted in 0.070366s"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 containerd[5025]: time="2022-01-11T13:25:49.025822267Z" level=info msg="loading plugin \"io.containerd.event.v1.publisher\"..." runtime=io.containerd.runc.v2 type=io.containerd.event.v1
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 containerd[5025]: time="2022-01-11T13:25:49.028213502Z" level=info msg="loading plugin \"io.containerd.internal.v1.shutdown\"..." runtime=io.containerd.runc.v2 type=io.containerd.internal.v1
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 containerd[5025]: time="2022-01-11T13:25:49.028404010Z" level=info msg="loading plugin \"io.containerd.ttrpc.v1.task\"..." runtime=io.containerd.runc.v2 type=io.containerd.ttrpc.v1
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 containerd[5025]: time="2022-01-11T13:25:49.031070584Z" level=info msg="starting signal loop" namespace=moby path=/run/containerd/io.containerd.runtime.v2.task/moby/666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121 pid=5215 runtime=io.containerd.runc.v2
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 containerd[5025]: time="2022-01-11T13:25:49.486856954Z" level=info msg="shim disconnected" id=666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 containerd[5025]: time="2022-01-11T13:25:49.488489684Z" level=warning msg="cleaning up after shim disconnected" id=666e30b515938592409fc8f0da585efcbf5555382f736dcd99795d6a16194121 namespace=moby
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 containerd[5025]: time="2022-01-11T13:25:49.488845303Z" level=info msg="cleaning up dead shim"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 containerd[5025]: time="2022-01-11T13:25:49.514679387Z" level=warning msg="cleanup warnings time=\"2022-01-11T13:25:49Z\" level=info msg=\"starting signal loop\" namespace=moby pid=5258 runtime=io.containerd.runc.v2\n"
Jan 11 13:25:49 ubuntu-s-1vcpu-2gb-ams3-01 containerd[5025]: time="2022-01-11T13:25:49.515273608Z" level=error msg="copy shim log" error="read /proc/self/fd/12: file already closed"

Difference in docker logs between both of the above (after replacing digests/ID's etc);

diff --git a/with-c8d-1.4.txt b/with-c8d-1.6.txt
index f67d2afd87..c3eda06365 100644
--- a/with-c8d-1.4.txt
+++ b/with-c8d-1.6.txt
@@ -16,6 +16,9 @@ level=debug msg="EnableService XXXXXXX START"
 level=debug msg="EnableService XXXXXXX DONE"
 level=debug msg="bundle dir created" bundle=/var/run/docker/containerd/XXXXXXX module=libcontainerd namespace=moby root=/var/lib/docker/overlay2/XXXXXXX/merged
 level=debug msg="sandbox set key processing took 167.0000ms for container XXXXXXX"
+level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/exit
+level=debug msg=event module=libcontainerd namespace=moby topic=/tasks/delete
+level=info msg="ignoring event" container=XXXXXXX module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
 level=error msg="stream copy error: reading from a closed fifo"
 level=error msg="stream copy error: reading from a closed fifo"
 level=debug msg="attach: stdout: end"
@@ -27,3 +30,6 @@ level=debug msg="Releasing addresses for endpoint error-values's interface on ne
 level=debug msg="ReleaseAddress(LocalDefault/172.17.0.0/16, 172.17.0.2)"
 level=debug msg="Released address PoolID:LocalDefault/172.17.0.0/16, Address:172.17.0.2 Sequence:App: ipam/default/data, ID: LocalDefault/172.17.0.0/16, DBIndex: 0x0, Bits: 65536, Unselected: 65532, Sequence: (0xe0000000, 1)->(0x0, 2046)->(0x1, 1)->end Curr:3"
 level=error msg="XXXXXXX cleanup: failed to delete container from containerd: no such container"
+level=warning msg="error locating sandbox id da26632e5a31e42e5b13c3ca8f6f6881beb1cabe79f3ac671923e44984d9cfcb: sandbox da26632e5a31e42e5b13c3ca8f6f6881beb1cabe79f3ac671923e44984d9cfcb not found"
+level=debug msg="Failed to unmount XXXXXXX overlay: /var/lib/docker/overlay2/XXXXXXX/merged - no such file or directory" storage-driver=overlay2
+level=error msg="XXXXXXX cleanup: failed to delete container from containerd: no such container"

Files:

with-c8d-1.6.txt
with-c8d-1.4.txt

Describe the results you received and expected

Expected the same exit code for the container

What version of containerd are you using?

containerd github.com/containerd/containerd v1.6.0-beta.5 857b35d.m

Any other relevant information

Client: Docker Engine - Community
 Version:           20.10.12
 API version:       1.41
 Go version:        go1.16.12
 Git commit:        e91ed57
 Built:             Mon Dec 13 11:45:33 2021
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.12
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.16.12
  Git commit:       459d0df
  Built:            Mon Dec 13 11:43:42 2021
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          v1.6.0-beta.5
  GitCommit:        857b35de6c6d40962d24dc1e561e8446e9f3197f.m
 runc:
  Version:          1.0.2
  GitCommit:        v1.0.2-0-g52b36a2
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

Show configuration if it is related to CRI plugin.

No response

Metadata

Metadata

Assignees

No one assigned

    Labels

    kind/bug

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions