Client.Timeout exceeded while reading body

[tao12345666333]

Description

Steps to reproduce the issue:

1. run any container. e.g. redis

(MoeLove) ➜  docker-ce git:(b274b68) ✗ docker run --rm -d redis
7078a615609d6b63e56837f16c2c866cb8e35fceba69c3ab219bfff118b99134

2. docker logs -f follow the container's logs.

(MoeLove) ➜  docker-ce git:(b274b68) ✗ docker logs -f $(docker ps -ql)
1:C 17 May 2019 08:13:58.300 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
1:C 17 May 2019 08:13:58.300 # Redis version=5.0.4, bits=64, commit=00000000, modified=0, pid=1, just started
1:C 17 May 2019 08:13:58.300 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
1:M 17 May 2019 08:13:58.303 * Running mode=standalone, port=6379.
1:M 17 May 2019 08:13:58.303 # WARNING: The TCP backlog setting of 511 cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of 128.
1:M 17 May 2019 08:13:58.304 # Server initialized
1:M 17 May 2019 08:13:58.304 # WARNING you have Transparent Huge Pages (THP) support enabled in your kernel. This will create latency and memory usage issues with Redis. To fix this issue run the command 'echo never > /sys/kernel/mm/transparent_hugepage/enabled' as root, and add it to your /etc/rc.local in order to retain the setting after a reboot. Redis must be restarted after THP is disabled.
1:M 17 May 2019 08:13:58.304 * Ready to accept connections
net/http: request canceled (Client.Timeout exceeded while reading body)
(MoeLove) ➜  docker-ce git:(b274b68) ✗ echo $?
1
(MoeLove) ➜  docker-ce git:(b274b68) ✗

Describe the results you received:

net/http: request canceled (Client.Timeout exceeded while reading body)

Describe the results you expected:

follow the logs.

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

Output of docker version:

(MoeLove) ➜  docker-ce git:(b274b68) ✗ docker version
Client: Docker Engine - Community
 Version:           0.0.0-20190515050035-b274b68
 API version:       1.40
 Go version:        go1.12.4
 Git commit:        b274b68
 Built:             Wed May 15 07:31:14 2019
 OS/Arch:           linux/amd64
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          0.0.0-20190515050035-b274b68
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.12.4
  Git commit:       b274b68
  Built:            Wed May 15 07:29:57 2019
  OS/Arch:          linux/amd64
  Experimental:     true
 containerd:
  Version:          1.2.5
  GitCommit:        bb71b10fd8f58240ca47fbb579b9d1028eea7c84
 runc:
  Version:          1.0.0-rc7
  GitCommit:        69ae5da6afdcaaf38285a10b36f362e41cb298d6
 docker-init:
  Version:          0.18.0
  GitCommit:        fec3683

Output of docker info:

(MoeLove) ➜  docker-ce git:(b274b68) ✗ docker info
Client:                               
 Debug Mode: false
 Plugins:          
  app: Docker Application (Docker Inc., v0.8.0-beta2)
  buildx: Build with BuildKit (Docker Inc., v0.2.0-28-gcb83df7-tp)
             
Server:                    
 Containers: 2
  Running: 1                          
  Paused: 0
  Stopped: 1
 Images: 225
 Server Version: 0.0.0-20190515050035-b274b68
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
 Logging Driver: json-file
 Cgroup Driver: systemd
 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: runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: bb71b10fd8f58240ca47fbb579b9d1028eea7c84
 runc version: 69ae5da6afdcaaf38285a10b36f362e41cb298d6
 init version: fec3683
 Security Options:
  seccomp
   Profile: default
 Kernel Version: 5.0.11-100.fc28.x86_64
 Operating System: Fedora 28 (Workstation Edition)
 OSType: linux
 Architecture: x86_64
 CPUs: 4
 Total Memory: 15.56GiB
 Name: localhost.localdomain
 ID: 23f7e031-5e53-4256-83ce-3238ad0d5ccc
 Docker Root Dir: /var/lib/docker
 Debug Mode: true
  File Descriptors: 29
  Goroutines: 42
  System Time: 2019-05-17T16:18:22.586673499+08:00
  EventsListeners: 0
 HTTP Proxy: socks5://127.0.0.1:1081/
 HTTPS Proxy: socks5://127.0.0.1:1081/
 No Proxy: localhost,127.0.0.1,docker.io,yanzhe919.mirror.aliyuncs.com,99nkhzdo.mirror.aliyuncs.com,*.aliyuncs.com,*.mirror.aliyuncs.com,registry.docker-cn.com,hub.c.163.com,hub-auth.c.163.com,harbor-registry.inner.youdao.com,registry.corp.youdao.com
 Username: taobeier
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: true
 Insecure Registries:
  127.0.0.1:5000
  127.0.0.0/8
 Live Restore Enabled: true

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

my laptop Fedora 28 / Linux 5.0.11-100.fc28.x86_64

xref: docker/for-linux#669

[tao12345666333]

using strace -tt -T -f -o cli-strace.txt docker logs -f 7078a615609d

cli strace log here. cli-strace.txt

[tao12345666333]

And the seem error here:

(MoeLove) ➜  docker-ce git:(b274b68) ✗ docker pull golang:1.12.5-alpine
1.12.5-alpine: Pulling from library/golang
e7c96db7181b: Already exists
5297bd381816: Already exists
3a664477889c: Already exists
bb89ac7faaa9: Downloading [===>                                               ]  8.088MB/125.3MB
8bb43bd9c21d: Download complete
net/http: request canceled (Client.Timeout exceeded while reading body)

the daemon's log

5月 17 16:24:23 localhost.localdomain dockerd[17003]: time="2019-05-17T16:24:23.811449928+08:00" level=debug msg="Calling HEAD /_ping"                                                                              
5月 17 16:24:23 localhost.localdomain dockerd[17003]: time="2019-05-17T16:24:23.812059823+08:00" level=debug msg="Calling GET /v1.40/info"                                                                          
5月 17 16:24:23 localhost.localdomain dockerd[17003]: time="2019-05-17T16:24:23.832701110+08:00" level=debug msg="Calling POST /v1.40/images/create?fromImage=golang&tag=1.12.5-alpine"                             
5月 17 16:24:23 localhost.localdomain dockerd[17003]: time="2019-05-17T16:24:23.832831340+08:00" level=debug msg="Trying to pull golang from https://registry-1.docker.io v2"                                       
5月 17 16:24:27 localhost.localdomain dockerd[17003]: time="2019-05-17T16:24:27.746741597+08:00" level=debug msg="Pulling ref from V2 registry: golang:1.12.5-alpine"                                               
5月 17 16:24:27 localhost.localdomain dockerd[17003]: time="2019-05-17T16:24:27.746869140+08:00" level=debug msg="docker.io/library/golang:1.12.5-alpine resolved to a manifestList object with 7 entries; looking for a unknown/amd64 match"
5月 17 16:24:27 localhost.localdomain dockerd[17003]: time="2019-05-17T16:24:27.746936926+08:00" level=debug msg="found match for linux/amd64 with media type application/vnd.docker.distribution.manifest.v2+json, digest sha256:5ec3232b32e6876c0941d66d8392f667c77ca1ef14cafb85991deea4339b92da"
5月 17 16:24:29 localhost.localdomain dockerd[17003]: time="2019-05-17T16:24:29.081320789+08:00" level=debug msg="Layer already exists: e7c96db7181b"                                                               
5月 17 16:24:29 localhost.localdomain dockerd[17003]: time="2019-05-17T16:24:29.091749059+08:00" level=debug msg="Layer already exists: 5297bd381816"                                                               
5月 17 16:24:29 localhost.localdomain dockerd[17003]: time="2019-05-17T16:24:29.097634955+08:00" level=debug msg="Layer already exists: 3a664477889c"                                                               
5月 17 16:24:29 localhost.localdomain dockerd[17003]: time="2019-05-17T16:24:29.103638655+08:00" level=debug msg="pulling blob \"sha256:8bb43bd9c21dcf98c3c1391e7d823ae075f050cd0a3fee64e2f3b40180889287\""         
5月 17 16:24:29 localhost.localdomain dockerd[17003]: time="2019-05-17T16:24:29.103763214+08:00" level=debug msg="pulling blob \"sha256:bb89ac7faaa96be5766878cb01812422cb180a1b2bc7941e59d0164317766344\""         
5月 17 16:24:31 localhost.localdomain dockerd[17003]: time="2019-05-17T16:24:31.507281555+08:00" level=debug msg="Downloaded 8bb43bd9c21d to tempfile /var/lib/docker/tmp/GetImageBlob954819057"                    
5月 17 16:24:33 localhost.localdomain dockerd[17003]: time="2019-05-17T16:24:33.832937615+08:00" level=error msg="Not continuing with pull after error: context canceled" 

Not continuing with pull after error: context canceled

[ijc]

I am pretty sure this is because of #1872. I'll try and take a look today.

[tao12345666333]

I am pretty sure this is because of #1872. I'll try and take a look today.

Thanks for your reply. The version I am using now is built with the docker-archive/docker-ce@b274b68 commit. This does contain the timeout change.

[ijc]

I've now tested head with an without that commit and can confirm it is at fault. The fact that the timeout happens after 10s is also a big hint.

[tao12345666333]

I tried to build using master's latest code(4c605bd) on my laptop.

(MoeLove) ➜  cli git:(master) ./build/docker version
Client:
 Version:           unknown-version
 API version:       1.40
 Go version:        go1.11.6
 Git commit:        4c605bdc
 Built:             Fri May 17 08:07:07 2019
 OS/Arch:           linux/amd64
 Experimental:      true

It works well.

(MoeLove) ➜  cli git:(master) docker ps
CONTAINER ID        IMAGE               COMMAND                  CREATED             STATUS              PORTS               NAMES                                                                                  
7078a615609d        redis               "docker-entrypoint.s…"   37 minutes ago      Up 37 minutes       6379/tcp            bold_lumiere
(MoeLove) ➜  cli git:(master) time ./build/docker logs -f 7078a615609d
1:C 17 May 2019 08:13:58.300 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
1:C 17 May 2019 08:13:58.300 # Redis version=5.0.4, bits=64, commit=00000000, modified=0, pid=1, just started
1:C 17 May 2019 08:13:58.300 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
1:M 17 May 2019 08:13:58.303 * Running mode=standalone, port=6379.
1:M 17 May 2019 08:13:58.303 # WARNING: The TCP backlog setting of 511 cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of 128.
1:M 17 May 2019 08:13:58.304 # Server initialized
1:M 17 May 2019 08:13:58.304 # WARNING you have Transparent Huge Pages (THP) support enabled in your kernel. This will create latency and memory usage issues with Redis. To fix this issue run the command 'echo never > /sys/kernel/mm/transparent_hugepage/enabled' as root, and add it to your /etc/rc.local in order to retain the setting after a reboot. Redis must be restarted after THP is disabled.
1:M 17 May 2019 08:13:58.304 * Ready to accept connections
^C
./build/docker logs -f 7078a615609d  0.03s user 0.01s system 0% cpu 47.157 total

my golang version is 1.11.6.

[tao12345666333]

but I am still not sure exactly where to fix this problem.

EDIT:

the code diff 5f17b1d...master

[tao12345666333]

when I using make -f docker.Makefile binary build, can reproduce the issue.

(MoeLove) ➜  cli git:(master) PATH=$PWD/build:$PATH make -f docker.Makefile binary
# build dockerfile from stdin so that we don't send the build-context; source is bind-mounted in the development environment
cat ./dockerfiles/Dockerfile.binary-native | docker build -t docker-cli-native -
[+] Building 8.3s (7/7) FINISHED                
 => [internal] load build definition from Dockerfile                                                                                                                                                            0.0s
 => => transferring dockerfile: 319B                                                                                                                                                                            0.0s
 => [internal] load .dockerignore                                                                                                                                                                               0.0s
 => => transferring context: 2B                                                                                                                                                                                 0.0s
 => [internal] load metadata for docker.io/library/golang:1.12.5-alpine                                                                                                                                         0.0s
 => CACHED [1/3] FROM docker.io/library/golang:1.12.5-alpine                                                                                                                                                    0.0s
 => [2/3] RUN     apk add -U git bash coreutils gcc musl-dev                                                                                                                                                    7.2s
 => [3/3] WORKDIR /go/src/github.com/docker/cli                                                                                                                                                                 0.0s
 => exporting to image                                                                                                                                                                                          0.9s
 => => exporting layers                                                                                                                                                                                         0.9s
 => => writing image sha256:f845309d9d4da49559b74eee7d52b25b87973991ed24ab71c443c86d260e9c7e                                                                                                                    0.0s
 => => naming to docker.io/library/docker-cli-native                                                                                                                                                            0.0s
docker run --rm -e VERSION=19.09.0-dev -e GITCOMMIT -e PLATFORM -e TESTFLAGS -e TESTDIRS -e GOOS -e GOARCH -e GOARM -v "/home/tao/workspace/cli":/go/src/github.com/docker/cli -v "docker-cli-dev-cache:/root/.cache/
go-build"  docker-cli-native
Building statically linked build/docker-linux-amd64

(MoeLove) ➜  cli git:(master) ls -al build
总用量 64012
drwxr-xr-x.  2 tao  tao      4096 5月  17 17:20 .
drwxrwxr-x. 22 tao  tao      4096 5月  16 15:46 ..
lrwxrwxrwx.  1 root root       18 5月  17 17:20 docker -> docker-linux-amd64
-rwxr-xr-x.  1 root root 65539981 5月  17 17:20 docker-linux-amd64
(MoeLove) ➜  cli git:(master) ./build/docker ps
CONTAINER ID        IMAGE               COMMAND                  CREATED             STATUS              PORTS               NAMES                                                                                  
7078a615609d        redis               "docker-entrypoint.s…"   About an hour ago   Up About an hour    6379/tcp            bold_lumiere                                                                           
(MoeLove) ➜  cli git:(master) ./build/docker logs -f 7078a615609d
1:C 17 May 2019 08:13:58.300 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
1:C 17 May 2019 08:13:58.300 # Redis version=5.0.4, bits=64, commit=00000000, modified=0, pid=1, just started                                                                                                       
1:C 17 May 2019 08:13:58.300 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf                                                  
1:M 17 May 2019 08:13:58.303 * Running mode=standalone, port=6379.
1:M 17 May 2019 08:13:58.303 # WARNING: The TCP backlog setting of 511 cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of 128.                                                    
1:M 17 May 2019 08:13:58.304 # Server initialized
1:M 17 May 2019 08:13:58.304 # WARNING you have Transparent Huge Pages (THP) support enabled in your kernel. This will create latency and memory usage issues with Redis. To fix this issue run the command 'echo never > /sys/kernel/mm/transparent_hugepage/enabled' as root, and add it to your /etc/rc.local in order to retain the setting after a reboot. Redis must be restarted after THP is disabled.                           
1:M 17 May 2019 08:13:58.304 * Ready to accept connections
net/http: request canceled (Client.Timeout exceeded while reading body)
(MoeLove) ➜  cli git:(master) ./build/docker version
Client:
 Version:           19.09.0-dev
 API version:       1.40
 Go version:        go1.12.5
 Git commit:        4c605bdc
 Built:             Fri May 17 09:19:55 2019
 OS/Arch:           linux/amd64
 Experimental:      true

[ijc]

@tao12345666333 I think we will have to revert #1872 for now. I can't see a way to fix this issue only in this repo while still retaining the reduced timeout for dial but not for subsequent operations.

I think I will need to patch github.com/docker/docker/client or perhaps github.com/docker/go-connections to achieve what I was trying to do with #1872.

[ijc]

See #1893 which reverts the commit for now.

[tao12345666333]

Thanks.
I also revert this commit and test will not encounter the previous problem.

[tao12345666333]

But I still have a confusion 🤔

Why do I not encounter the same problem with the binary files I built directly with DISABLE_WARN_OUTSIDE_CONTAINER=1 make?

See #1892 (comment)