Stopped container is shown in docker ps and is unresponsive due to blocked attached output reader

[asterite3]

Description

When a container logs a lot and there is a client attached to it that does not read it's output, that container will eventually block on write as it's output buffer fills up - this was discussed in #22502. However, if such a container stops - either due to it's main process exiting by itself or due to being killed with docker kill or by sending a death signal - the container will remain in docker ps and all operations on it (docker exec, docker kill etc.) will get stuck. It will remain in that state until that attached client goes away (detaches or exits). If client remains attached, container will be in such "zombie" state for arbitrarily long time.

Steps to reproduce the issue:
The easiest way to reproduce is to use docker attach command. (another way to do it might be using steps from #22502)

1. Run a container that logs a lot docker run --name testing --rm -it ubuntu yes testing > /dev/null
2. In another console do docker attach --no-stdin testing | /bin/sleep infinity - sleep does not read it's stdin, so attach will block and won't read output from container.
3. In yet another console do docker kill testing (or kill yes process in container with kill -9). Note that if docker kill is used, it will get stuck.
4. And in yet another console: htop or ps can be used to verify that process yes testing is not running any more, as well as corresponding containerd-shim.
5. However, docker ps will still show the container as running. docker inspect testing, docker exec -it testing bash, docker stop testing, docker kill testing and docker rm -f testing will all do nothing and just get stuck.
6. An attached process can be-unblocked (in this case, by killing sleep for example) - then container shutdown will complete, it will disappear from docker ps and all operations on it will unblock. At this point an error like stream copy error: read /proc/self/fd/24: file already closed will be printed to Docker daemon log - this happens here because the read end with container's output coming from containerd has already been closed by Wait

Describe the results you received:

A container that died (it's main process and it's containerd-shim exited) is still shown in docker ps and operations on it get stuck forever without reporting an error.

Describe the results you expected:

After container is stopped and it's main process exits (together with containerd-shim), it is not shown in docker ps and all operations on it return immediately with error stating that this container is not running/does not exist.

Additional information you deem important:

We originally faced this issue with docker-compose, that attaches to container to read it's logs - see docker/compose#6018

Output of docker version:

Client: Docker Engine - Community
 Version:           19.03.12
 API version:       1.40
 Go version:        go1.13.10
 Git commit:        48a66213fe
 Built:             Mon Jun 22 15:45:36 2020
 OS/Arch:           linux/amd64
 Experimental:      false

Server: Docker Engine - Community
 Engine:
  Version:          19.03.12
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.13.10
  Git commit:       48a66213fe
  Built:            Mon Jun 22 15:44:07 2020
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.2.13
  GitCommit:        7ad184331fa3e55e52b890ea95e65ba581ae3429
 runc:
  Version:          1.0.0-rc10
  GitCommit:        dc9208a3303feef5b3839f4323d9beb36df0a9dd
 docker-init:
  Version:          0.18.0
  GitCommit:        fec3683

It also reproduces with docker built from master git branch.

Output of docker info:

Client:
 Debug Mode: false

Server:
 Containers: 4
  Running: 3
  Paused: 0
  Stopped: 1
 Images: 474
 Server Version: 19.03.12
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 7ad184331fa3e55e52b890ea95e65ba581ae3429
 runc version: dc9208a3303feef5b3839f4323d9beb36df0a9dd
 init version: fec3683
 Security Options:
  apparmor
  seccomp
   Profile: default
 Kernel Version: 5.4.0-54-generic
 Operating System: Ubuntu 20.04.1 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 8
 Total Memory: 31.13GiB
 Name: asterite
 ID: YFJ6:3JWI:FPQE:2GZ6:GMYF:BMSM:ALQY:56ZU:Y26B:3I5P:YB4Z:7BQG
 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

WARNING: No swap limit support

Additional environment details (AWS, VirtualBox, physical, etc.):

We were able to reproduce it both on a physical machine and on a VM.

[asterite3]

I debugged this a bit to find a cause, this is what I found:

1. When containerd sees that container exited, it notifies docker daemon about it - as a result, handleContainerExit is called. Fist of all, this method takes a lock on a container (c.Lock()).
2. After that, in handleContainerExit control passes to c.StreamConfig.Wait(ctx) and gets stuck there a bit. But there is a 2 second timeout, so, after two seconds, Wait is forcibly unblocked and control passes further.
3. Then c.Reset(false) is called. It, in turn, calls container.CloseStreams(), container.CloseStreams delegates to container.StreamConfig.CloseStreams(), which will firstly close stdin and then try to close stdout with c.stdout.Clean()
4. c.stdout is an instance of broadcaster.Unbuffered - it will try to take a lock on this Unbuffered object - and will get stuck indefinitely on waiting for that lock to become available.

So that call to c.Reset(false) will block, so control won't pass further through the code of handleContainerExit and won't mark container as stopped, won't do autoremove. It will remain holding container's lock, which is, I beleive, a reason why all other operations on that container get stuck.

The reason why the lock of broadcaster.Unbuffered is unavailable is because it's Write method has taken it and then got blocked on a Write that sends data to our attached client that does not read it.

By looking at dockerd stack traces (and descriptions) it seems that #40455 and #38501 (comment) might be related to the same issue.

[asterite3]

I would be happy to provide a PR that fixes it, but I am not 100% sure what is the correct approach to do that. Still, I made a draft PR with one of the possible ways I could come up with (and a couple others in comments): #41828. The basic idea behind all of them is: add a cleanup method to Unbuffered that will, if some timeout for normal cleanup expires, forcibly call .Close() on all writers right in the middle of them being blocked on Write() (somewhat in the style of b5f2886).

[attrib]

I believe we have the same problem or maybe the issue described in #41828 (comment)

I attached my goroutine stacks, when the docker starts to not respond anymore.

goroutine-stacks-2021-07-06T060002Z.log

I'm currently unsure how I can reproduce this, this currently happens "randomly" every 10-30days on one server.
From what I've seen there are a lot of semaphores waiting which suspects me to this issue.

On this server where this happens a lot of containers are stopped and started each minute, not sure if this is related.