moby / moby/moby

Docker client commands hang forever when dockerd is starting

Open
#43,376 1 comment 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
Go
Stars
72.1k
Forks
19.2k
Avg merge
1d 17h
Merged PRs (30d)
164

Description

Description
When running a docker CLI command, e.g. docker images while dockerd is restarting the command hangs forever.

Steps to reproduce the issue:
This is reproducible on a machine that is experiencing some load during boot. In my case the machine is a K8s master node:

  1. Reboot machine
  2. Run docker images right after machine becomes accessible via SSH

I use following ansible playbook to reproduce:

- hosts: all
  gather_facts: no
  tasks:
    - reboot:
      become: yes
    - shell: docker -D -l debug images >/tmp/client 2>&1

Describe the results you received:
The docker command hangs.

Describe the results you expected:
The docker command either succeeds or fails.

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

After sending ABRT to the hanging process I got following output:

SIGABRT: abort
PC=0x55ac5f942161 m=0 sigcode=0

goroutine 0 [idle]:
runtime.futex(0x55ac62558110, 0x80, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x7ffc4790f8e8, 0x55ac5f8de265, ...)
        /usr/local/go/src/runtime/sys_linux_amd64.s:579 +0x21
runtime.futexsleep(0x55ac62558110, 0x200000000, 0xffffffffffffffff)
        /usr/local/go/src/runtime/os_linux.go:44 +0x46
runtime.notesleep(0x55ac62558110)
        /usr/local/go/src/runtime/lock_futex.go:159 +0xa5
runtime.mPark()
        /usr/local/go/src/runtime/proc.go:1340 +0x3d
runtime.stopm()
        /usr/local/go/src/runtime/proc.go:2301 +0x96
runtime.findrunnable(0xc000062800, 0x0)
        /usr/local/go/src/runtime/proc.go:2960 +0x731
runtime.schedule()
        /usr/local/go/src/runtime/proc.go:3169 +0x2d7
runtime.park_m(0xc000000180)
        /usr/local/go/src/runtime/proc.go:3318 +0xab
runtime.mcall(0x0)
        /usr/local/go/src/runtime/asm_amd64.s:327 +0x53

goroutine 1 [select]:
net/http.(*persistConn).roundTrip(0xc0004bd8c0, 0xc0000d3a80, 0x0, 0x0, 0x0)
        /usr/local/go/src/net/http/transport.go:2610 +0x765
net/http.(*Transport).roundTrip(0xc0002bc280, 0xc0000d4700, 0xc00041c6e0, 0x160, 0x150)
        /usr/local/go/src/net/http/transport.go:592 +0xacb
net/http.(*Transport).RoundTrip(0xc0002bc280, 0xc0000d4700, 0xc0002bc280, 0x0, 0x0)
        /usr/local/go/src/net/http/roundtrip.go:17 +0x37
net/http.send(0xc0000d4700, 0x55ac61792d58, 0xc0002bc280, 0x0, 0x0, 0x0, 0xc00012e990, 0x203000, 0x1, 0x0)
        /usr/local/go/src/net/http/client.go:251 +0x454
net/http.(*Client).send(0xc00046d050, 0xc0000d4700, 0x0, 0x0, 0x0, 0xc00012e990, 0x0, 0x1, 0x7f936a13f5b8)
        /usr/local/go/src/net/http/client.go:175 +0xff
net/http.(*Client).do(0xc00046d050, 0xc0000d4700, 0x0, 0x0, 0x0)
        /usr/local/go/src/net/http/client.go:717 +0x45f
net/http.(*Client).Do(...)
        /usr/local/go/src/net/http/client.go:585
github.com/docker/cli/vendor/github.com/docker/docker/client.(*Client).doRequest(0xc0000adf00, 0x55ac617e0978, 0xc00012c020, 0xc0000d4600, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /go/src/github.com/docker/cli/vendor/github.com/docker/docker/client/request.go:125 +0x158
github.com/docker/cli/vendor/github.com/docker/docker/client.(*Client).Ping(0xc0000adf00, 0x55ac617e0978, 0xc00012c020, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /go/src/github.com/docker/cli/vendor/github.com/docker/docker/client/ping.go:26 +0x1ba
github.com/docker/cli/cli/command.(*DockerCli).initializeFromClient(0xc000404820)
        /go/src/github.com/docker/cli/cli/command/cli.go:361 +0x122
github.com/docker/cli/cli/command.(*DockerCli).Initialize(0xc000404820, 0xc00000e4b0, 0x0, 0x0, 0x0, 0xc00015cb00, 0xc00025c040)
        /go/src/github.com/docker/cli/cli/command/cli.go:267 +0x3d9
github.com/docker/cli/cli.(*TopLevelCommand).Initialize(0xc0000d2000, 0x0, 0x0, 0x0, 0x4, 0x0)
        /go/src/github.com/docker/cli/cli/cobra.go:161 +0x7e
main.runDocker(0xc000404820, 0x55ac61793058, 0xc00012e010)
        /go/src/github.com/docker/cli/cmd/docker/docker.go:263 +0xc8
main.main()
        /go/src/github.com/docker/cli/cmd/docker/docker.go:298 +0xfc

goroutine 20 [chan receive]:
github.com/docker/cli/vendor/k8s.io/klog.(*loggingT).flushDaemon(0x55ac625573c0)
        /go/src/github.com/docker/cli/vendor/k8s.io/klog/klog.go:1010 +0x8d
created by github.com/docker/cli/vendor/k8s.io/klog.init.0
        /go/src/github.com/docker/cli/vendor/k8s.io/klog/klog.go:411 +0xd8

goroutine 23 [IO wait]:
internal/poll.runtime_pollWait(0x7f93400ac968, 0x72, 0xffffffffffffffff)
        /usr/local/go/src/runtime/netpoll.go:227 +0x65
internal/poll.(*pollDesc).wait(0xc00037c018, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x47
internal/poll.(*pollDesc).waitRead(...)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc00037c000, 0xc0004e1000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /usr/local/go/src/internal/poll/fd_unix.go:166 +0x1d8
net.(*netFD).Read(0xc00037c000, 0xc0004e1000, 0x1000, 0x1000, 0x7f9369fbfdd8, 0x0, 0xc0005a5c70)
        /usr/local/go/src/net/fd_posix.go:55 +0x51
net.(*conn).Read(0xc00012e9a8, 0xc0004e1000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /usr/local/go/src/net/net.go:183 +0x93
net/http.(*persistConn).Read(0xc0004bd8c0, 0xc0004e1000, 0x1000, 0x1000, 0x55ac5f8d7650, 0x60, 0x0)
        /usr/local/go/src/net/http/transport.go:1922 +0x77
bufio.(*Reader).fill(0xc0001d4f60)
        /usr/local/go/src/bufio/bufio.go:101 +0x108
bufio.(*Reader).Peek(0xc0001d4f60, 0x1, 0xc0001022a0, 0x0, 0x0, 0x0, 0x0)
        /usr/local/go/src/bufio/bufio.go:139 +0x51
net/http.(*persistConn).readLoop(0xc0004bd8c0)
        /usr/local/go/src/net/http/transport.go:2083 +0x1aa
created by net/http.(*Transport).dialConn
        /usr/local/go/src/net/http/transport.go:1743 +0xc77

goroutine 24 [select]:
net/http.(*persistConn).writeLoop(0xc0004bd8c0)
        /usr/local/go/src/net/http/transport.go:2382 +0xf9
created by net/http.(*Transport).dialConn
        /usr/local/go/src/net/http/transport.go:1744 +0xc9c

rax    0xca
rbx    0x55ac62557fc0
rcx    0xffffffffffffffff
rdx    0x0
rdi    0x55ac62558110
rsi    0x80
rbp    0x7ffc4790f8b0
rsp    0x7ffc4790f868
r8     0x0
r9     0x0
r10    0x0
r11    0x286
r12    0x7ffc4790f920
r13    0x4
r14    0x1
r15    0x2
rip    0x55ac5f942161
rflags 0x286
cs     0x33
fs     0x0
gs     0x0

From syslog it seems the docker CLI command was executed before dockerd initialized listener for Unix socket (not sure if it is relevant):

Mar 14 08:14:50 node-10-130-48-213 ansible-command: Invoked with creates=None executable=None _uses_shell=True strip_empty_ends=True _raw_params=docker -D -l debug images >/tmp/client 2>&1 removes=None argv=None warn=True chdir=None stdin_add_newline=True stdin=None
Mar 14 08:14:58 node-10-130-48-213 dockerd: time="2022-03-14T08:14:58.477177731Z" level=debug msg="Listener created for HTTP on tcp (0.0.0.0:2375)"
Mar 14 08:14:58 node-10-130-48-213 dockerd: time="2022-03-14T08:14:58.477450219Z" level=debug msg="Listener created for HTTP on unix (/var/run/docker.sock)"

Output of docker version:

Client: Docker Engine - Community
 Version:           20.10.13
 API version:       1.41
 Go version:        go1.16.15
 Git commit:        a224086
 Built:             Thu Mar 10 14:09:51 2022
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.13
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.16.15
  Git commit:       906f57f
  Built:            Thu Mar 10 14:08:16 2022
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.4.12
  GitCommit:        7b11cfaabd73bb80907dd23182b9347b4245eb5d
 runc:
  Version:          1.0.2
  GitCommit:        v1.0.2-0-g52b36a2
 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: Docker Buildx (Docker Inc., v0.8.0-docker)
  scan: Docker Scan (Docker Inc., v0.9.0)

Server:
 Containers: 38
  Running: 18
  Paused: 0
  Stopped: 20
 Images: 11
 Server Version: 20.10.13
 Storage Driver: overlay2
  Backing Filesystem: xfs
  Supports d_type: true
  Native Overlay Diff: true
  userxattr: false
 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.runc.v2 io.containerd.runtime.v1.linux runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 7b11cfaabd73bb80907dd23182b9347b4245eb5d
 runc version: v1.0.2-0-g52b36a2
 init version: de40ad0
 Security Options:
  seccomp
   Profile: default
 Kernel Version: 3.10.0-1062.el7.x86_64
 Operating System: CentOS Linux 7 (Core)
 OSType: linux
 Architecture: x86_64
 CPUs: 2
 Total Memory: 7.638GiB
 Name: node-10-130-48-213.pl.somedomain.corp
 ID: ET2K:DCVM:ORKK:AR3F:O5WB:OESD:FFJF:VVXE:SFS7:6CU2:F6WF:77HU
 Docker Root Dir: /var/lib/docker
 Debug Mode: true
  File Descriptors: 128
  Goroutines: 111
  System Time: 2022-03-14T08:21:58.755557148Z
  EventsListeners: 0
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  nexus.pl.somedomain.corp:5000
  127.0.0.0/8
 Registry Mirrors:
  http://nexus.pl.somedomain.corp:5001/
 Live Restore Enabled: false

WARNING: API is accessible on http://0.0.0.0:2375 without encryption.
         Access to the remote API is equivalent to root access on the host. Refer
         to the 'Docker daemon attack surface' section in the documentation for
         more information: https://docs.docker.com/go/attack-surface/

Additional environment details (AWS, VirtualBox, physical, etc.):
KVM, CentOS 7, kernel 3.10.0-1062.el7.x86_64

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with the Docker CLI initialization path in cli/command/cli.go and cli/command/cobra.go, then trace the request through vendor/github.com/docker/docker/client/request.go and ping.go. Reproduce the reboot scenario with docker -D -l debug images while dockerd is starting. Done means the command returns success or a failure instead of hanging indefinitely.

Written by the indexing model from the issue text.

Assessment

Tech stack
docker, go
Domain
backend, cli
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.