Docker daemon hanging

[chbatey]

I have seen the daemon hang (1.8.3) under high load: #13885. However this appears different. I am now running 1.11.2 and had a hang under little to no load.

BUG REPORT INFORMATION

Output of docker version:

centos@ip-10-50-185-106 ~]$ docker version
Client:
 Version:      1.11.2
 API version:  1.23
 Go version:   go1.5.4
 Git commit:   b9f10c9
 Built:        Wed Jun  1 21:23:11 2016
 OS/Arch:      linux/amd64
Cannot connect to the Docker daemon. Is the docker daemon running on this host?
[centos@ip-10-50-185-106 ~]$ sudo docker version
Client:
 Version:      1.11.2
 API version:  1.23
 Go version:   go1.5.4
 Git commit:   b9f10c9
 Built:        Wed Jun  1 21:23:11 2016
 OS/Arch:      linux/amd64

Server:
 Version:      1.11.2
 API version:  1.23
 Go version:   go1.5.4
 Git commit:   b9f10c9
 Built:        Wed Jun  1 21:23:11 2016
 OS/Arch:      linux/amd64

Output of docker info:

Containers: 13
 Running: 12
 Paused: 0
 Stopped: 1
Images: 11
Server Version: 1.11.2
Storage Driver: devicemapper
 Pool Name: direct_lvm-thin_pool
 Pool Blocksize: 65.54 kB
 Base Device Size: 107.4 GB
 Backing Filesystem: xfs
 Data file: 
 Metadata file: 
 Data Space Used: 2.39 GB
 Data Space Total: 66.57 GB
 Data Space Available: 64.18 GB
 Metadata Space Used: 4.375 MB
 Metadata Space Total: 1.074 GB
 Metadata Space Available: 1.069 GB
 Udev Sync Supported: true
 Deferred Removal Enabled: false
 Deferred Deletion Enabled: false
 Deferred Deleted Device Count: 0
 Library Version: 1.02.107-RHEL7 (2016-06-09)
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins: 
 Volume: local
 Network: null host bridge
Kernel Version: 3.10.0-327.22.2.el7.x86_64
Operating System: CentOS Linux 7 (Core)
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 6.897 GiB
Name: ip-10-50-185-106.internal
ID: DDCD:TC7W:6V5N:QDUA:YQF6:24EU:5SVR:WY3L:VZ7X:4BRW:NKM4:INSA
Docker Root Dir: /var/lib/docker
Debug mode (client): false
Debug mode (server): false
Http Proxy: http://10.50.185.193:80
Https Proxy: http://10.50.185.193:80
No Proxy: 10.50.185.0/24,.internal,registry-k8.api.bskyb.com,master-test-k8.api.bskyb.com,localhost,127.0.0.0/8,::1,/var/run/docker.sock,169.254.169.254
Registry: https://index.docker.io/v1/

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

Steps to reproduce the issue:
Unknown

Describe the results you received:
All docker client commands hang

Stracing docker client:

read(6, 0xc8203ea000, 4096)             = -1 EAGAIN (Resource temporarily unavailable)
write(6, "GET /v1.23/containers/json HTTP/"..., 89) = 89
futex(0x21ef2b0, FUTEX_WAIT, 0, NULL

So basically no response back from the daemon.

Stracing docker daemon

[root@ip-10-50-185-112 ~]# strace -p 1095
Process 1095 attached
read(46, 

So the daemon look to be reading on FD 46

[centos@ip-10-50-185-112 ~]$ sudo lsof -d 46                                                                                                                                                                                                                                                                                                                               
COMMAND     PID USER   FD   TYPE             DEVICE SIZE/OFF      NODE NAME
kube-prox   991 root   46u  IPv6              24429      0t0       TCP *:31624 (LISTEN)
docker     1095 root   46r  FIFO               0,18      0t0   3836156 /run/docker/libcontainerd/110d033df2a6bf66ddffce6aeef574148f04b25b61a4f931978933cec4f51116/init-stderr
master     1540 root   46u  unix 0xffff8800e787c740      0t0     24830 public/flush
docker-co  1583 root   46r  FIFO               0,18      0t0     36330 /run/containerd/d6bd98f8998e1e5638a8d0122e44ae452a30ff89a7e6733ab962188762b3785e/init/exit
kubelet    2244 root   46u  sock                0,6      0t0   6102239 protocol: TCPv6

Describe the results you expected:
Docker to work

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

Any additional information I can add today. I have taken this node out of use and left it hung. The only fix is to restart docker which I can hold off for 24 hours.

[krisives]

I notice when doing this:

An error occurred trying to connect: Get http://%2Fvar%2Frun%2Fdocker.sock/v1.24/containers/json?all=1: EOF

[chbatey]

We got a a bunch of these errors before it started happening. Not sure if it is relevant:

Aug 01 13:36:19 ip-10-50-185-112.internal docker[1095]: time="2016-08-01T13:36:19.141572744Z" level=error msg="Error running exec in container: rpc error: code = 2 desc = \"oci runtime error: exec failed: exec format error\"\n"
Aug 01 13:36:19 ip-10-50-185-112.internal docker[1095]: time="2016-08-01T13:36:19.141621771Z" level=error msg="Handler for POST /exec/72f9059aad0a6b32510fef17cbc83605fff69aaee3d2310d2632da7156850c3a/start returned error: rpc error: code = 2 desc = \"oci runtime error: exec failed: exec format error\""
Aug 01 13:36:19 ip-10-50-185-112.internal docker[1095]: 2016/08/01 13:36:19 http: response.WriteHeader on hijacked connection
Aug 01 13:36:19 ip-10-50-185-112.internal docker[1095]: 2016/08/01 13:36:19 http: response.Write on hijacked connection
Aug 01 13:36:19 ip-10-50-185-112.internal start-kubelet.sh[2244]: E0801 13:36:19.141978    2244 exec.go:54] error executing command in container: Error executing in Docker Container: 126

[krisives]

Without getting to specific to our application logic, we have a CRON task that runs a few docker exec commands:

docker exec c_5 wc -c /var/log/foo.log

If the logfile is empty the cron task is done. Otherwise we run another command:

docker exec c_5 rotate_logs

This causes an application we use to close foo.log rename it to foo.log.1 and make a new foo.log file. Once that is done we run this command to find all the logs:

docker exec c_5 bash -c 'ls -1 /var/log/foo.log.*'

For each log we read it:

docker exec c_5 cat /var/log/foo.log.1

Then we remove it:

docker exec c_5 rm /var/log/foo.log.1

As you can see we are generating a few commands within this CRON task. After a few hours of running these commands across 20 or so docker images we see docker hang. For whatever reason it seems isolated to a single container as docker ps -a -n 5 may work if the offending container is not within that query. Basically any docker commands that don't touch the affected container(s) will work as normal. All containers continue running the application within them without interruption it's just the daemon that stops communicating.

[thaJeztah]

/cc @mlaventure

[krisives]

Here is a stack trace from kill -s USR1 5561

https://gist.githubusercontent.com/krisives/5a9d4f3fab5d17329630e105ccd80060/raw/e8c7b6a65d6978a8d4a2806fe28fe497eeda0f4e/gistfile1.txt

I don't know much about the stack being dumped there but I do see something about some of the "goroutines" being "525 minutes" old. This makes since because I went to sleep and about 8 hours later came back to the docker daemon being hung/stuck.

[krisives]

Also it's worth noting that attempting to docker stop the offending container doesn't do anything as any command that "touches" the container will not execute. The only way I have found to work around this is with a reboot or a docker service restart

[thaJeztah]

ping @crosbymichael @mlaventure PTAL

[b00lduck]

I have the same issue with 1.12.0 too.

"docker ps" hangs forever and "docker stop" etc. access via swarm hangs too.

The log is absolutely quiet about this.

strace docker ps

...snip...
epoll_ctl(4, EPOLL_CTL_ADD, 3, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=144861200, u64=140024668645392}}) = 0
getsockname(3, {sa_family=AF_LOCAL, NULL}, [2]) = 0
getpeername(3, {sa_family=AF_LOCAL, sun_path="/var/run/docker.sock"}, [23]) = 0
futex(0xc82002c908, FUTEX_WAKE, 1) = 1
read(3, 0xc82034e000, 4096) = -1 EAGAIN (Resource temporarily unavailable)
write(3, "GET /v1.24/containers/json HTTP/"..., 95) = 95
epoll_wait(4, [], 128, 0) = 0
futex(0x1326ca8, FUTEX_WAIT, 0, NULL

docker info

Containers: 11
Running: 4
Paused: 0
Stopped: 7
Images: 149
Server Version: 1.12.0
Storage Driver: aufs
Root Dir: /var/lib/docker/aufs
Backing Filesystem: extfs
Dirs: 849
Dirperm1 Supported: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
Volume: local
Network: overlay null bridge host
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Security Options: apparmor seccomp
Kernel Version: 4.4.0-31-generic
Operating System: Ubuntu 16.04.1 LTS
OSType: linux
Architecture: x86_64
CPUs: 8
Total Memory: 7.795 GiB
Name: content-1
ID: MHM7:O6J2:ACPA:6ZPU:SQY4:WFCG:DV7O:YJ5K:TLLL:MH5N:2GXZ:QRR2
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Labels:
nodetype=worker-content
provider=generic
Cluster Store: consul://172.17.0.1:8500
Cluster Advertise: 192.168.1.13:2376
Insecure Registries:
127.0.0.0/8

[thaJeztah]

@b00lduck that looks like a strace of the client; could you try to get a stacktrace of the daemon? See #25321 (comment)

[b00lduck]

The strace of the dockerd ist absolutely quiet here:

strace -p 2853 (which is dockerd)

strace: Process 2853 attached
futex(0x2a7cca8, FUTEX_WAIT, 0, NULL

even if i issue docker ps, nothing in the trace.

[thaJeztah]

I think if you send it USR1, if should out a stacktrace in the logs (but possibly "debug" must be enabled on the daemon)

[krisives]

kill -s USR1 1234

Where 1234 is the pic. Works for me on stock debian Jessie.

[krisives]

I added some sleep commands in between various docker commands and we have not had a problem for about 12 hours now.

[b00lduck]

Stacktrace attached
out.txt

[thaJeztah]

@krisives could you share what commands you put the sleep between?

[thaJeztah]

Thanks @b00lduck!

[thaJeztah]

@krisives (off topic) looking at your use-case; is there a reason you're logging to files inside the container, instead of logging to stdout, and making use of the docker logging features?

[rokkbert]

From b00lduck's stacktrace it seems that goroutine 7 is stuck while trying to connect to containerd, waiting for the connection to change it's idle state. Don't know if that indicates a problem with containerd or rather an RPC or network issue? There's other goroutines IO-waiting in grpc-code, but also some other places...

[mlaventure]

@b00lduck @krisives could you provide the associated daemon logs for those stacktraces? After a first read, I didn't notice anything peculiar about them, I'll go through them again though.

@rokkbert that goroutine is just here to handle drops in connection with containerd. It just waits for the connection status to changed to fail, in which case it will make sure to reconnect to containerd (restarting it if needed).

@chbatey the exec format error means that the kernel was asked to create a process with a binary that was not created for the current architecture (e.g. built for ARM)

[mlaventure]

@b00lduck on your stacktrace file, it looks like a container's lock was never released. There is several instance of docker ps that seems to be stuck on it, but not obvious routine that owns the lock. It's possible that that goroutine already returned without releasing it. If you can provide the daemon logs maybe I can pinpoint the command that was run before the first docker ps or docker rm that got stuck, that would help reduce the range of code that may be faulty.

@chbatey if you still have the daemon running, a stacktrace may be helpful too :)

Thanks,

[cpuguy83]

@mlaventure @b00lduck Looks like it's stuck leaving an overlay network while the container is locked:

goroutine 869 [chan send, 974 minutes]:
github.com/docker/libnetwork/drivers/overlay.(*driver).Leave(0xc8202c2b60, 0xc82122c380, 0x40, 0xc820c24600, 0x40, 0x0, 0x0)
    /usr/src/docker/vendor/src/github.com/docker/libnetwork/drivers/overlay/joinleave.go:216 +0x3ff
github.com/docker/libnetwork.(*endpoint).sbLeave(0xc820edba20, 0xc8201a03c0, 0xc8201a0300, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/src/docker/vendor/src/github.com/docker/libnetwork/endpoint.go:669 +0xba2
github.com/docker/libnetwork.(*endpoint).Leave(0xc82089f080, 0x7f7a40588f38, 0xc8201a03c0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/src/docker/vendor/src/github.com/docker/libnetwork/endpoint.go:619 +0x1ab
github.com/docker/libnetwork.(*sandbox).delete(0xc8201a03c0, 0xc820105f00, 0x0, 0x0)
    /usr/src/docker/vendor/src/github.com/docker/libnetwork/sandbox.go:216 +0xaff
github.com/docker/libnetwork.(*sandbox).Delete(0xc8201a03c0, 0x0, 0x0)
    /usr/src/docker/vendor/src/github.com/docker/libnetwork/sandbox.go:179 +0x32
github.com/docker/docker/daemon.(*Daemon).releaseNetwork(0xc820372000, 0xc820496d20)
    /usr/src/docker/.gopath/src/github.com/docker/docker/daemon/container_operations.go:758 +0x51c
github.com/docker/docker/daemon.(*Daemon).Cleanup(0xc820372000, 0xc820496d20)
    /usr/src/docker/.gopath/src/github.com/docker/docker/daemon/start.go:172 +0x53
github.com/docker/docker/daemon.(*Daemon).StateChanged(0xc820372000, 0xc820a2d200, 0x40, 0xc82130202c, 0x4, 0x8900000000, 0x0, 0x0, 0x0, 0x0, ...)
    /usr/src/docker/.gopath/src/github.com/docker/docker/daemon/monitor.go:41 +0x629
github.com/docker/docker/libcontainerd.(*container).handleEvent.func2()
    /usr/src/docker/.gopath/src/github.com/docker/docker/libcontainerd/container_linux.go:202 +0x9e
github.com/docker/docker/libcontainerd.(*queue).append.func1(0xc8208f3c00, 0x0, 0xc820e04d00, 0xc820ed8840)
    /usr/src/docker/.gopath/src/github.com/docker/docker/libcontainerd/queue_linux.go:26 +0x47
created by github.com/docker/docker/libcontainerd.(*queue).append
    /usr/src/docker/.gopath/src/github.com/docker/docker/libcontainerd/queue_linux.go:28 +0x1da

[cpuguy83]

ping @mavenugo

Looks like it's blocking on a channel send:

    if d.notifyCh != nil {
        d.notifyCh <- ovNotify{
            action: "leave",
            nw:     n,
            ep:     ep,
        }
    }

[mlaventure]

@cpuguy83 ah, correct the lock is taken here: https://github.com/docker/docker/blob/v1.12.0/daemon/monitor.go#L31

Thanks!

[cpuguy83]

Maybe @mrjana too, since I know madhu is travelling.

[krisives]

After adding the sleep command we have been running for 24+ hours without a docker hang. This could be because we are issuing less commands overall or because we never issue two commands within a short period of time.

@krisives could you share what commands you put the sleep between?

I am currently sleeping after any docker exec commands. The place where this might matter most is within a loop we had executing docker exec rm /var/log/foo.1 where now each command is separated by a second at least.

@krisives could you provide the associated daemon logs for those stacktraces? After a first read, I didn't notice anything peculiar about them, I'll go through them again though.

Yes here is everything up until the USR1 signal stack trace when it was hung:

https://gist.githubusercontent.com/krisives/4b9d3ff7c13877845c30aa31075d1bde/raw/820485b881f8ede98cf24d8569ea61b19d6267c6/daemon.log

@krisives (off topic) looking at your use-case; is there a reason you're logging to files inside the container, instead of logging to stdout, and making use of the docker logging features?

I am not a docker expert I just play one on TV. My next solution is to write a script which runs within the container itself and parses the logs and inserts it into the appropriate database tables. How could I get docker to output all of the logs to one file on the host?

[thaJeztah]

How could I get docker to output all of the logs to one file on the host?

To keep your "current" approach, you can bind-mount a directory on your host, and have the container write to that (-v /path/on/host/:/var/log/), that way, you don't have to exec into the container to access the log files.

However, that also doesn't use the docker logging features. To do that, make sure the container writes logs to stdout / stderr (which can be as simple as symlinking the file, if the process expects a file to write to; see for example the nginx Dockerfile). After that, you can use a suitable logging driver for your use case to, e.g., log to syslog, collect logs with GELF, or splunk (see the logging drivers section

(sorry all for the off topic - back to the issue at hand)

[danmelton]

Hi, we're having a similar issue across all of our docker machines that were recently upgraded to 1.12. I'll try to get get stack traces out tomorrow. docker ps and all docker compose commands now hang. Going to try to rollback to previous version of docker.

[vanthome]

Same issue here on Gentoo. One thing I read the same from a SuSE user.
He says he is using btrfs, but I'm using ext4.
I have sowngraded to 1.10 now which does not seem to have the issue.

[ryneeverett]

@vanthome You may be experiencing an openrc bug. I haven't dug deep enough to figure out the problem yet but downgrading openrc from 0.21.3 to 0.19.1 fixed the hanging issue for me.

[crosbymichael]

Is everyone experiencing this running extra processes with docker exec?

[kingfame]

I have the same issue. I'm not using "docker exec" at all. After running "/etc/init.d/docker start" I can't run a single docker command, even "docker version" is hung.

Version is "1.12.1_rc1 (Gentoo)".

Tried to downgrade to 1.11, same issue.

[mlaventure]

@kingfame Can you send a USR1 signal to the daemon and provide the daemon log?

Thanks

[ryneeverett]

Same issue here as @kingfame on gentoo -- no docker commands are responsive. The daemon doesn't respond to a USR1 signal. The daemon log gets to the "starting containers" bit during initialization and no further. As I said before, downgrading openrc somehow fixes it.

[kingfame]

I downgraded to openrc 0.19.1 without success, same issue.

Here is the output of the USR1 signal:

time="2016-08-22T20:49:00.942776695+02:00" level=info msg="=== BEGIN goroutine stack dump ===\ngoroutine 45 [running]:\ngithub.com/docker/docker/pkg/signal.DumpStacks()\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/pkg/signal/trap.go:74 +0x98\ngithub.com/docker/docker/daemon.setupDumpStackTrap.func1(0xc820403440)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/daemon/debugtrap_unix.go:18 +0x5e\ncreated by github.com/docker/docker/daemon.setupDumpStackTrap\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/daemon/debugtrap_unix.go:20 +0x13f\n\ngoroutine 1 [semacquire]:\nsync.runtime_Semacquire(0xc82015461c)\n\t/usr/lib/go/src/runtime/sema.go:47 +0x26\nsync.(*WaitGroup).Wait(0xc820154610)\n\t/usr/lib/go/src/sync/waitgroup.go:127 +0xb4\ngithub.com/docker/docker/daemon.(*Daemon).restore(0xc820433040, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/daemon/daemon.go:222 +0xa46\ngithub.com/docker/docker/daemon.NewDaemon(0xc820435180, 0x7f011d1c8c08, 0xc820406108, 0x7f011d1c4510, 0xc8203fd520, 0x0, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/daemon/daemon.go:605 +0x34aa\nmain.(*DaemonCli).start(0xc82040da70, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/cmd/dockerd/daemon.go:265 +0x1951\nmain.main()\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/cmd/dockerd/docker.go:68 +0x491\n\ngoroutine 17 [syscall, locked to thread]:\nruntime.goexit()\n\t/usr/lib/go/src/runtime/asm_amd64.s:1998 +0x1\n\ngoroutine 6 [syscall]:\nos/signal.signal_recv(0x7f011d242190)\n\t/usr/lib/go/src/runtime/sigqueue.go:116 +0x132\nos/signal.loop()\n\t/usr/lib/go/src/os/signal/signal_unix.go:22 +0x18\ncreated by os/signal.init.1\n\t/usr/lib/go/src/os/signal/signal_unix.go:28 +0x37\n\ngoroutine 34 [syscall]:\nsyscall.Syscall6(0x3d, 0x5f58, 0xc82002eddc, 0x0, 0xc820418870, 0x0, 0x0, 0x441ee1, 0x441ee1, 0xc820001eb8)\n\t/usr/lib/go/src/syscall/asm_linux_amd64.s:44 +0x5\nsyscall.wait4(0x5f58, 0xc82002eddc, 0x0, 0xc820418870, 0x90, 0x0, 0x0)\n\t/usr/lib/go/src/syscall/zsyscall_linux_amd64.go:172 +0x7f\nsyscall.Wait4(0x5f58, 0xc82002ee24, 0x0, 0xc820418870, 0x415b63, 0x0, 0x0)\n\t/usr/lib/go/src/syscall/syscall_linux.go:256 +0x55\nos.(*Process).wait(0xc8204589e0, 0xc820014080, 0x0, 0x0)\n\t/usr/lib/go/src/os/exec_unix.go:22 +0x105\nos.(*Process).Wait(0xc8204589e0, 0x0, 0x0, 0x0)\n\t/usr/lib/go/src/os/doc.go:49 +0x2d\nos/exec.(*Cmd).Wait(0xc820411cc0, 0x0, 0x0)\n\t/usr/lib/go/src/os/exec/exec.go:396 +0x211\ngithub.com/docker/docker/libcontainerd.(*remote).runContainerdDaemon.func1(0xc820411cc0, 0xc8203fd520)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/libcontainerd/remote_linux.go:418 +0x21\ncreated by github.com/docker/docker/libcontainerd.(*remote).runContainerdDaemon\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/libcontainerd/remote_linux.go:420 +0x12eb\n\ngoroutine 35 [select]:\ngoogle.golang.org/grpc.(*Conn).transportMonitor(0xc82041e0f0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/clientconn.go:544 +0x1d3\ngoogle.golang.org/grpc.NewConn.func1(0xc82041e0f0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/clientconn.go:355 +0x1b5\ncreated by google.golang.org/grpc.NewConn\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/clientconn.go:356 +0x4e3\n\ngoroutine 36 [semacquire]:\nsync.runtime_Syncsemacquire(0xc82045d1d0)\n\t/usr/lib/go/src/runtime/sema.go:241 +0x201\nsync.(*Cond).Wait(0xc82045d1c0)\n\t/usr/lib/go/src/sync/cond.go:63 +0x9b\ngoogle.golang.org/grpc.(*Conn).WaitForStateChange(0xc82041e0f0, 0x7f011d246940, 0xc8200106a8, 0x2, 0x0, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/clientconn.go:405 +0x19f\ngoogle.golang.org/grpc.(*unicastPicker).WaitForStateChange(0xc820458aa0, 0x7f011d246940, 0xc8200106a8, 0x2, 0x2044f40, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/picker.go:96 +0x4f\ngoogle.golang.org/grpc.(*ClientConn).WaitForStateChange(0xc820416370, 0x7f011d246940, 0xc8200106a8, 0x2, 0x1, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/clientconn.go:283 +0x6b\ngithub.com/docker/docker/libcontainerd.(*remote).handleConnectionChange(0xc8203fd520)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/libcontainerd/remote_linux.go:139 +0xb4\ncreated by github.com/docker/docker/libcontainerd.New\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/libcontainerd/remote_linux.go:117 +0xb42\n\ngoroutine 38 [IO wait]:\nnet.runtime_pollWait(0x7f011d1c42b8, 0x72, 0xc82047a000)\n\t/usr/lib/go/src/runtime/netpoll.go:160 +0x60\nnet.(*pollDesc).Wait(0xc820441bf0, 0x72, 0x0, 0x0)\n\t/usr/lib/go/src/net/fd_poll_runtime.go:73 +0x3a\nnet.(*pollDesc).WaitRead(0xc820441bf0, 0x0, 0x0)\n\t/usr/lib/go/src/net/fd_poll_runtime.go:78 +0x36\nnet.(*netFD).Read(0xc820441b90, 0xc82047a000, 0x8000, 0x8000, 0x0, 0x7f011d242168, 0xc820010048)\n\t/usr/lib/go/src/net/fd_unix.go:250 +0x23a\nnet.(*conn).Read(0xc820406140, 0xc82047a000, 0x8000, 0x8000, 0x0, 0x0, 0x0)\n\t/usr/lib/go/src/net/net.go:172 +0xe4\nbufio.(*Reader).fill(0xc820403020)\n\t/usr/lib/go/src/bufio/bufio.go:97 +0x1e9\nbufio.(*Reader).Read(0xc820403020, 0xc820422338, 0x9, 0x9, 0xc8202287d8, 0x0, 0x0)\n\t/usr/lib/go/src/bufio/bufio.go:207 +0x260\nio.ReadAtLeast(0x7f011d1c8870, 0xc820403020, 0xc820422338, 0x9, 0x9, 0x9, 0x0, 0x0, 0x0)\n\t/usr/lib/go/src/io/io.go:297 +0xe6\nio.ReadFull(0x7f011d1c8870, 0xc820403020, 0xc820422338, 0x9, 0x9, 0xc8202d08d8, 0x0, 0x0)\n\t/usr/lib/go/src/io/io.go:315 +0x62\ngolang.org/x/net/http2.readFrameHeader(0xc820422338, 0x9, 0x9, 0x7f011d1c8870, 0xc820403020, 0x2000000, 0x7f0100000000, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/golang.org/x/net/http2/frame.go:236 +0xa5\ngolang.org/x/net/http2.(*Framer).ReadFrame(0xc820422300, 0x0, 0x0, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/golang.org/x/net/http2/frame.go:463 +0x106\ngoogle.golang.org/grpc/transport.(*framer).readFrame(0xc82045e1e0, 0x0, 0x0, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/transport/http_util.go:406 +0x3d\ngoogle.golang.org/grpc/transport.(*http2Client).reader(0xc82041e1e0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/transport/http2_client.go:788 +0x109\ncreated by google.golang.org/grpc/transport.newHTTP2Client\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/transport/http2_client.go:174 +0xd21\n\ngoroutine 39 [select]:\ngoogle.golang.org/grpc/transport.(*http2Client).controller(0xc82041e1e0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/transport/http2_client.go:866 +0x5da\ncreated by google.golang.org/grpc/transport.newHTTP2Client\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/transport/http2_client.go:201 +0x15c2\n\ngoroutine 41 [select]:\ngoogle.golang.org/grpc.NewClientStream.func1(0x7f011d1c88c0, 0xc82041e1e0, 0xc820420540, 0xc820450460)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/stream.go:151 +0x258\ncreated by google.golang.org/grpc.NewClientStream\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/stream.go:159 +0xab2\n\ngoroutine 42 [select]:\ngoogle.golang.org/grpc/transport.(*recvBufferReader).Read(0xc82045e330, 0xc820458cb0, 0x5, 0x5, 0x0, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/transport/transport.go:141 +0x7e6\ngoogle.golang.org/grpc/transport.(*Stream).Read(0xc820420540, 0xc820458cb0, 0x5, 0x5, 0x0, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/transport/transport.go:294 +0x71\nio.ReadAtLeast(0x7f011d1c8a60, 0xc820420540, 0xc820458cb0, 0x5, 0x5, 0x5, 0x0, 0x0, 0x0)\n\t/usr/lib/go/src/io/io.go:297 +0xe6\nio.ReadFull(0x7f011d1c8a60, 0xc820420540, 0xc820458cb0, 0x5, 0x5, 0x0, 0x0, 0x0)\n\t/usr/lib/go/src/io/io.go:315 +0x62\ngoogle.golang.org/grpc.(*parser).recvMsg(0xc820458ca0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/rpc_util.go:216 +0xb9\ngoogle.golang.org/grpc.recv(0xc820458ca0, 0x7f011d1c45c0, 0x2ad4780, 0xc820420540, 0x0, 0x0, 0x1bb82e0, 0xc82032d780, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/rpc_util.go:300 +0x45\ngoogle.golang.org/grpc.(*clientStream).RecvMsg(0xc820450460, 0x1bb82e0, 0xc82032d780, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/stream.go:234 +0xac\ngithub.com/docker/containerd/api/grpc/types.(*aPIEventsClient).Recv(0xc82044d100, 0x0, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/github.com/docker/containerd/api/grpc/types/api.pb.go:1032 +0x7e\ngithub.com/docker/docker/libcontainerd.(*remote).handleEventStream(0xc8203fd520, 0x7f011d1c8bb0, 0xc82044d100)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/libcontainerd/remote_linux.go:286 +0x64\ncreated by github.com/docker/docker/libcontainerd.(*remote).startEventsMonitor\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/libcontainerd/remote_linux.go:280 +0x2db\n\ngoroutine 43 [select, locked to thread]:\nruntime.gopark(0x2197e88, 0xc820494728, 0x1d84eb8, 0x6, 0x18, 0x2)\n\t/usr/lib/go/src/runtime/proc.go:262 +0x163\nruntime.selectgoImpl(0xc820494728, 0x0, 0x18)\n\t/usr/lib/go/src/runtime/select.go:392 +0xa67\nruntime.selectgo(0xc820494728)\n\t/usr/lib/go/src/runtime/select.go:215 +0x12\nruntime.ensureSigM.func1()\n\t/usr/lib/go/src/runtime/signal1_unix.go:279 +0x358\nruntime.goexit()\n\t/usr/lib/go/src/runtime/asm_amd64.s:1998 +0x1\n\ngoroutine 44 [chan receive]:\ngithub.com/docker/docker/pkg/signal.Trap.func1(0xc8204032c0, 0xc820458d80)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/pkg/signal/trap.go:32 +0x71\ncreated by github.com/docker/docker/pkg/signal.Trap\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/pkg/signal/trap.go:62 +0x2be\n\ngoroutine 107 [select]:\ngoogle.golang.org/grpc.(*Conn).WaitForStateChange.func1(0x7f011d246940, 0xc8200106a8, 0xc82041e0f0, 0xc820154790, 0xc820228ae0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/clientconn.go:394 +0x1b1\ncreated by google.golang.org/grpc.(*Conn).WaitForStateChange\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/clientconn.go:402 +0x14e\n\ngoroutine 106 [select]:\ngoogle.golang.org/grpc.NewClientStream.func1(0x7f011d1c88c0, 0xc82041e1e0, 0xc8204201c0, 0xc820291d60)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/stream.go:151 +0x258\ncreated by google.golang.org/grpc.NewClientStream\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/stream.go:159 +0xab2\n\ngoroutine 100 [select]:\ngoogle.golang.org/grpc/transport.(*recvBufferReader).Read(0xc8202d0ba0, 0xc8200ecc10, 0x5, 0x5, 0x0, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/transport/transport.go:141 +0x7e6\ngoogle.golang.org/grpc/transport.(*Stream).Read(0xc8204201c0, 0xc8200ecc10, 0x5, 0x5, 0x100000000, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/transport/transport.go:294 +0x71\nio.ReadAtLeast(0x7f011d1c8a60, 0xc8204201c0, 0xc8200ecc10, 0x5, 0x5, 0x5, 0x0, 0x0, 0x0)\n\t/usr/lib/go/src/io/io.go:297 +0xe6\nio.ReadFull(0x7f011d1c8a60, 0xc8204201c0, 0xc8200ecc10, 0x5, 0x5, 0x0, 0x0, 0x0)\n\t/usr/lib/go/src/io/io.go:315 +0x62\ngoogle.golang.org/grpc.(*parser).recvMsg(0xc8200ecc00, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/rpc_util.go:216 +0xb9\ngoogle.golang.org/grpc.recv(0xc8200ecc00, 0x7f011d1c45c0, 0x2ad4780, 0xc8204201c0, 0x0, 0x0, 0x1bb82e0, 0xc82026ad00, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/rpc_util.go:300 +0x45\ngoogle.golang.org/grpc.(*clientStream).RecvMsg(0xc820291d60, 0x1bb82e0, 0xc82026ad00, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/google.golang.org/grpc/stream.go:234 +0xac\ngithub.com/docker/containerd/api/grpc/types.(*aPIEventsClient).Recv(0xc820154750, 0x7f011d246940, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/vendor/src/github.com/docker/containerd/api/grpc/types/api.pb.go:1032 +0x7e\ngithub.com/docker/docker/libcontainerd.(*client).getContainerLastEventSinceTime(0xc820402840, 0xc8202a5a00, 0x40, 0xc82044cfc0, 0x7f011d246940, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/libcontainerd/client_linux.go:470 +0x37e\ngithub.com/docker/docker/libcontainerd.(*client).getContainerLastEvent(0xc820402840, 0xc8202a5a00, 0x40, 0x0, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/libcontainerd/client_linux.go:491 +0x6c\ngithub.com/docker/docker/libcontainerd.(*client).Restore(0xc820402840, 0xc8202a5a00, 0x40, 0xc820154630, 0x1, 0x1, 0x0, 0x0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/libcontainerd/client_linux.go:527 +0x12f\ngithub.com/docker/docker/daemon.(*Daemon).restore.func1(0xc820154610, 0xc820433040, 0xc820154368, 0xc8202d0870, 0xc8202d0840, 0xc820154360, 0xc820293860)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/daemon/daemon.go:178 +0x6f6\ncreated by github.com/docker/docker/daemon.(*Daemon).restore\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/daemon/daemon.go:220 +0xa11\n\ngoroutine 99 [chan receive]:\ngithub.com/docker/docker/daemon.(*Daemon).execCommandGC(0xc820433040)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/daemon/exec.go:237 +0x87\ncreated by github.com/docker/docker/daemon.NewDaemon\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/daemon/daemon.go:598 +0x339c\n\ngoroutine 98 [chan receive]:\ngithub.com/docker/docker/daemon.(*statsCollector).run(0xc8202a4bc0)\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/daemon/stats_collector_unix.go:106 +0xb6\ncreated by github.com/docker/docker/daemon.(*Daemon).newStatsCollector\n\t/var/tmp/portage/app-emulation/docker-1.12.1_rc1/work/docker-1.12.1_rc1/src/github.com/docker/docker/daemon/stats_collector_unix.go:44 +0x1f1\n\n=== END goroutine stack dump ==="

[mlaventure]

@kingfame your issue is different.

docker is stuck waiting for events from containerd.

What version of containerd are you running?

Could you provide containerd logs?

[kingfame]

Containerd isn't installed, and doesn't seems to be a dependency regarding to the gentoo packet manager (portage/emerge).

I guess I should install it o0

EDIT: Sorry for the noise. This seems to be a gentoo bug, where it is not pulling in containerd. After I installed containerd docker seems to be working again.

[mlaventure]

@kingfame If gentoo uses our package format, containerd would be called docker-containerd

EDIT: ah, glad to see it fixed it :)

[ryneeverett]

@kingfame The atom is "app-emulation/containerd" and it is in fact a runtime dependency.

[krisives]

Running with storage driver overlay has solved this problem for us currently. Previously we used the out-of-the-box on Debian of devicemapper. My suggestion is try overlay if you are experiencing this issue.

[mlaventure]

Several issues are now part of this thread:

• @kingfame issue was a packaging error and seemed to be fixed
• @krisives issue is mitigated by them moving to overlay for now
• @b00lduck issue seems to be caused by a deadlock in libnetwork.
• @chbatey issue I will assume is the same as the above once since we lack more information.

I've created #26459 to keep track of the deadlock and am thus closing this thread in favor of the new issue for easier tracking.

[beedub]

@mlaventure is my issue (#25321 (comment)) documented as well?

[mlaventure]

@beedub I'll take a look today, thanks for the ping!

[mlaventure]

@beedub can you confirm what issue you are seeing?

Are you having the daemon being hung or something else?

[beedub]

@mlaventure daemon hung as far as I remember

[sakserv]

We appear to be encountering similar after moving to docker 1.12.2. Restarting docker appears to be the only way to recover.

We are using an lvm thinpool devicemapper setup leveraging xfs and unfortunately, overlay is not very stable on Centos 7.2 so making that move is not currently an option. Doing so would be quite disruptive to existing workloads as well.

Here is the stack trace from dockerd:
https://gist.github.com/sakserv/6aa7c7a1a8eac147e27d8c060023a36d

Docker info (note that even docker info hangs in my case):

Containers: 105
 Running: 19
 Paused: 0
 Stopped: 86
Images: 108
Server Version: 1.12.2
Storage Driver: devicemapper
 Pool Name: vg01-docker--pool
 Pool Blocksize: 524.3 kB
 Base Device Size: 274.9 GB
 Backing Filesystem: xfs
 Data file:
 Metadata file:
 Data Space Used: 853.2 GB
 Data Space Total: 5.63 TB
 Data Space Available: 4.777 TB
 Metadata Space Used: 105.9 MB
 Metadata Space Total: 16.98 GB
 Metadata Space Available: 16.87 GB
 Thin Pool Minimum Free Space: 563 GB
 Udev Sync Supported: true
 Deferred Removal Enabled: false
 Deferred Deletion Enabled: false
 Deferred Deleted Device Count: 0
 Library Version: 1.02.107-RHEL7 (2015-12-01)
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: host null overlay bridge
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Security Options: seccomp
Kernel Version: 3.10.0-327.13.1.el7.x86_64
Operating System: CentOS Linux 7 (Core)
OSType: linux
Architecture: x86_64
CPUs: 32
Total Memory: 251.6 GiB
Name: foo.example.com
ID: OSYP:WEPA:N2LF:KFTJ:BZNP:L3PT:LDNV:4OBJ:A4AM:CWFB:HHIK:WN4M
Docker Root Dir: /grid/0/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
WARNING: bridge-nf-call-iptables is disabled
WARNING: bridge-nf-call-ip6tables is disabled
Insecure Registries:
 127.0.0.0/8

Docker client strace:

-snip-
etpeername(4, {sa_family=AF_LOCAL, sun_path="/var/run/docker.sock"}, [23]) = 0
futex(0xc82004a908, FUTEX_WAKE, 1)      = 1
read(4, 0xc820327000, 4096)             = -1 EAGAIN (Resource temporarily unavailable)
write(4, "GET /v1.24/info HTTP/1.1\r\nHost: "..., 84) = 84
epoll_wait(5, {}, 128, 0)               = 0
futex(0x132cca8, FUTEX_WAIT, 0, NULL

dockerd strace:

Process 850182 attached
wait4(850188,

docker-containerd (pid 850188) strace:

Process 850188 attached
futex(0xee44c8, FUTEX_WAIT, 0, NULL

[thaJeztah]

@sakserv could you open a new issue? "daemon hang" can have many causes, and I'd like to prevent having possibly unrelated issue to be in the same issue on GitHub. Also, may be worth updating to 1.12.3, because there are some deadlocks fixed in that version; https://github.com/docker/docker/releases/tag/v1.12.3

[sakserv]

@thaJeztah - sure, I will open a new issue.