Docker hangs after a few minutes

saponace · 2019-03-19 23:03:05

Hi everyone,

I run all the services on my home server on docker.
I made a script to install everything on the server from scratch.
Two weeks ago I decided everything was ready for a first "release", do wiped out my test server and ran the script on it.

I face an issue I had never encountered while working on the script (and having the server running for days straight): Docker hangs.
It happens randomly after some time (a few minutes to an hour or more; the more containers started, the faster it enters the hung state), it is not tied to a given container (it will sometimes hang for a container, and sometimes not for a set of containers including the one that previously failed).
I've noticed most of the times it hangs, top shows two processes called "dmcrypt_write/2" "at 45% of CPU, iowait (some containers have volumes mapped to LUKS encrypted disks: LUKS+ext4 and LUKS+btrfs). These processes PPID is 1.

It seems like the containers causing an issue are containers that have volumes mapped to the LUKS encrypted drives.
When I say "docker hangs" I mean I can't call most docker commands on some containers (docker-compose up/down/start/stop and docker start/stop on these containers, systemctl stop docker), but some others like docker ps work, or docker-compose up/down/start/stop and docker start/stop on other containers will work. Any connection to these failed containers will induce a timeout, while others work perfectly.

My issue is I have no idea what to look for. I've been going from dead-end to dead-end for the past ten days, it's driving me crazy.

Do you have any idea in what direction I could go ?

Here is docker info:

 
Containers: 7
 Running: 1
 Paused: 0
 Stopped: 6
Images: 26
Server Version: 18.09.3-ce
Storage Driver: overlay2
 Backing Filesystem: extfs
 Supports d_type: true
 Native Overlay Diff: false
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host 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: bb71b10fd8f58240ca47fbb579b9d1028eea7c84.m
runc version: ccb5efd37fb7c86364786e9137e22948751de7ed-dirty
init version: fec3683
Security Options:
 seccomp
  Profile: default
Kernel Version: 5.0.1-arch1-1-ARCH
Operating System: Arch Linux
OSType: linux
Architecture: x86_64
CPUs: 12
Total Memory: 15.66GiB
Name: tartiflette
ID: XSXS:EVKL:B7BJ:T74U:C5CW:GNJ6:SFL7:GPKY:MLRX:7JC6:UGY4:TBDW
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Labels:
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

And here is the journal of the docker unit after I called docker stop while hung:

Mar 19 22:08:14 tartiflette systemd[1]: Stopping Docker Application Container Engine...
Mar 19 22:08:14 tartiflette dockerd[653]: time="2019-03-19T22:08:14.559932966+01:00" level=info msg="shim reaped" id=e988095c47d0fc95b4d6d5172c8e5d1fd28b8adeee86c952b266817a4978b11f
Mar 19 22:08:14 tartiflette dockerd[653]: time="2019-03-19T22:08:14.569798321+01:00" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Mar 19 22:08:17 tartiflette dockerd[653]: time="2019-03-19T22:08:17.875107894+01:00" level=info msg="shim reaped" id=50e4adc459efb80446616fa132ced51c046136698418a6d7dc726c8339f4fbc6
Mar 19 22:08:17 tartiflette dockerd[653]: time="2019-03-19T22:08:17.884836933+01:00" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Mar 19 22:08:18 tartiflette dockerd[653]: time="2019-03-19T22:08:18.587153024+01:00" level=error msg="[resolver] invalid concurrent query count"
Mar 19 22:08:24 tartiflette dockerd[653]: time="2019-03-19T22:08:24.441324623+01:00" level=info msg="Container af08ff30c7d6ddbbea28803aa1822087753cd16a1e54f3bfe4eb9859cdf92481 failed to exit within 10 seconds of signal 15 - using the force"
Mar 19 22:08:24 tartiflette dockerd[653]: time="2019-03-19T22:08:24.443907137+01:00" level=info msg="Container c70b579e7629735fbb8fe581d4593bf27f4d3f76daf0770f9691625948314ce7 failed to exit within 10 seconds of signal 15 - using the force"
Mar 19 22:08:24 tartiflette dockerd[653]: time="2019-03-19T22:08:24.505961081+01:00" level=info msg="shim reaped" id=af08ff30c7d6ddbbea28803aa1822087753cd16a1e54f3bfe4eb9859cdf92481
Mar 19 22:08:24 tartiflette dockerd[653]: time="2019-03-19T22:08:24.515616872+01:00" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Mar 19 22:08:29 tartiflette dockerd[653]: time="2019-03-19T22:08:29.430097508+01:00" level=error msg="Force shutdown daemon"
Mar 19 22:08:29 tartiflette dockerd[653]: time="2019-03-19T22:08:29.430153774+01:00" level=info msg="stopping healthcheck following graceful shutdown" module=libcontainerd
Mar 19 22:08:29 tartiflette dockerd[653]: time="2019-03-19T22:08:29.430177478+01:00" level=info msg="stopping event stream following graceful shutdown" error="context canceled" module=libcontainerd namespace=plugins.moby
Mar 19 22:08:29 tartiflette dockerd[653]: time="2019-03-19T22:08:29.430186094+01:00" level=info msg="stopping event stream following graceful shutdown" error="context canceled" module=libcontainerd namespace=moby
Mar 19 22:08:29 tartiflette dockerd[653]: time="2019-03-19T22:08:29.430368737+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00007ffa0, TRANSIENT_FAILURE" module=grpc
Mar 19 22:08:29 tartiflette dockerd[653]: time="2019-03-19T22:08:29.430401879+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00007ffa0, CONNECTING" module=grpc
Mar 19 22:08:29 tartiflette dockerd[653]: time="2019-03-19T22:08:29.430358027+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00013e590, TRANSIENT_FAILURE" module=grpc
Mar 19 22:08:29 tartiflette dockerd[653]: time="2019-03-19T22:08:29.430435662+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00013e590, CONNECTING" module=grpc
Mar 19 22:09:44 tartiflette systemd[1]: docker.service: State 'stop-sigterm' timed out. Killing.
Mar 19 22:09:44 tartiflette systemd[1]: docker.service: Killing process 653 (dockerd) with signal SIGKILL.
Mar 19 22:11:14 tartiflette systemd[1]: docker.service: Processes still around after SIGKILL. Ignoring.
Mar 19 22:12:45 tartiflette systemd[1]: docker.service: State 'stop-final-sigterm' timed out. Killing.
Mar 19 22:12:45 tartiflette systemd[1]: docker.service: Killing process 653 (dockerd) with signal SIGKILL.
Mar 19 22:14:15 tartiflette systemd[1]: docker.service: Processes still around after final SIGKILL. Entering failed mode.
Mar 19 22:14:15 tartiflette systemd[1]: docker.service: Failed with result 'timeout'.
Mar 19 22:14:15 tartiflette systemd[1]: Stopped Docker Application Container Engine.
Mar 19 22:14:15 tartiflette systemd[1]: docker.service: Found left-over process 1683 (containerd-shim) in control group while starting unit. Ignoring.
Mar 19 22:14:15 tartiflette systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 19 22:14:15 tartiflette systemd[1]: docker.service: Found left-over process 11679 (s6-sync) in control group while starting unit. Ignoring.
Mar 19 22:14:15 tartiflette systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 19 22:14:15 tartiflette systemd[1]: Starting Docker Application Container Engine...
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.422336039+01:00" level=info msg="libcontainerd: started new containerd process" pid=11840
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.422418644+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.422440245+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.422498173+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/containerd.sock 0  <nil>}]" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.422523501+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.422579566+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00013b6e0, CONNECTING" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.441740135+01:00" level=info msg="starting containerd" revision=bb71b10fd8f58240ca47fbb579b9d1028eea7c84.m version=v1.2.5.m
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.442002237+01:00" level=info msg="loading plugin "io.containerd.content.v1.content"..." type=io.containerd.content.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.442023937+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.btrfs"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.442180371+01:00" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.btrfs" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.btrfs must be a btrfs filesystem to be used with the btrfs snapshotter"
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.442191692+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.aufs"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443283921+01:00" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.aufs" error="modprobe aufs failed: "modprobe: FATAL: Module aufs not found in directory /lib/modules/5.0.1-arch1-1-ARCH\n": exit status 1"
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443310981+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.native"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443340046+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.overlayfs"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443403014+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.zfs"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443667941+01:00" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.zfs" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.zfs must be a zfs filesystem to be used with the zfs snapshotter"
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443680104+01:00" level=info msg="loading plugin "io.containerd.metadata.v1.bolt"..." type=io.containerd.metadata.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443696955+01:00" level=warning msg="could not use snapshotter btrfs in metadata plugin" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.btrfs must be a btrfs filesystem to be used with the btrfs snapshotter"
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443705832+01:00" level=warning msg="could not use snapshotter aufs in metadata plugin" error="modprobe aufs failed: "modprobe: FATAL: Module aufs not found in directory /lib/modules/5.0.1-arch1-1-ARCH\n": exit status 1"
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443713166+01:00" level=warning msg="could not use snapshotter zfs in metadata plugin" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.zfs must be a zfs filesystem to be used with the zfs snapshotter"
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443831448+01:00" level=info msg="loading plugin "io.containerd.differ.v1.walking"..." type=io.containerd.differ.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443849552+01:00" level=info msg="loading plugin "io.containerd.gc.v1.scheduler"..." type=io.containerd.gc.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443874999+01:00" level=info msg="loading plugin "io.containerd.service.v1.containers-service"..." type=io.containerd.service.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443888314+01:00" level=info msg="loading plugin "io.containerd.service.v1.content-service"..." type=io.containerd.service.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443898954+01:00" level=info msg="loading plugin "io.containerd.service.v1.diff-service"..." type=io.containerd.service.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443910666+01:00" level=info msg="loading plugin "io.containerd.service.v1.images-service"..." type=io.containerd.service.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443922489+01:00" level=info msg="loading plugin "io.containerd.service.v1.leases-service"..." type=io.containerd.service.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443934251+01:00" level=info msg="loading plugin "io.containerd.service.v1.namespaces-service"..." type=io.containerd.service.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443946133+01:00" level=info msg="loading plugin "io.containerd.service.v1.snapshots-service"..." type=io.containerd.service.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.443957494+01:00" level=info msg="loading plugin "io.containerd.runtime.v1.linux"..." type=io.containerd.runtime.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.445658255+01:00" level=info msg="loading plugin "io.containerd.runtime.v2.task"..." type=io.containerd.runtime.v2
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.445701355+01:00" level=info msg="loading plugin "io.containerd.monitor.v1.cgroups"..." type=io.containerd.monitor.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446033839+01:00" level=info msg="loading plugin "io.containerd.service.v1.tasks-service"..." type=io.containerd.service.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446116715+01:00" level=info msg="loading plugin "io.containerd.internal.v1.restart"..." type=io.containerd.internal.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446151991+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.containers"..." type=io.containerd.grpc.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446166418+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.content"..." type=io.containerd.grpc.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446177579+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.diff"..." type=io.containerd.grpc.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446187748+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.events"..." type=io.containerd.grpc.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446197787+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.healthcheck"..." type=io.containerd.grpc.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446208447+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.images"..." type=io.containerd.grpc.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446218616+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.leases"..." type=io.containerd.grpc.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446232141+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.namespaces"..." type=io.containerd.grpc.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446244344+01:00" level=info msg="loading plugin "io.containerd.internal.v1.opt"..." type=io.containerd.internal.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446273609+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.snapshots"..." type=io.containerd.grpc.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446287755+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.tasks"..." type=io.containerd.grpc.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446300249+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.version"..." type=io.containerd.grpc.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446310839+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.introspection"..." type=io.containerd.grpc.v1
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446446744+01:00" level=info msg=serving... address="/var/run/docker/containerd/containerd-debug.sock"
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446485256+01:00" level=info msg=serving... address="/var/run/docker/containerd/containerd.sock"
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.446498641+01:00" level=info msg="containerd successfully booted in 0.005200s"
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.453015604+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00013b6e0, READY" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.455664823+01:00" level=info msg="systemd-resolved is running, so using resolvconf: /run/systemd/resolve/resolv.conf"
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.456085122+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.456097455+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.456126830+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.456136428+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.456191000+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/containerd.sock 0  <nil>}]" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.456202532+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/containerd.sock 0  <nil>}]" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.456219694+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.456253137+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0008dd250, CONNECTING" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.456216228+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.456326825+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00013ba90, CONNECTING" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.456350860+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0008dd250, READY" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.456442502+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00013ba90, READY" module=grpc
Mar 19 22:14:15 tartiflette dockerd[11824]: time="2019-03-19T22:14:15.457932567+01:00" level=info msg="[graphdriver] using prior storage driver: overlay2"
Mar 19 22:14:16 tartiflette dockerd[11824]: time="2019-03-19T22:14:16.429331996+01:00" level=info msg="stopping healthcheck following graceful shutdown" module=libcontainerd
Mar 19 22:14:16 tartiflette dockerd[11824]: time="2019-03-19T22:14:16.429333328+01:00" level=info msg="stopping event stream following graceful shutdown" error="context canceled" module=libcontainerd namespace=plugins.moby
Mar 19 22:14:16 tartiflette dockerd[11824]: time="2019-03-19T22:14:16.429729471+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0008dd250, TRANSIENT_FAILURE" module=grpc
Mar 19 22:14:16 tartiflette dockerd[11824]: time="2019-03-19T22:14:16.429809341+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0008dd250, CONNECTING" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11824]: Error starting daemon: error while opening volume store metadata database: timeout
Mar 19 22:14:17 tartiflette systemd[1]: docker.service: Main process exited, code=exited, status=1/FAILURE
Mar 19 22:14:17 tartiflette systemd[1]: docker.service: Failed with result 'exit-code'.
Mar 19 22:14:17 tartiflette systemd[1]: Failed to start Docker Application Container Engine.
Mar 19 22:14:17 tartiflette systemd[1]: docker.service: Service RestartSec=100ms expired, scheduling restart.
Mar 19 22:14:17 tartiflette systemd[1]: docker.service: Scheduled restart job, restart counter is at 1.
Mar 19 22:14:17 tartiflette systemd[1]: Stopped Docker Application Container Engine.
Mar 19 22:14:17 tartiflette systemd[1]: docker.service: Found left-over process 1683 (containerd-shim) in control group while starting unit. Ignoring.
Mar 19 22:14:17 tartiflette systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 19 22:14:17 tartiflette systemd[1]: docker.service: Found left-over process 11679 (s6-sync) in control group while starting unit. Ignoring.
Mar 19 22:14:17 tartiflette systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 19 22:14:17 tartiflette systemd[1]: Starting Docker Application Container Engine...
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.670581321+01:00" level=info msg="libcontainerd: started new containerd process" pid=11879
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.670637336+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.670646343+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.670680016+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/containerd.sock 0  <nil>}]" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.670692600+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.670729619+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00007fec0, CONNECTING" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.686304002+01:00" level=info msg="starting containerd" revision=bb71b10fd8f58240ca47fbb579b9d1028eea7c84.m version=v1.2.5.m
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.686611118+01:00" level=info msg="loading plugin "io.containerd.content.v1.content"..." type=io.containerd.content.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.686634372+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.btrfs"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.686837472+01:00" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.btrfs" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.btrfs must be a btrfs filesystem to be used with the btrfs snapshotter"
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.686855076+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.aufs"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.687935943+01:00" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.aufs" error="modprobe aufs failed: "modprobe: FATAL: Module aufs not found in directory /lib/modules/5.0.1-arch1-1-ARCH\n": exit status 1"
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.687950881+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.native"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.687975728+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.overlayfs"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688027324+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.zfs"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688228923+01:00" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.zfs" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.zfs must be a zfs filesystem to be used with the zfs snapshotter"
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688242338+01:00" level=info msg="loading plugin "io.containerd.metadata.v1.bolt"..." type=io.containerd.metadata.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688255322+01:00" level=warning msg="could not use snapshotter zfs in metadata plugin" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.zfs must be a zfs filesystem to be used with the zfs snapshotter"
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688261584+01:00" level=warning msg="could not use snapshotter btrfs in metadata plugin" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.btrfs must be a btrfs filesystem to be used with the btrfs snapshotter"
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688267735+01:00" level=warning msg="could not use snapshotter aufs in metadata plugin" error="modprobe aufs failed: "modprobe: FATAL: Module aufs not found in directory /lib/modules/5.0.1-arch1-1-ARCH\n": exit status 1"
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688376469+01:00" level=info msg="loading plugin "io.containerd.differ.v1.walking"..." type=io.containerd.differ.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688394253+01:00" level=info msg="loading plugin "io.containerd.gc.v1.scheduler"..." type=io.containerd.gc.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688423167+01:00" level=info msg="loading plugin "io.containerd.service.v1.containers-service"..." type=io.containerd.service.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688438195+01:00" level=info msg="loading plugin "io.containerd.service.v1.content-service"..." type=io.containerd.service.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688452923+01:00" level=info msg="loading plugin "io.containerd.service.v1.diff-service"..." type=io.containerd.service.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688467310+01:00" level=info msg="loading plugin "io.containerd.service.v1.images-service"..." type=io.containerd.service.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688479663+01:00" level=info msg="loading plugin "io.containerd.service.v1.leases-service"..." type=io.containerd.service.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688492176+01:00" level=info msg="loading plugin "io.containerd.service.v1.namespaces-service"..." type=io.containerd.service.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688504009+01:00" level=info msg="loading plugin "io.containerd.service.v1.snapshots-service"..." type=io.containerd.service.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.688515751+01:00" level=info msg="loading plugin "io.containerd.runtime.v1.linux"..." type=io.containerd.runtime.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.690222161+01:00" level=info msg="loading plugin "io.containerd.runtime.v2.task"..." type=io.containerd.runtime.v2
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.690265352+01:00" level=info msg="loading plugin "io.containerd.monitor.v1.cgroups"..." type=io.containerd.monitor.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.690790167+01:00" level=info msg="loading plugin "io.containerd.service.v1.tasks-service"..." type=io.containerd.service.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.690929037+01:00" level=info msg="loading plugin "io.containerd.internal.v1.restart"..." type=io.containerd.internal.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691007765+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.containers"..." type=io.containerd.grpc.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691033012+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.content"..." type=io.containerd.grpc.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691058871+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.diff"..." type=io.containerd.grpc.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691082756+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.events"..." type=io.containerd.grpc.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691103114+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.healthcheck"..." type=io.containerd.grpc.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691124374+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.images"..." type=io.containerd.grpc.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691145002+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.leases"..." type=io.containerd.grpc.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691165391+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.namespaces"..." type=io.containerd.grpc.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691186861+01:00" level=info msg="loading plugin "io.containerd.internal.v1.opt"..." type=io.containerd.internal.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691231244+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.snapshots"..." type=io.containerd.grpc.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691256321+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.tasks"..." type=io.containerd.grpc.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691278032+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.version"..." type=io.containerd.grpc.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691304802+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.introspection"..." type=io.containerd.grpc.v1
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691592031+01:00" level=info msg=serving... address="/var/run/docker/containerd/containerd-debug.sock"
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691661581+01:00" level=info msg=serving... address="/var/run/docker/containerd/containerd.sock"
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.691692309+01:00" level=info msg="containerd successfully booted in 0.005891s"
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.701177851+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00007fec0, READY" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.703913041+01:00" level=info msg="systemd-resolved is running, so using resolvconf: /run/systemd/resolve/resolv.conf"
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.704356854+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.704372643+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.704401077+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.704409813+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.704439779+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/containerd.sock 0  <nil>}]" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.704454958+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.704448947+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/containerd.sock 0  <nil>}]" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.704485074+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.704526231+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc000706550, CONNECTING" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.704492128+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00079d220, CONNECTING" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.705038152+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00079d220, READY" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.705507422+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc000706550, READY" module=grpc
Mar 19 22:14:17 tartiflette dockerd[11866]: time="2019-03-19T22:14:17.707205427+01:00" level=info msg="[graphdriver] using prior storage driver: overlay2"
Mar 19 22:14:18 tartiflette dockerd[11866]: time="2019-03-19T22:14:18.679581307+01:00" level=info msg="stopping healthcheck following graceful shutdown" module=libcontainerd
Mar 19 22:14:18 tartiflette dockerd[11866]: time="2019-03-19T22:14:18.679601395+01:00" level=info msg="stopping event stream following graceful shutdown" error="context canceled" module=libcontainerd namespace=plugins.moby
Mar 19 22:14:18 tartiflette dockerd[11866]: time="2019-03-19T22:14:18.679813553+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00079d220, TRANSIENT_FAILURE" module=grpc
Mar 19 22:14:18 tartiflette dockerd[11866]: time="2019-03-19T22:14:18.679853057+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc00079d220, CONNECTING" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11866]: Error starting daemon: error while opening volume store metadata database: timeout
Mar 19 22:14:19 tartiflette systemd[1]: docker.service: Main process exited, code=exited, status=1/FAILURE
Mar 19 22:14:19 tartiflette systemd[1]: docker.service: Failed with result 'exit-code'.
Mar 19 22:14:19 tartiflette systemd[1]: Failed to start Docker Application Container Engine.
Mar 19 22:14:19 tartiflette systemd[1]: docker.service: Service RestartSec=100ms expired, scheduling restart.
Mar 19 22:14:19 tartiflette systemd[1]: docker.service: Scheduled restart job, restart counter is at 2.
Mar 19 22:14:19 tartiflette systemd[1]: Stopped Docker Application Container Engine.
Mar 19 22:14:19 tartiflette systemd[1]: docker.service: Found left-over process 1683 (containerd-shim) in control group while starting unit. Ignoring.
Mar 19 22:14:19 tartiflette systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 19 22:14:19 tartiflette systemd[1]: docker.service: Found left-over process 11679 (s6-sync) in control group while starting unit. Ignoring.
Mar 19 22:14:19 tartiflette systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Mar 19 22:14:19 tartiflette systemd[1]: Starting Docker Application Container Engine...
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.916878970+01:00" level=info msg="libcontainerd: started new containerd process" pid=11923
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.916944934+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.916954602+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.916990299+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/containerd.sock 0  <nil>}]" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.917003012+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.917041665+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc000765dc0, CONNECTING" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.936716469+01:00" level=info msg="starting containerd" revision=bb71b10fd8f58240ca47fbb579b9d1028eea7c84.m version=v1.2.5.m
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.936952612+01:00" level=info msg="loading plugin "io.containerd.content.v1.content"..." type=io.containerd.content.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.936970355+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.btrfs"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.937112582+01:00" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.btrfs" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.btrfs must be a btrfs filesystem to be used with the btrfs snapshotter"
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.937121499+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.aufs"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938025695+01:00" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.aufs" error="modprobe aufs failed: "modprobe: FATAL: Module aufs not found in directory /lib/modules/5.0.1-arch1-1-ARCH\n": exit status 1"
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938038449+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.native"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938057805+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.overlayfs"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938109883+01:00" level=info msg="loading plugin "io.containerd.snapshotter.v1.zfs"..." type=io.containerd.snapshotter.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938260725+01:00" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.zfs" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.zfs must be a zfs filesystem to be used with the zfs snapshotter"
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938270684+01:00" level=info msg="loading plugin "io.containerd.metadata.v1.bolt"..." type=io.containerd.metadata.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938281424+01:00" level=warning msg="could not use snapshotter zfs in metadata plugin" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.zfs must be a zfs filesystem to be used with the zfs snapshotter"
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938286614+01:00" level=warning msg="could not use snapshotter btrfs in metadata plugin" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.btrfs must be a btrfs filesystem to be used with the btrfs snapshotter"
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938291523+01:00" level=warning msg="could not use snapshotter aufs in metadata plugin" error="modprobe aufs failed: "modprobe: FATAL: Module aufs not found in directory /lib/modules/5.0.1-arch1-1-ARCH\n": exit status 1"
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938414494+01:00" level=info msg="loading plugin "io.containerd.differ.v1.walking"..." type=io.containerd.differ.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938429893+01:00" level=info msg="loading plugin "io.containerd.gc.v1.scheduler"..." type=io.containerd.gc.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938453808+01:00" level=info msg="loading plugin "io.containerd.service.v1.containers-service"..." type=io.containerd.service.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938464187+01:00" level=info msg="loading plugin "io.containerd.service.v1.content-service"..." type=io.containerd.service.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938474066+01:00" level=info msg="loading plugin "io.containerd.service.v1.diff-service"..." type=io.containerd.service.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938485197+01:00" level=info msg="loading plugin "io.containerd.service.v1.images-service"..." type=io.containerd.service.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938495205+01:00" level=info msg="loading plugin "io.containerd.service.v1.leases-service"..." type=io.containerd.service.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938504713+01:00" level=info msg="loading plugin "io.containerd.service.v1.namespaces-service"..." type=io.containerd.service.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938513560+01:00" level=info msg="loading plugin "io.containerd.service.v1.snapshots-service"..." type=io.containerd.service.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.938522987+01:00" level=info msg="loading plugin "io.containerd.runtime.v1.linux"..." type=io.containerd.runtime.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.939808549+01:00" level=info msg="loading plugin "io.containerd.runtime.v2.task"..." type=io.containerd.runtime.v2
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.939840028+01:00" level=info msg="loading plugin "io.containerd.monitor.v1.cgroups"..." type=io.containerd.monitor.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940135843+01:00" level=info msg="loading plugin "io.containerd.service.v1.tasks-service"..." type=io.containerd.service.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940232935+01:00" level=info msg="loading plugin "io.containerd.internal.v1.restart"..." type=io.containerd.internal.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940279452+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.containers"..." type=io.containerd.grpc.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940296143+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.content"..." type=io.containerd.grpc.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940310360+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.diff"..." type=io.containerd.grpc.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940322523+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.events"..." type=io.containerd.grpc.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940333714+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.healthcheck"..." type=io.containerd.grpc.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940349624+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.images"..." type=io.containerd.grpc.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940361175+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.leases"..." type=io.containerd.grpc.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940373208+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.namespaces"..." type=io.containerd.grpc.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940384038+01:00" level=info msg="loading plugin "io.containerd.internal.v1.opt"..." type=io.containerd.internal.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940410708+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.snapshots"..." type=io.containerd.grpc.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940425746+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.tasks"..." type=io.containerd.grpc.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940437538+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.version"..." type=io.containerd.grpc.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940455763+01:00" level=info msg="loading plugin "io.containerd.grpc.v1.introspection"..." type=io.containerd.grpc.v1
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940622145+01:00" level=info msg=serving... address="/var/run/docker/containerd/containerd-debug.sock"
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940675655+01:00" level=info msg=serving... address="/var/run/docker/containerd/containerd.sock"
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.940691395+01:00" level=info msg="containerd successfully booted in 0.004447s"
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.947495998+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc000765dc0, READY" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.950488862+01:00" level=info msg="systemd-resolved is running, so using resolvconf: /run/systemd/resolve/resolv.conf"
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.950973060+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.950986816+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.951012304+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.951018245+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.951087996+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/containerd.sock 0  <nil>}]" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.951105689+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.951150873+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc000765fe0, CONNECTING" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.951153929+01:00" level=info msg="blockingPicker: the picked transport is not ready, loop back to repick" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.951095349+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/containerd.sock 0  <nil>}]" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.951193373+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.951244249+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0007eb0e0, CONNECTING" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.951268965+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc000765fe0, READY" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.951374984+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0007eb0e0, READY" module=grpc
Mar 19 22:14:19 tartiflette dockerd[11908]: time="2019-03-19T22:14:19.952705309+01:00" level=info msg="[graphdriver] using prior storage driver: overlay2"
Mar 19 22:14:20 tartiflette dockerd[11908]: time="2019-03-19T22:14:20.921922284+01:00" level=info msg="stopping event stream following graceful shutdown" error="context canceled" module=libcontainerd namespace=plugins.moby
Mar 19 22:14:20 tartiflette dockerd[11908]: time="2019-03-19T22:14:20.921910963+01:00" level=info msg="stopping healthcheck following graceful shutdown" module=libcontainerd
Mar 19 22:14:20 tartiflette dockerd[11908]: time="2019-03-19T22:14:20.922225203+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc000765fe0, TRANSIENT_FAILURE" module=grpc
Mar 19 22:14:20 tartiflette dockerd[11908]: time="2019-03-19T22:14:20.922242936+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc000765fe0, CONNECTING" module=grpc
Mar 19 22:14:21 tartiflette dockerd[11908]: Error starting daemon: error while opening volume store metadata database: timeout
Mar 19 22:14:21 tartiflette systemd[1]: docker.service: Main process exited, code=exited, status=1/FAILURE
Mar 19 22:14:21 tartiflette systemd[1]: docker.service: Failed with result 'exit-code'.
Mar 19 22:14:21 tartiflette systemd[1]: Failed to start Docker Application Container Engine.
Mar 19 22:14:22 tartiflette systemd[1]: docker.service: Service RestartSec=100ms expired, scheduling restart.
Mar 19 22:14:22 tartiflette systemd[1]: docker.service: Scheduled restart job, restart counter is at 3.
Mar 19 22:14:22 tartiflette systemd[1]: Stopped Docker Application Container Engine.
Mar 19 22:14:22 tartiflette systemd[1]: docker.service: Start request repeated too quickly.
Mar 19 22:14:22 tartiflette systemd[1]: docker.service: Failed with result 'exit-code'.
Mar 19 22:14:22 tartiflette systemd[1]: Failed to start Docker Application Container Engine.

From this point, ps showed the process as <defunct> and I had to reboot.

My issue looks like these: https://github.com/moby/moby/issues/13885, but nothing worked for me

Thanks for your help

Last edited by saponace (2019-03-20 15:20:40)

saponace · 2019-04-26 22:25:06

Anyone have an idea that could help me ?
I'd really appreciate help right now. I've been stuck on this exact problem since then. LItterally no progress.
What gives me hope for is that it used to work before I wipe everything and start from scratch. Probably a config I did without keeping track of it and forgot about it.

Last edited by saponace (2019-04-26 22:29:16)

Arch Linux

#1 2019-03-19 23:03:05

Docker hangs after a few minutes

#2 2019-04-26 22:25:06

Re: Docker hangs after a few minutes

Board footer