Cannot stop the container: stop timeout

[sofat1989]

Containerd: v1.2.4
Error Message:

time="2019-03-25T02:07:08.210779178-07:00" level=error msg="An error occurs during waiting for container "50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3" to be stopped" error="wait container "50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3" stop timeout"

The container is soon OOMKilled after it is up. The command, crictl ps shows the container is running. But the container is exited
I checked the logs of containerd, here is an error message

Mar 22 01:56:43  containerd[9598]: time="2019-03-22T01:56:43.650896850-07:00" level=info msg="StartContainer for "50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3""
Mar 22 01:56:43 containerd[9598]: time="2019-03-22T01:56:43.652175173-07:00" level=info msg="shim containerd-shim started" address="/containerd-shim/k8s.io/50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3/shim.sock" debug=true pid=28058
Mar 22 01:56:44 containerd[9598]: time="2019-03-22T01:56:44.476147620-07:00" level=info msg="StartContainer for "50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3" returns successfully"
Mar 22 01:58:04 containerd[9598]: time="2019-03-22T01:58:04-07:00" level=error msg="post event" error="failed to publish event" namespace=k8s.io path="/run/containerd/io.containerd.runtime.v1.linux/k8s.io/50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3" pid=28058
Mar 22 02:01:23 containerd[9598]: time="2019-03-22T02:01:23.970668962-07:00" level=info msg="Finish piping stderr of container "50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3""
Mar 22 02:01:23  containerd[9598]: time="2019-03-22T02:01:23.970856941-07:00" level=info msg="Finish piping stdout of container "50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3""
Mar 22 02:01:24 containerd[9598]: time="2019-03-22T02:01:24.013183916-07:00" level=info msg="TaskOOM event &TaskOOM{ContainerID:50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3,}"
Mar 22 02:07:16  containerd[9598]: time="2019-03-22T02:07:16.799368410-07:00" level=info msg="StopContainer for "50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3" with timeout 30 (s)"
Mar 22 02:07:16 containerd[9598]: time="2019-03-22T02:07:16.818108390-07:00" level=info msg="Stop container "50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3" with signal terminated"
Mar 22 02:07:46  containerd[9598]: time="2019-03-22T02:07:46.834222655-07:00" level=error msg="An error occurs during waiting for container "50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3" to be stopped" error="wait container "50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3" stop timeout"

Here is an error

Mar 22 01:58:04  containerd[9598]: time="2019-03-22T01:58:04-07:00" level=error msg="post event" error="failed to publish event" namespace=k8s.io path="/run/containerd/io.containerd.runtime.v1.linux/k8s.io/50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3" pid=28058

I think here should have a TaskExit event. We cannot get the reason why the event is failed to publish. We doubt that the container cannot be stopped because containerd didn't get the TaskExit event

After the containerd is restarted, The containerd shows

Mar 25 02:07:28 containerd[25806]: time="2019-03-25T02:07:28.877990557-07:00" level=info msg="TaskExit event &TaskExit{ContainerID:50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3,ID:50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3,Pid:28097,ExitStatus:137,ExitedAt:2019-03-25 09:07:26.071348787 +0000 UTC,}"
Mar 25 02:07:36  containerd[25806]: time="2019-03-25T02:07:36.494666976-07:00" level=info msg="Container to stop "50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3" must be in running or unknown state, current state "CONTAINER_EXITED""
Mar 25 02:07:36  containerd[25806]: time="2019-03-25T02:07:36.516380707-07:00" level=info msg="Container to stop "50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3" must be in running or unknown state, current state "CONTAINER_EXITED""
Mar 25 02:07:36  containerd[25806]: time="2019-03-25T02:07:36.537179076-07:00" level=info msg="RemoveContainer for "50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3""
Mar 25 02:07:36 containerd[25806]: time="2019-03-25T02:07:36.563730617-07:00" level=info msg="RemoveContainer for "50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3" returns successfully"
Mar 25 02:07:36  containerd[25806]: time="2019-03-25T02:07:36.766274471-07:00" level=debug msg="removed snapshot" key="k8s.io/4711/50226b57f4b79111737460f54cc3e142631d8803efa6ecef58d808f8b56ed0a3" snapshotter=overlayfs

Q1: In which conditions, will the publishing events fail?
Q2: Why cannot the container be stopped?

[estesp]

I don't know about the failed event publish, but Q2 has at least one fairly easy answer; if we're talking about Linux (which I assume we are), then uninterruptible sleep (e.g. in-kernel I/O) is one reason for a container process to refuse to be killed, even after the 30s delay followed by SIGKILL. I have seen this with containerd and the use of NFS mounted filesystems in several cases--more detail in this 2015 blog.

Can you look at the PID mentioned on the host and validate what state it is in? Looks like it is pid 28058

[keyingliu]

@estesp the container process has been killed and gone, but the containerd-shim for this container is still there, 28058 is the pid of containerd-shim. From the ctr c ls or crictl ps, the container is still in running status.
After restart containerd, the containerd-shim process disappeared.

[Random-Liu]

Q1: In which conditions, will the publishing events fail?

We need to figure this out.

Based on the code, this is because the event publishing process exits with non-zero exit code. https://github.com/containerd/containerd/blob/master/cmd/containerd-shim/main_unix.go#L286

We should:

1. Print error with stdout/stderr from event publishing process for debuging;
2. Retry sending event, especially for TaskExit, which is very important in the container lifecycle handling.

Q2: Why cannot the container be stopped?

If containerd doesn't receive the TaskExit event, it won't know the container exited.

[sofat1989]

@Random-Liu We reproduced this issue. The error message from stderr is

stderr: containerd: transport is closing: unavailable

stdout is empty
the exit code is 1

[Random-Liu]

@sofat1989 IIRC, If containerd is down at that time, it is fine, because when containerd restarts, it will recover the correct container state by querying the latest state from shims.

However, if containerd is runing, but event publish fails, containerd will never know the container exits, in this case we need to do something.

[Random-Liu]

This should be fixed by containerd/cri#1133 and containerd/cri#1136

Close for now. Feel free to reopen if you encounter this issue again after next containerd upgrade.