1.13.0-rc5 healthcheck on non existant containers goes awry

[RRAlex]

A few minutes after we launch our containers, and for too long afterwards, we see ongoing health check on non existent containers...
Maybe the 1 or 2 we use at the beginning to setup things, but that exit after, leave their mark somewhere and aren't cleared in the health check container list.

The result is that the No such exec instance warning quickly (sometimes < 1h) turn into context deadline exceeded errors and the daemon reports everyone as unhealthy.
Furthermore, the daemon sometimes stops responding swiftly.
Even stranger, the docker info line of the containerd version: now says N/A as seen below while it was fine on the daemon's initial start.

Steps to reproduce the issue:
Hard to say, it seems we use a container whose health check stay active after their gone, causing a build up that ends up causing more trouble for the docker daemon.

Describe the results you received:

Jan 11 10:25:46 server0 dockerd[903]: time="2017-01-11T10:25:46.412211080-05:00" level=warning msg="Health check for container 075bf45cf93dd571bcad58bdabf0ff110a3858a7adc7e723f086b52d3bad5265 error: No such exec instance 'db55507a76e5a807224bc3ee3a13a51560d1c06842b42974cb88096327e0c536' found in daemon"
Jan 11 10:26:13 server0 dockerd[903]: time="2017-01-11T10:26:13.266877963-05:00" level=warning msg="Health check for container 2fc1a5a860dba35a0a3a67d4ad65fd0ad332e2d0c6867a1cb44d915d0e6d1538 error: No such exec instance '737e5577996f393824ac2bb26609f44432f34ea7dd3bec14552d5442d6a08011' found in daemon"
Jan 11 10:26:16 server0 dockerd[903]: time="2017-01-11T10:26:16.413149842-05:00" level=warning msg="Health check for container 075bf45cf93dd571bcad58bdabf0ff110a3858a7adc7e723f086b52d3bad5265 error: No such exec instance 'd72b00fdaf51984253fb9c988974754218917a8a687627cd462c586df2f75448' found in daemon"
Jan 11 10:26:43 server0 dockerd[903]: time="2017-01-11T10:26:43.267936886-05:00" level=warning msg="Health check for container 2fc1a5a860dba35a0a3a67d4ad65fd0ad332e2d0c6867a1cb44d915d0e6d1538 error: No such exec instance '4ffe31051cce8b1aa0f60b1f7456e3469d734058a5ac2e050bd2663737992812' found in daemon"
Jan 11 10:26:46 server0 dockerd[903]: time="2017-01-11T10:26:46.413808033-05:00" level=warning msg="Health check for container 075bf45cf93dd571bcad58bdabf0ff110a3858a7adc7e723f086b52d3bad5265 error: No such exec instance '9a481c36d86c4015e851943a0414d54f027860801ca9ec2f773f916fc6d09c15' found in daemon"
Jan 11 10:27:13 server0 dockerd[903]: time="2017-01-11T10:27:13.268959487-05:00" level=warning msg="Health check for container 2fc1a5a860dba35a0a3a67d4ad65fd0ad332e2d0c6867a1cb44d915d0e6d1538 error: No such exec instance 'f0f6246f9eda5d7f38f9a8b9cfdbf75c89d10580eecae869064fa738779329fc' found in daemon"
Jan 11 10:27:16 server0 dockerd[903]: time="2017-01-11T10:27:16.414144730-05:00" level=warning msg="Health check for container 075bf45cf93dd571bcad58bdabf0ff110a3858a7adc7e723f086b52d3bad5265 error: No such exec instance 'cc777112330b7607cb0f9776902d8047a7ab5e81c81aa676138f3446eaec085a' found in daemon"
Jan 11 10:27:28 server0 dockerd[903]: time="2017-01-11T10:27:28.022418771-05:00" level=warning msg="Health check for container 1807479428c59e08be1c056269462a526ab367d71bcc1860c0b541cbf024a819 error: rpc error: code = 4 desc = context deadline exceeded"
Jan 11 10:27:28 server0 dockerd[903]: time="2017-01-11T10:27:28.770459007-05:00" level=warning msg="Health check for container 515b205d5d47a165845c9a2c5236bf0910a872f6ae1dbf19cf5fb69623ab4f09 error: rpc error: code = 4 desc = context deadline exceeded"
Jan 11 10:27:30 server0 dockerd[903]: time="2017-01-11T10:27:30.088651675-05:00" level=warning msg="Health check for container 1b80639a25d75e73310fe45c1dbc604846ac5085773c4441635d3c48d59b0077 error: rpc error: code = 4 desc = context deadline exceeded"
Jan 11 10:27:33 server0 dockerd[903]: time="2017-01-11T10:27:33.507450992-05:00" level=warning msg="Health check for container 8090bd7c56c46d545001af00b4edb516ea4b000f5f097c283329189982623729 error: rpc error: code = 4 desc = context deadline exceeded"
Jan 11 10:27:34 server0 dockerd[903]: time="2017-01-11T10:27:34.463844739-05:00" level=warning msg="Health check for container c87549ceadc9f40b474f1c2b24d5c1468f6d07534519d94b40a44b92b3b44112 error: rpc error: code = 4 desc = context deadline exceeded"
Jan 11 10:27:35 server0 dockerd[903]: time="2017-01-11T10:27:35.081994789-05:00" level=warning msg="Health check for container 7b78b1c413d5bf767abb4f2e650458431fe1e3e789d71838f32028254393f567 error: rpc error: code = 4 desc = context deadline exceeded"
Jan 11 10:27:35 server0 dockerd[903]: time="2017-01-11T10:27:35.207010460-05:00" level=warning msg="Health check for container c9cdadde8fdf9c0c584f88f3f8075c4b127aa1ec3e5e3447902c80a27f056b0e error: rpc error: code = 4 desc = context deadline exceeded"
Jan 11 10:27:36 server0 dockerd[903]: time="2017-01-11T10:27:36.048869073-05:00" level=error msg="libcontainerd: failed to receive event from containerd: rpc error: code = 13 desc = transport is closing"
Jan 11 10:27:36 server0 dockerd[903]: time="2017-01-11T10:27:36.056835736-05:00" level=info msg="libcontainerd: new containerd process, pid: 31072"
Jan 11 10:27:36 server0 dockerd[903]: time="2017-01-11T10:27:36.088448897-05:00" level=warning msg="Health check for container 16c786570ae6fc698d5af7e6b388a61b075f68d5fb232610429fc2904f439b19 error: rpc error: code = 13 desc = transport is closing"
Jan 11 10:27:36 server0 dockerd[903]: time="2017-01-11T10:27:36.175748731-05:00" level=fatal msg="open /var/run/docker/libcontainerd/containerd/1807479428c59e08be1c056269462a526ab367d71bcc1860c0b541cbf024a819/70fb10743a22cb7b0bee1e30294d1d58193d8170a3f5ee3d6c20a78050cef65f/process.json: no such file or directory"
Jan 11 10:27:36 server0 dockerd[903]: time="2017-01-11T10:27:36.871861345-05:00" level=info msg="libcontainerd: new containerd process, pid: 31081"
Jan 11 10:27:36 server0 dockerd[903]: time="2017-01-11T10:27:36.924295488-05:00" level=fatal msg="open /var/run/docker/libcontainerd/containerd/1807479428c59e08be1c056269462a526ab367d71bcc1860c0b541cbf024a819/70fb10743a22cb7b0bee1e30294d1d58193d8170a3f5ee3d6c20a78050cef65f/process.json: no such file or directory"
Jan 11 10:27:37 server0 dockerd[903]: time="2017-01-11T10:27:37.868735810-05:00" level=warning msg="Health check for container 4191eb499571da26c3493f94598d3f2a5c6565171d0dbb6c7be2fed985103b1c error: rpc error: code = 14 desc = grpc: the connection is unavailable"
Jan 11 10:27:38 server0 dockerd[903]: time="2017-01-11T10:27:38.373862486-05:00" level=info msg="libcontainerd: new containerd process, pid: 31090"
Jan 11 10:27:38 server0 dockerd[903]: time="2017-01-11T10:27:38.398648957-05:00" level=fatal msg="open /var/run/docker/libcontainerd/containerd/1807479428c59e08be1c056269462a526ab367d71bcc1860c0b541cbf024a819/70fb10743a22cb7b0bee1e30294d1d58193d8170a3f5ee3d6c20a78050cef65f/process.json: no such file or directory"
Jan 11 10:27:39 server0 dockerd[903]: time="2017-01-11T10:27:39.872293729-05:00" level=info msg="libcontainerd: new containerd process, pid: 31098"
Jan 11 10:27:39 server0 dockerd[903]: time="2017-01-11T10:27:39.89301445-05:00" level=fatal msg="open /var/run/docker/libcontainerd/containerd/1807479428c59e08be1c056269462a526ab367d71bcc1860c0b541cbf024a819/70fb10743a22cb7b0bee1e30294d1d58193d8170a3f5ee3d6c20a78050cef65f/process.json: no such file or directory"
Jan 11 10:27:41 server0 dockerd[903]: time="2017-01-11T10:27:41.373768302-05:00" level=info msg="libcontainerd: new containerd process, pid: 31106"
Jan 11 10:27:41 server0 dockerd[903]: time="2017-01-11T10:27:41.423101794-05:00" level=fatal msg="open /var/run/docker/libcontainerd/containerd/1807479428c59e08be1c056269462a526ab367d71bcc1860c0b541cbf024a819/70fb10743a22cb7b0bee1e30294d1d58193d8170a3f5ee3d6c20a78050cef65f/process.json: no such file or directory"
Jan 11 10:27:42 server0 dockerd[903]: time="2017-01-11T10:27:42.874085871-05:00" level=info msg="libcontainerd: new containerd process, pid: 31115"
Jan 11 10:27:42 server0 dockerd[903]: time="2017-01-11T10:27:42.895149032-05:00" level=fatal msg="open /var/run/docker/libcontainerd/containerd/1807479428c59e08be1c056269462a526ab367d71bcc1860c0b541cbf024a819/70fb10743a22cb7b0bee1e30294d1d58193d8170a3f5ee3d6c20a78050cef65f/process.json: no such file or directory"
Jan 11 10:27:43 server0 dockerd[903]: time="2017-01-11T10:27:43.269496559-05:00" level=warning msg="Health check for container 2fc1a5a860dba35a0a3a67d4ad65fd0ad332e2d0c6867a1cb44d915d0e6d1538 error: No such exec instance '25de0f4c8f8a4e0e6dfb9ca5ba86a9204cb512d3f894e23c98de11c52b2c5059' found in daemon"
Jan 11 10:27:44 server0 dockerd[903]: time="2017-01-11T10:27:44.371805952-05:00" level=info msg="libcontainerd: new containerd process, pid: 31123"
Jan 11 10:27:44 server0 dockerd[903]: time="2017-01-11T10:27:44.391271529-05:00" level=fatal msg="open /var/run/docker/libcontainerd/containerd/1807479428c59e08be1c056269462a526ab367d71bcc1860c0b541cbf024a819/70fb10743a22cb7b0bee1e30294d1d58193d8170a3f5ee3d6c20a78050cef65f/process.json: no such file or directory"
Jan 11 10:27:45 server0 dockerd[903]: time="2017-01-11T10:27:45.873800793-05:00" level=info msg="libcontainerd: new containerd process, pid: 31130"
Jan 11 10:27:45 server0 dockerd[903]: time="2017-01-11T10:27:45.898087536-05:00" level=fatal msg="open /var/run/docker/libcontainerd/containerd/1807479428c59e08be1c056269462a526ab367d71bcc1860c0b541cbf024a819/70fb10743a22cb7b0bee1e30294d1d58193d8170a3f5ee3d6c20a78050cef65f/process.json: no such file or directory"
Jan 11 10:27:46 server0 dockerd[903]: time="2017-01-11T10:27:46.415003192-05:00" level=warning msg="Health check for container 075bf45cf93dd571bcad58bdabf0ff110a3858a7adc7e723f086b52d3bad5265 error: No such exec instance 'bcacfba2bd99da04082e8ecfcfbad4301e14722a46a25d5c1d98e2f37fa09b20' found in daemon"
Jan 11 10:27:47 server0 dockerd[903]: time="2017-01-11T10:27:47.372911944-05:00" level=info msg="libcontainerd: new containerd process, pid: 31140"
Jan 11 10:27:47 server0 dockerd[903]: time="2017-01-11T10:27:47.391975517-05:00" level=fatal msg="open /var/run/docker/libcontainerd/containerd/1807479428c59e08be1c056269462a526ab367d71bcc1860c0b541cbf024a819/70fb10743a22cb7b0bee1e30294d1d58193d8170a3f5ee3d6c20a78050cef65f/process.json: no such file or directory"
Jan 11 10:27:48 server0 dockerd[903]: time="2017-01-11T10:27:48.004981172-05:00" level=warning msg="Health check for container c1a153c01eb7b7667498af5024a042464dc30d7d5f5fb04c538ee8864b99c257 error: rpc error: code = 14 desc = grpc: the connection is unavailable"
Jan 11 10:27:48 server0 dockerd[903]: time="2017-01-11T10:27:48.873267403-05:00" level=info msg="libcontainerd: new containerd process, pid: 31149"
Jan 11 10:27:48 server0 dockerd[903]: time="2017-01-11T10:27:48.894804885-05:00" level=fatal msg="open /var/run/docker/libcontainerd/containerd/1807479428c59e08be1c056269462a526ab367d71bcc1860c0b541cbf024a819/70fb10743a22cb7b0bee1e30294d1d58193d8170a3f5ee3d6c20a78050cef65f/process.json: no such file or directory"
Jan 11 10:27:50 server0 dockerd[903]: time="2017-01-11T10:27:50.371847643-05:00" level=info msg="libcontainerd: new containerd process, pid: 31157"
Jan 11 10:27:50 server0 dockerd[903]: time="2017-01-11T10:27:50.391874139-05:00" level=fatal msg="open /var/run/docker/libcontainerd/containerd/1807479428c59e08be1c056269462a526ab367d71bcc1860c0b541cbf024a819/70fb10743a22cb7b0bee1e30294d1d58193d8170a3f5ee3d6c20a78050cef65f/process.json: no such file or directory"
Jan 11 10:27:50 server0 dockerd[903]: time="2017-01-11T10:27:50.472630292-05:00" level=warning msg="Health check for container d1b297c55f4a0757dff8f4308f14b26640d7867c10ceca1191df99984480e702 error: rpc error: code = 14 desc = grpc: the connection is unavailable"
Jan 11 10:27:51 server0 dockerd[903]: time="2017-01-11T10:27:51.872738602-05:00" level=info msg="libcontainerd: new containerd process, pid: 31165"
Jan 11 10:27:51 server0 dockerd[903]: time="2017-01-11T10:27:51.895508321-05:00" level=fatal msg="open /var/run/docker/libcontainerd/containerd/1807479428c59e08be1c056269462a526ab367d71bcc1860c0b541cbf024a819/70fb10743a22cb7b0bee1e30294d1d58193d8170a3f5ee3d6c20a78050cef65f/process.json: no such file or directory"
Jan 11 10:27:52 server0 dockerd[903]: time="2017-01-11T10:27:52.376425977-05:00" level=warning msg="Health check for container 165693603abb52553ea1055d18f68d57b7fc1bd54f1ae10b03de64574baf883f error: rpc error: code = 14 desc = grpc: the connection is unavailable"
Jan 11 10:27:53 server0 dockerd[903]: time="2017-01-11T10:27:53.375101821-05:00" level=info msg="libcontainerd: new containerd process, pid: 31171"
Jan 11 10:27:53 server0 dockerd[903]: time="2017-01-11T10:27:53.400707355-05:00" level=fatal msg="open /var/run/docker/libcontainerd/containerd/1807479428c59e08be1

Describe the results you expected:

• Healthcheck logs should stop quite fast for containers that don't exist at all (docker ps -a not showing these hashes).
• Healthcheck status should stay healthy for other containers.
• docker commands should keep working

Additional information you deem important (e.g. issue happens only occasionally):

Output of docker version:

Client:
 Version:      1.13.0-rc5
 API version:  1.25
 Go version:   go1.7.3
 Git commit:   43cc971
 Built:        Thu Jan  5 00:55:26 2017
 OS/Arch:      linux/amd64
Server:
 Version:      1.13.0-rc5
 API version:  1.25 (minimum version 1.12)
 Go version:   go1.7.3
 Git commit:   43cc971
 Built:        Thu Jan  5 00:55:26 2017
 OS/Arch:      linux/amd64
 Experimental: false

Output of docker info:

The interesting thing is that the containerd version line, after a while, becomes N/A...

Containers: 28
 Running: 28
 Paused: 0
 Stopped: 0
Images: 43
Server Version: 1.13.0-rc5
Storage Driver: aufs
 Root Dir: /var/lib/docker/aufs
 Backing Filesystem: extfs
 Dirs: 389
 Dirperm1 Supported: true
Logging Driver: syslog
Cgroup Driver: cgroupfs
Plugins: 
 Volume: local
 Network: bridge host macvlan null overlay
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: N/A (expected: 03e5862ec0d8d3b3f750e19fca3ee367e13c090e)
runc version: 51371867a01c467f08af739783b8beafc154c4d7
init version: 949e6fa
Security Options:
 apparmor
 seccomp
  Profile: default
Kernel Version: 4.4.0-59-generic
Operating System: Ubuntu 16.04.1 LTS
OSType: linux
Architecture: x86_64
CPUs: 6
Total Memory: 22.99 GiB
Name: warden
ID: MRFE:3XHR:QEKV:QMJF:RV3O:Z63T:DAEC:QB4G:H72B:4CNA:E5G4:Z4HR
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

Additional environment details (AWS, VirtualBox, physical, etc.):
It runs on a Proxmox VM.

Not sure if it relates to these other issues:
#29854
#29369

[fntlnz]

@RRAlex looks like that CloseMonitorChannel¹ is never reached after container stop.

Logs are showing only the OpenMonitorChannel.

root@net-1:/var/lib/docker# journalctl -u docker | grep -i channel
Jan 12 23:58:03 net-1 dockerd[8706]: time="2017-01-12T23:58:03.244992200Z" level=debug msg=OpenMonitorChannel

Anyhow I never hitted the no such exec instance during my trials.

[¹]https://github.com/docker/docker/blob/89b123473774248fc3a0356dd3ce5b116cc69b29/container/health.go#L44

[RRAlex]

I couldn't find any OpenMonitorChannel reference in any docker or system log.
Also it's still acting this way on rc6 and was apparently doing the same on the last 1.12.x releases.

[thaJeztah]

@fntlnz told me he was looking into this, so let me put a "claimed" label on it, but let me know if you need help

[exstral]

We are hitting this issue in one of our jenkins agents running jobs that create and then kill a lot of containers. Looking at our previous job runs, it seems that in a job run several days ago, one container failed to turn healthy and the job failed. The next job then removed all containers as per normal procedure.

Now several days later the health check for that container is still running every few seconds, even though the container was removed (docker rm -f -v). This is not causing any other issues so far, it is only being logged.

Should we stop the containers some other way (docker stop?) to make sure the health check monitoring is also properly removed?

Mar 20 13:01:25 local-rosetta-06-server2 dockerd[27229]: time="2017-03-20T13:01:25.558788947+01:00" level=warning msg="Health check for container a5977e6b58e6ce2807aa1fa8564c305fef14f09865bd80280ce433cd7b966065 error: No such exec instance '0cf2afd9d36ca87ace00dcf0a17120375fd177f3b3d3c1212717ccc9d7719440' found in daemon"
Mar 20 13:01:28 local-rosetta-06-server2 dockerd[27229]: time="2017-03-20T13:01:28.562878293+01:00" level=warning msg="Health check for container a5977e6b58e6ce2807aa1fa8564c305fef14f09865bd80280ce433cd7b966065 error: No such exec instance '460c97aa3267eb5e3d7d771d7ff92447e9d13c088927a27cbf94c882d3ba662a' found in daemon"
Mar 20 13:01:31 local-rosetta-06-server2 dockerd[27229]: time="2017-03-20T13:01:31.564341886+01:00" level=warning msg="Health check for container a5977e6b58e6ce2807aa1fa8564c305fef14f09865bd80280ce433cd7b966065 error: No such exec instance '5e3b55c3f57c4e473a89787828c17f7ae506c745ee6e4b1eba35762b4ec07c5f' found in daemon"
Mar 20 13:01:34 local-rosetta-06-server2 dockerd[27229]: time="2017-03-20T13:01:34.565294521+01:00" level=warning msg="Health check for container a5977e6b58e6ce2807aa1fa8564c305fef14f09865bd80280ce433cd7b966065 error: No such exec instance 'eab559c28d50551affb5695b22d89058a71913aa6c765b3b7df43efb6ec43d60' found in daemon"
Mar 20 13:01:37 local-rosetta-06-server2 dockerd[27229]: time="2017-03-20T13:01:37.566310572+01:00" level=warning msg="Health check for container a5977e6b58e6ce2807aa1fa8564c305fef14f09865bd80280ce433cd7b966065 error: No such exec instance 'fe8d06b981742b736aa03278a97ab071b5b3aa8dddd1c707dcad37c51c56e84a' found in daemon"
Mar 20 13:01:40 local-rosetta-06-server2 dockerd[27229]: time="2017-03-20T13:01:40.571477709+01:00" level=warning msg="Health check for container a5977e6b58e6ce2807aa1fa8564c305fef14f09865bd80280ce433cd7b966065 error: No such exec instance '4ef37bd6dd3c527bc021f651c188f95a4565d490e6ab540d09c9970035213c26' found in daemon"
Mar 20 13:01:43 local-rosetta-06-server2 dockerd[27229]: time="2017-03-20T13:01:43.573351131+01:00" level=warning msg="Health check for container a5977e6b58e6ce2807aa1fa8564c305fef14f09865bd80280ce433cd7b966065 error: No such exec instance '6feec9648f35064677a9d581939437512b22c6b2038f5f49a7d7f9da6cecf206' found in daemon"

[thaJeztah]

ping @fntlnz did you have time to look into this?

[exstral]

I just found a way to reproduce this in our setup. It happens if we restart the docker service when we have containers running.

After restart the docker service will try and start up all the containers again, but without docker-compose to take care with the depends_on it just starts all containers at once. Since we have a lot of interdependent services that do not deal well with backends being down, they will fail. And that is when we get broken health checks that just keep on running, even after the containers are deleted and recreated.

I'm not sure how easy it would be to create a reproducible docker-compose.yml that causes this error without our internal services, but if you need it to debug this issue I could try.

[mlaventure]

@esbite could you provide your docker info and if possible the daemon logs (with debug activated)?

If your issue it similar to the original one, it looks like containerd is failing to start after the restart.

[exstral]

I managed to create a small docker-compose.yml that will reproduce this. The example could very likely be smaller and simpler, but this is the way I found to do it :)

In short it happens for us when we had running containers with restart: always set. Then when restarting the docker daemon, they will start up with missing backends and one health check will get stuck forever, resulting in this daemon log output:

Mar 22 11:14:08 local-rosetta-eriksson dockerd[701]: time="2017-03-22T11:14:08.676276395+01:00" level=warning msg="Health check for container 901de17c55cf3657a40fed00b8e135267267e7a33587d932a4905840a950e907 error: No such exec instance '16358d76605b65050443f2c7cca02c6c0606d730fa0b4b4b17f779180b423001' found in daemon"
Mar 22 11:14:10 local-rosetta-eriksson dockerd[701]: time="2017-03-22T11:14:10.689975120+01:00" level=warning msg="Health check for container 901de17c55cf3657a40fed00b8e135267267e7a33587d932a4905840a950e907 error: No such exec instance '7d5a6de2a93cac1f882a76856238122186353a5282d9f91badfcee830f67a902' found in daemon"
Mar 22 11:14:12 local-rosetta-eriksson dockerd[701]: time="2017-03-22T11:14:12.691835148+01:00" level=warning msg="Health check for container 901de17c55cf3657a40fed00b8e135267267e7a33587d932a4905840a950e907 error: No such exec instance 'af736034ee149c2416d9d2baa445020abc485938fd6ef5692293a372f634e669' found in daemon"

Gist with instructions on how to reproduce this:
https://gist.github.com/esbite/d0c639e72435b4721d44445b0972dff8

[mlaventure]

@esbite thanks for the instructions, I can reproduce the issue following them.

[fntlnz]

@mlaventure I actually tried to check if your fix to containerd brought to the 17.03.x branch by #31662 solved this but it doesn't looks like.
Still investiganting / debugging