Docker 20.10 daemon takes 5 minutes to start after reboot

[calvincheng8]

• This is a bug report
• This is a feature request
• I searched existing issues before opening this one

Expected behavior

Docker daemon starts immediately after system reboot and available.

Actual behavior

Docker daemon is stuck for 5 minutes after reboot. No containers can be started. After 5 minutes, all seems to be OK.

Reverting docker-ce to 19.03.14 fixes the problem, the daemon starts immediately and containers can be started.

Steps to reproduce the behavior

Install docker-ce 20.10.0 on Ubuntu 20.04.1, then reboot.

After reboot, the command "docker ps" is stuck for almost 5 minutes. Any docker-cli commands are all stuck during this time.

Output of docker version:

Client: Docker Engine - Community
 Version:           20.10.0
 API version:       1.41
 Go version:        go1.13.15
 Git commit:        7287ab3
 Built:             Tue Dec  8 18:59:40 2020
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.0
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.13.15
  Git commit:       eeddea2
  Built:            Tue Dec  8 18:57:45 2020
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.4.3
  GitCommit:        269548fa27e0089a8b8278fc4fc781d7f65a939b
 runc:
  Version:          1.0.0-rc92
  GitCommit:        ff819c7e9184c13b7c2607fe6c30ae19403a7aff
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

Output of docker info:

Client:
 Context:    default
 Debug Mode: false
 Plugins:
  app: Docker App (Docker Inc., v0.9.1-beta3)
  buildx: Build with BuildKit (Docker Inc., v0.4.2-docker)

Server:
 Containers: 1
  Running: 1
  Paused: 0
  Stopped: 0
 Images: 5
 Server Version: 20.10.0
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Cgroup Version: 1
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runtime.v1.linux runc io.containerd.runc.v2
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 269548fa27e0089a8b8278fc4fc781d7f65a939b
 runc version: ff819c7e9184c13b7c2607fe6c30ae19403a7aff
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: default
 Kernel Version: 5.4.0-56-generic
 Operating System: Ubuntu 20.04.1 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 48
 Total Memory: 377.8GiB
 Name: REDACTED
 ID: SJDV:CLNU:LI5U:4KK3:6K5N:CZH2:WYNQ:SSK3:S57L:L2BM:N4BL:64RB
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

WARNING: No swap limit support
WARNING: No blkio weight support
WARNING: No blkio weight_device support

Additional environment details (AWS, VirtualBox, physical, etc.)
This is a physical server.

I can also reproduce this easily on a virtual server running in kvm, only difference seems to be that on the virtual server, I waited about 2 minutes for docker to start.

[cpuguy83]

What's in the daemon logs? You can check this in journalctl -u docker

[calvincheng8]

The system started at 16:28, but the logs for docker does not appear until 16:33.

journalctl -u docker shows

Dec 09 16:23:24 REDACTED systemd[1]: Stopped Docker Application Container Engine.
-- Reboot --
Dec 09 16:33:21 REDACTED systemd[1]: Starting Docker Application Container Engine...
Dec 09 16:33:22 REDACTED dockerd[2015]: time="2020-12-09T16:33:22.168186373Z" level=info msg="Starting up"
Dec 09 16:33:22 REDACTED dockerd[2015]: time="2020-12-09T16:33:22.177075626Z" level=info msg="detected 127.0.0.53 nameserver, assuming systemd-resolved, so using resolv.conf: /run/systemd/resolve/resolv.conf"
Dec 09 16:33:22 REDACTED dockerd[2015]: time="2020-12-09T16:33:22.251190964Z" level=info msg="parsed scheme: \"unix\"" module=grpc
Dec 09 16:33:22 REDACTED dockerd[2015]: time="2020-12-09T16:33:22.251249450Z" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Dec 09 16:33:22 REDACTED dockerd[2015]: time="2020-12-09T16:33:22.251303034Z" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock  <nil> 0 <nil>}] <nil> <nil>}" module=grpc
Dec 09 16:33:22 REDACTED dockerd[2015]: time="2020-12-09T16:33:22.251342844Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Dec 09 16:33:22 REDACTED dockerd[2015]: time="2020-12-09T16:33:22.275090334Z" level=info msg="parsed scheme: \"unix\"" module=grpc
Dec 09 16:33:22 REDACTED dockerd[2015]: time="2020-12-09T16:33:22.275165908Z" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Dec 09 16:33:22 REDACTED dockerd[2015]: time="2020-12-09T16:33:22.275216054Z" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock  <nil> 0 <nil>}] <nil> <nil>}" module=grpc
Dec 09 16:33:22 REDACTED dockerd[2015]: time="2020-12-09T16:33:22.275249468Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Dec 09 16:33:22 REDACTED dockerd[2015]: time="2020-12-09T16:33:22.949292685Z" level=info msg="[graphdriver] using prior storage driver: overlay2"
Dec 09 16:33:23 REDACTED dockerd[2015]: time="2020-12-09T16:33:23.582363044Z" level=warning msg="Your kernel does not support swap memory limit"
Dec 09 16:33:23 REDACTED dockerd[2015]: time="2020-12-09T16:33:23.582404812Z" level=warning msg="Your kernel does not support CPU realtime scheduler"
Dec 09 16:33:23 REDACTED dockerd[2015]: time="2020-12-09T16:33:23.582419375Z" level=warning msg="Your kernel does not support cgroup blkio weight"
Dec 09 16:33:23 REDACTED dockerd[2015]: time="2020-12-09T16:33:23.582432379Z" level=warning msg="Your kernel does not support cgroup blkio weight_device"
Dec 09 16:33:23 REDACTED dockerd[2015]: time="2020-12-09T16:33:23.582789329Z" level=info msg="Loading containers: start."
Dec 09 16:33:23 REDACTED dockerd[2015]: time="2020-12-09T16:33:23.619838845Z" level=error msg="Failed to load container 7815ffe534aa6ccf88b83fa61cb14e4be82aeee7f1ba56ff613f4871bac7dc7c: open /var/lib/docker/containers/7815ffe534aa6ccf88b83fa61cb14e4be82aeee7f1ba56ff613f4871bac7dc7c/config.v2.json: no such file or directory"
Dec 09 16:33:23 REDACTED dockerd[2015]: time="2020-12-09T16:33:23.635608621Z" level=error msg="Failed to load container mount 25820927fa2712b8acd114f202ca83f38a9df91f4b01ad6dcccce35d5ffc34eb: mount does not exist"
Dec 09 16:33:23 REDACTED dockerd[2015]: time="2020-12-09T16:33:23.635645725Z" level=error msg="Failed to load container mount 26689beb649d02d84e4ffab14de363f90229017c95a6334be40c6a8140a275cf: mount does not exist"
Dec 09 16:33:24 REDACTED dockerd[2015]: time="2020-12-09T16:33:24.089067437Z" level=info msg="Default bridge (docker0) is assigned with an IP address 172.17.0.0/16. Daemon option --bip can be used to set a preferred IP address"
Dec 09 16:33:24 REDACTED dockerd[2015]: time="2020-12-09T16:33:24.204228691Z" level=info msg="Loading containers: done."
Dec 09 16:33:24 REDACTED dockerd[2015]: time="2020-12-09T16:33:24.707394762Z" level=info msg="Docker daemon" commit=eeddea2 graphdriver(s)=overlay2 version=20.10.0
Dec 09 16:33:24 REDACTED dockerd[2015]: time="2020-12-09T16:33:24.712222830Z" level=info msg="Daemon has completed initialization"
Dec 09 16:33:24 REDACTED systemd[1]: Started Docker Application Container Engine.

[thaJeztah]

This might be related to moby/moby#41767

[calvincheng8]

Indeed this is very similar to the problem described in moby/moby#41767.

I had a service that required docker.service but not after docker.

[Unit]
Description=Start a docker app
Requires=docker.service

[Service]
Type=simple
ExecStartPre=-/usr/bin/docker rm -f docker-app
ExecStart=/usr/bin/docker run --rm --name docker-app docker-app-img
ExecStop=-/usr/bin/docker stop docker-app
Restart=always
TimeoutStartSec=5min

[Install]
WantedBy=multi-user.target

This service caused the 5 minutes delay in multi-user.target. After the failure of this service in 5 minutes, docker.service started up correctly.

After I added the line to start my app after docker.service

After=docker.service

docker.service starts normally but my service never starts up.

The culprit seems to be the line in docker.service,

After=network-online.target firewalld.service containerd.service multi-user.target
...
[Install]
WantedBy=multi-user.target

The circular dependency really confuses systemd.

[calvincheng8]

The problem went away after reverting the changes introduced in 20.10.3 in docker.service.

I removed multi-user.target from the After=... line and both docker.service and my own docker app started without problems or delays.

[thaJeztah]

Thanks for verifying; let me close this ticket as a duplicate of moby/moby#41767, to keep everything in a single place 👍

[thaJeztah]

Docker 20.10.1 was released, which contains an updated systemd unit to fix this issue