Skip to content

docker exec occasionally runs resize before container is attached. #31223

New issue
New issue
Closed
#37172
Closed
docker exec occasionally runs resize before container is attached.#31223
#37172
Labels
version/1.13
@gburiola

Description

@gburiola
gburiola
opened on Feb 21, 2017

Description

Sometimes, docker exec executes POST /v1.25/exec/{id}/resize before container has completed attaching to stdin and stdout.
When that happens, dockerd shows the following error and terminal size is not set inside the container.

level=error msg="Handler for POST /v1.25/exec/{id}/resize returned error: rpc error: code = 2 desc = containerd: process not found for container"

Steps to reproduce the issue:

  1. start dockerd

    /usr/bin/dockerd \
  --selinux-enabled \
  --userns-remap=default \
  --iptables=false \
  --bridge=none \
  --storage-driver=devicemapper \
  -D \
  --storage-opt dm.basesize=75G

  2. start container (docker run)

    docker run -v /dev/mqueue:/dev/mqueue \
           -v /etc/environment:/etc/environment:ro \
           -v /dev/log:/dev/log \
           --name container \
           --network docker0 \
           --dns=192.168.0.1 \
           -e HOSTNAME=myserver \
           --hostname myserver \
           --ip 192.168.0.2 \
           --storage-opt size=75G \
           --ulimit nofile=950000:950000 \
           --ulimit nproc=32768:32768 \
           --tty \
           docker.internal/container:1.0.7

  3. docker --debug exec -u myuser -ti ded836502956 /bin/bash

Additional information:

Issue only happens occasionally (roughly 10% of the time).

See order of API calls below for a GOOD docker exec run and for a BAD docker exec

GOOD

dockerd logs
Feb 21 15:01:54 myserver dockerd[22443]: time="2017-02-21T15:01:54.459916031Z" level=debug msg="Calling POST /v1.25/containers/ded836502956/exec"
Feb 21 15:01:54 myserver dockerd[22443]: time="2017-02-21T15:01:54.460037225Z" level=debug msg="form data: {\"AttachStderr\":true,\"AttachStdin\":true,\"AttachStdout\":true,\"Cmd\":[\"/bin/bash\"],\"Detach\":false,\"DetachKeys\":\"\",\"Env\":null,\"Privileged\":false,\"Tty\":true,\"User\":\"myuser\"}"
Feb 21 15:01:54 myserver dockerd[22443]: time="2017-02-21T15:01:54.460702441Z" level=debug msg="Calling POST /v1.25/exec/23683ad3fdccc23c44a4a69c9427df2c1b89dfc35e4d542c2c57a05489c2183a/start"
Feb 21 15:01:54 myserver dockerd[22443]: time="2017-02-21T15:01:54.460838760Z" level=debug msg="form data: {\"AttachStderr\":true,\"AttachStdin\":true,\"AttachStdout\":true,\"Cmd\":[\"/bin/bash\"],\"Detach\":false,\"DetachKeys\":\"\",\"Env\":null,\"Privileged\":false,\"Tty\":true,\"User\":\"myuser\"}"
Feb 21 15:01:54 myserver dockerd[22443]: time="2017-02-21T15:01:54.460961924Z" level=debug msg="starting exec command 23683ad3fdccc23c44a4a69c9427df2c1b89dfc35e4d542c2c57a05489c2183a in container ded8365029563227f4ab87431772fb55a7c7f628cbce11308f34bda2264f321d"
Feb 21 15:01:54 myserver dockerd[22443]: time="2017-02-21T15:01:54.462763827Z" level=debug msg="attach: stdin: begin"
Feb 21 15:01:54 myserver dockerd[22443]: time="2017-02-21T15:01:54.462832282Z" level=debug msg="attach: stdout: begin"
Feb 21 15:01:54 myserver dockerd[22443]: time="2017-02-21T15:01:54.465266458Z" level=debug msg="Calling POST /v1.25/exec/23683ad3fdccc23c44a4a69c9427df2c1b89dfc35e4d542c2c57a05489c2183a/resize?h=31&w=272"
Feb 21 15:01:54 myserver dockerd[22443]: time="2017-02-21T15:01:54.510975360Z" level=debug msg="libcontainerd: received containerd event: &types.Event{Type:\"start-process\", Id:\"ded8365029563227f4ab87431772fb55a7c7f628cbce11308f34bda2264f321d\", Status:0x0, Pid:\"23683ad3fdccc23c44a4a69c9427df2c1b89dfc35e4d542c2c57a05489c2183a\", Timestamp:(*timestamp.Timestamp)(0xc421a8cd00)}"
Feb 21 15:01:54 myserver dockerd[22443]: time="2017-02-21T15:01:54.512622763Z" level=debug msg="libcontainerd: event unhandled: type:\"start-process\" id:\"ded8365029563227f4ab87431772fb55a7c7f628cbce11308f34bda2264f321d\" pid:\"23683ad3fdccc23c44a4a69c9427df2c1b89dfc35e4d542c2c57a05489c2183a\" timestamp:<seconds:1487689314 nanos:510534871 > "


# echo $COLUMNS
272
# docker --debug exec -u myuser -ti ded836502956 /bin/bash
$ echo $COLUMNS
272

BAD

dockerd logs
Feb 21 14:58:16 myserver dockerd[22443]: time="2017-02-21T14:58:16.546442865Z" level=debug msg="Calling POST /v1.25/containers/ded836502956/exec"
Feb 21 14:58:16 myserver dockerd[22443]: time="2017-02-21T14:58:16.546557939Z" level=debug msg="form data: {\"AttachStderr\":true,\"AttachStdin\":true,\"AttachStdout\":true,\"Cmd\":[\"/bin/bash\"],\"Detach\":false,\"DetachKeys\":\"\",\"Env\":null,\"Privileged\":false,\"Tty\":true,\"User\":\"myuser\"}"
Feb 21 14:58:16 myserver dockerd[22443]: time="2017-02-21T14:58:16.547519993Z" level=debug msg="Calling POST /v1.25/exec/7114e148b95e3b7df2d5a28a84a0760d75d29ac634ef7b7f938a6ba45fb45423/start"
Feb 21 14:58:16 myserver dockerd[22443]: time="2017-02-21T14:58:16.547630832Z" level=debug msg="form data: {\"AttachStderr\":true,\"AttachStdin\":true,\"AttachStdout\":true,\"Cmd\":[\"/bin/bash\"],\"Detach\":false,\"DetachKeys\":\"\",\"Env\":null,\"Privileged\":false,\"Tty\":true,\"User\":\"myuser\"}"
Feb 21 14:58:16 myserver dockerd[22443]: time="2017-02-21T14:58:16.547778692Z" level=debug msg="starting exec command 7114e148b95e3b7df2d5a28a84a0760d75d29ac634ef7b7f938a6ba45fb45423 in container ded8365029563227f4ab87431772fb55a7c7f628cbce11308f34bda2264f321d"
Feb 21 14:58:16 myserver dockerd[22443]: time="2017-02-21T14:58:16.548600029Z" level=debug msg="Calling POST /v1.25/exec/7114e148b95e3b7df2d5a28a84a0760d75d29ac634ef7b7f938a6ba45fb45423/resize?h=31&w=272"
Feb 21 14:58:16 myserver dockerd[22443]: time="2017-02-21T14:58:16.549055374Z" level=debug msg="attach: stdin: begin"
Feb 21 14:58:16 myserver dockerd[22443]: time="2017-02-21T14:58:16.549112586Z" level=debug msg="attach: stdout: begin"
Feb 21 14:58:16 myserver dockerd[22443]: time="2017-02-21T14:58:16.549144907Z" level=error msg="Handler for POST /v1.25/exec/7114e148b95e3b7df2d5a28a84a0760d75d29ac634ef7b7f938a6ba45fb45423/resize returned error: rpc error: code = 2 desc = containerd: process not found for container"
Feb 21 14:58:16 myserver dockerd[22443]: time="2017-02-21T14:58:16.602903520Z" level=debug msg="libcontainerd: received containerd event: &types.Event{Type:\"start-process\", Id:\"ded8365029563227f4ab87431772fb55a7c7f628cbce11308f34bda2264f321d\", Status:0x0, Pid:\"7114e148b95e3b7df2d5a28a84a0760d75d29ac634ef7b7f938a6ba45fb45423\", Timestamp:(*timestamp.Timestamp)(0xc421a65ac0)}"
Feb 21 14:58:16 myserver dockerd[22443]: time="2017-02-21T14:58:16.603483750Z" level=debug msg="libcontainerd: event unhandled: type:\"start-process\" id:\"ded8365029563227f4ab87431772fb55a7c7f628cbce11308f34bda2264f321d\" pid:\"7114e148b95e3b7df2d5a28a84a0760d75d29ac634ef7b7f938a6ba45fb45423\" timestamp:<seconds:1487689096 nanos:602325274 > "


# echo $COLUMNS
272
# docker --debug exec -u myuser -ti ded836502956 /bin/bash
DEBU[0000] Error resize: Error response from daemon: rpc error: code = 2 desc = containerd: process not found for container
$ echo $COLUMNS
80

When a "BAD" docker exec happens, that means, POST resize happens before attach: stdin: begin, if I re-run the POST that failed, it always works:

curl -v --unix-socket /var/run/docker.sock -X POST \
     "http:/v1.25/exec/23683ad3fdccc23c44a4a69c9427df2c1b89dfc35e4d542c2c57a05489c2183a/resize?h=31&w=272"


< HTTP/1.1 200 OK
< Api-Version: 1.25
< Docker-Experimental: false
< Server: Docker/1.13.0 (linux)

Output of docker version:

# docker version
Client:
 Version:      1.13.0
 API version:  1.25
 Go version:   go1.7.3
 Git commit:   49bf474
 Built:        Tue Jan 17 09:55:28 2017
 OS/Arch:      linux/amd64

Server:
 Version:      1.13.0
 API version:  1.25 (minimum version 1.12)
 Go version:   go1.7.3
 Git commit:   49bf474
 Built:        Tue Jan 17 09:55:28 2017
 OS/Arch:      linux/amd64
 Experimental: false


# rpm -qa | grep docker
docker-engine-selinux-1.13.0-1.el7.centos.noarch
docker-engine-1.13.0-1.el7.centos.x86_64


# cat /etc/redhat-release
CentOS Linux release 7.3.1611 (Core)

Output of docker info:

# docker info
Containers: 1
 Running: 1
 Paused: 0
 Stopped: 0
Images: 1
Server Version: 1.13.0
Storage Driver: devicemapper
 Pool Name: docker-253:0-894645-pool
 Pool Blocksize: 65.54 kB
 Base Device Size: 80.53 GB
 Backing Filesystem: xfs
 Data file: /dev/loop0
 Metadata file: /dev/loop1
 Data Space Used: 1.039 GB
 Data Space Total: 107.4 GB
 Data Space Available: 101.9 GB
 Metadata Space Used: 2.081 MB
 Metadata Space Total: 2.147 GB
 Metadata Space Available: 2.145 GB
 Thin Pool Minimum Free Space: 10.74 GB
 Udev Sync Supported: true
 Deferred Removal Enabled: false
 Deferred Deletion Enabled: false
 Deferred Deleted Device Count: 0
 Data loop file: /opt/docker/100000.100000/devicemapper/devicemapper/data
 WARNING: Usage of loopback devices is strongly discouraged for production use. Use `--storage-opt dm.thinpooldev` to specify a custom block storage device.
 Metadata loop file: /opt/docker/100000.100000/devicemapper/devicemapper/metadata
 Library Version: 1.02.135-RHEL7 (2016-09-28)
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host macvlan null overlay
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 03e5862ec0d8d3b3f750e19fca3ee367e13c090e
runc version: 2f7393a47307a16f8cee44a37b262e8b81021e3e
init version: 949e6fa
Security Options:
 seccomp
  Profile: default
 selinux
 userns
Kernel Version: 3.10.0-514.2.2.el7.x86_64
Operating System: CentOS Linux 7 (Core)
OSType: linux
Architecture: x86_64
CPUs: 2
Total Memory: 7.388 GiB
Name: myserver
ID: OACX:URVN:ALRN:27R6:XKMD:ULVL:OO2V:SOHM:34NA:2ZRQ:72JI:ORMJ
Docker Root Dir: /opt/docker/100000.100000
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 31
 Goroutines: 45
 System Time: 2017-02-21T15:01:18.874076279Z
 EventsListeners: 1
Http Proxy: http://proxy01:8888/
Https Proxy: http://proxy01:8888/
No Proxy: localhost,127.0.0.1,169.254.169.254,10.0.206.192
Registry: https://index.docker.io/v1/
WARNING: bridge-nf-call-iptables is disabled
WARNING: bridge-nf-call-ip6tables is disabled
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

Metadata

Metadata

Assignees

No one assigned

    Labels

    version/1.13

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions