{"action":"closed","issue":{"url":"https://api.github.com/repos/moby/moby/issues/31223","repository_url":"https://api.github.com/repos/moby/moby","labels_url":"https://api.github.com/repos/moby/moby/issues/31223/labels{/name}","comments_url":"https://api.github.com/repos/moby/moby/issues/31223/comments","events_url":"https://api.github.com/repos/moby/moby/issues/31223/events","html_url":"https://github.com/moby/moby/issues/31223","id":209187613,"node_id":"MDU6SXNzdWUyMDkxODc2MTM=","number":31223,"title":"docker exec occasionally runs resize before container is attached.","user":{"login":"gburiola","id":6121373,"node_id":"MDQ6VXNlcjYxMjEzNzM=","avatar_url":"https://avatars3.githubusercontent.com/u/6121373?v=4","gravatar_id":"","url":"https://api.github.com/users/gburiola","html_url":"https://github.com/gburiola","followers_url":"https://api.github.com/users/gburiola/followers","following_url":"https://api.github.com/users/gburiola/following{/other_user}","gists_url":"https://api.github.com/users/gburiola/gists{/gist_id}","starred_url":"https://api.github.com/users/gburiola/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/gburiola/subscriptions","organizations_url":"https://api.github.com/users/gburiola/orgs","repos_url":"https://api.github.com/users/gburiola/repos","events_url":"https://api.github.com/users/gburiola/events{/privacy}","received_events_url":"https://api.github.com/users/gburiola/received_events","type":"User","site_admin":false},"labels":[{"id":480238176,"node_id":"MDU6TGFiZWw0ODAyMzgxNzY=","url":"https://api.github.com/repos/moby/moby/labels/version/1.13","name":"version/1.13","color":"ededed","default":false}],"state":"closed","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":4,"created_at":"2017-02-21T15:55:13Z","updated_at":"2018-06-08T22:43:26Z","closed_at":"2018-06-08T22:43:26Z","author_association":"NONE","body":"**Description**\r\n\r\nSometimes, `docker exec` executes `POST /v1.25/exec/{id}/resize` before container has completed attaching to `stdin` and `stdout`.\r\nWhen that happens, `dockerd` shows the following error and terminal size is not set inside the container.\r\n\r\n```\r\nlevel=error msg=\"Handler for POST /v1.25/exec/{id}/resize returned error: rpc error: code = 2 desc = containerd: process not found for container\"\r\n```\r\n\r\n\r\n\r\n**Steps to reproduce the issue:**\r\n\r\n1. start `dockerd`\r\n    ```\r\n    /usr/bin/dockerd \\\r\n      --selinux-enabled \\\r\n      --userns-remap=default \\\r\n      --iptables=false \\\r\n      --bridge=none \\\r\n      --storage-driver=devicemapper \\\r\n      -D \\\r\n      --storage-opt dm.basesize=75G\r\n    ```\r\n\r\n2. start container (`docker run`)\r\n    ```\r\n    docker run -v /dev/mqueue:/dev/mqueue \\\r\n               -v /etc/environment:/etc/environment:ro \\\r\n               -v /dev/log:/dev/log \\\r\n               --name container \\\r\n               --network docker0 \\\r\n               --dns=192.168.0.1 \\\r\n               -e HOSTNAME=myserver \\\r\n               --hostname myserver \\\r\n               --ip 192.168.0.2 \\\r\n               --storage-opt size=75G \\\r\n               --ulimit nofile=950000:950000 \\\r\n               --ulimit nproc=32768:32768 \\\r\n               --tty \\\r\n               docker.internal/container:1.0.7\r\n    ```\r\n\r\n3. `docker --debug exec -u myuser -ti ded836502956 /bin/bash`\r\n\r\n\r\n\r\n**Additional information:**\r\n\r\nIssue only happens occasionally (roughly 10% of the time).\r\n\r\nSee order of API calls below for a GOOD `docker exec` run and for a BAD `docker exec`\r\n\r\nGOOD\r\n\r\n```\r\ndockerd logs\r\nFeb 21 15:01:54 myserver dockerd[22443]: time=\"2017-02-21T15:01:54.459916031Z\" level=debug msg=\"Calling POST /v1.25/containers/ded836502956/exec\"\r\nFeb 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\\\"}\"\r\nFeb 21 15:01:54 myserver dockerd[22443]: time=\"2017-02-21T15:01:54.460702441Z\" level=debug msg=\"Calling POST /v1.25/exec/23683ad3fdccc23c44a4a69c9427df2c1b89dfc35e4d542c2c57a05489c2183a/start\"\r\nFeb 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\\\"}\"\r\nFeb 21 15:01:54 myserver dockerd[22443]: time=\"2017-02-21T15:01:54.460961924Z\" level=debug msg=\"starting exec command 23683ad3fdccc23c44a4a69c9427df2c1b89dfc35e4d542c2c57a05489c2183a in container ded8365029563227f4ab87431772fb55a7c7f628cbce11308f34bda2264f321d\"\r\nFeb 21 15:01:54 myserver dockerd[22443]: time=\"2017-02-21T15:01:54.462763827Z\" level=debug msg=\"attach: stdin: begin\"\r\nFeb 21 15:01:54 myserver dockerd[22443]: time=\"2017-02-21T15:01:54.462832282Z\" level=debug msg=\"attach: stdout: begin\"\r\nFeb 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\"\r\nFeb 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)}\"\r\nFeb 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 > \"\r\n\r\n\r\n# echo $COLUMNS\r\n272\r\n# docker --debug exec -u myuser -ti ded836502956 /bin/bash\r\n$ echo $COLUMNS\r\n272\r\n```\r\n\r\nBAD\r\n\r\n```\r\ndockerd logs\r\nFeb 21 14:58:16 myserver dockerd[22443]: time=\"2017-02-21T14:58:16.546442865Z\" level=debug msg=\"Calling POST /v1.25/containers/ded836502956/exec\"\r\nFeb 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\\\"}\"\r\nFeb 21 14:58:16 myserver dockerd[22443]: time=\"2017-02-21T14:58:16.547519993Z\" level=debug msg=\"Calling POST /v1.25/exec/7114e148b95e3b7df2d5a28a84a0760d75d29ac634ef7b7f938a6ba45fb45423/start\"\r\nFeb 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\\\"}\"\r\nFeb 21 14:58:16 myserver dockerd[22443]: time=\"2017-02-21T14:58:16.547778692Z\" level=debug msg=\"starting exec command 7114e148b95e3b7df2d5a28a84a0760d75d29ac634ef7b7f938a6ba45fb45423 in container ded8365029563227f4ab87431772fb55a7c7f628cbce11308f34bda2264f321d\"\r\nFeb 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\"\r\nFeb 21 14:58:16 myserver dockerd[22443]: time=\"2017-02-21T14:58:16.549055374Z\" level=debug msg=\"attach: stdin: begin\"\r\nFeb 21 14:58:16 myserver dockerd[22443]: time=\"2017-02-21T14:58:16.549112586Z\" level=debug msg=\"attach: stdout: begin\"\r\nFeb 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\"\r\nFeb 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)}\"\r\nFeb 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 > \"\r\n\r\n\r\n# echo $COLUMNS\r\n272\r\n# docker --debug exec -u myuser -ti ded836502956 /bin/bash\r\nDEBU[0000] Error resize: Error response from daemon: rpc error: code = 2 desc = containerd: process not found for container\r\n$ echo $COLUMNS\r\n80\r\n```\r\n\r\nWhen 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:\r\n\r\n```\r\ncurl -v --unix-socket /var/run/docker.sock -X POST \\\r\n     \"http:/v1.25/exec/23683ad3fdccc23c44a4a69c9427df2c1b89dfc35e4d542c2c57a05489c2183a/resize?h=31&w=272\"\r\n\r\n\r\n< HTTP/1.1 200 OK\r\n< Api-Version: 1.25\r\n< Docker-Experimental: false\r\n< Server: Docker/1.13.0 (linux)\r\n```\r\n\r\n**Output of `docker version`:**\r\n\r\n```\r\n# docker version\r\nClient:\r\n Version:      1.13.0\r\n API version:  1.25\r\n Go version:   go1.7.3\r\n Git commit:   49bf474\r\n Built:        Tue Jan 17 09:55:28 2017\r\n OS/Arch:      linux/amd64\r\n\r\nServer:\r\n Version:      1.13.0\r\n API version:  1.25 (minimum version 1.12)\r\n Go version:   go1.7.3\r\n Git commit:   49bf474\r\n Built:        Tue Jan 17 09:55:28 2017\r\n OS/Arch:      linux/amd64\r\n Experimental: false\r\n\r\n\r\n# rpm -qa | grep docker\r\ndocker-engine-selinux-1.13.0-1.el7.centos.noarch\r\ndocker-engine-1.13.0-1.el7.centos.x86_64\r\n\r\n\r\n# cat /etc/redhat-release\r\nCentOS Linux release 7.3.1611 (Core)\r\n```\r\n\r\n**Output of `docker info`:**\r\n\r\n```\r\n# docker info\r\nContainers: 1\r\n Running: 1\r\n Paused: 0\r\n Stopped: 0\r\nImages: 1\r\nServer Version: 1.13.0\r\nStorage Driver: devicemapper\r\n Pool Name: docker-253:0-894645-pool\r\n Pool Blocksize: 65.54 kB\r\n Base Device Size: 80.53 GB\r\n Backing Filesystem: xfs\r\n Data file: /dev/loop0\r\n Metadata file: /dev/loop1\r\n Data Space Used: 1.039 GB\r\n Data Space Total: 107.4 GB\r\n Data Space Available: 101.9 GB\r\n Metadata Space Used: 2.081 MB\r\n Metadata Space Total: 2.147 GB\r\n Metadata Space Available: 2.145 GB\r\n Thin Pool Minimum Free Space: 10.74 GB\r\n Udev Sync Supported: true\r\n Deferred Removal Enabled: false\r\n Deferred Deletion Enabled: false\r\n Deferred Deleted Device Count: 0\r\n Data loop file: /opt/docker/100000.100000/devicemapper/devicemapper/data\r\n WARNING: Usage of loopback devices is strongly discouraged for production use. Use `--storage-opt dm.thinpooldev` to specify a custom block storage device.\r\n Metadata loop file: /opt/docker/100000.100000/devicemapper/devicemapper/metadata\r\n Library Version: 1.02.135-RHEL7 (2016-09-28)\r\nLogging Driver: json-file\r\nCgroup Driver: cgroupfs\r\nPlugins:\r\n Volume: local\r\n Network: bridge host macvlan null overlay\r\nSwarm: inactive\r\nRuntimes: runc\r\nDefault Runtime: runc\r\nInit Binary: docker-init\r\ncontainerd version: 03e5862ec0d8d3b3f750e19fca3ee367e13c090e\r\nrunc version: 2f7393a47307a16f8cee44a37b262e8b81021e3e\r\ninit version: 949e6fa\r\nSecurity Options:\r\n seccomp\r\n  Profile: default\r\n selinux\r\n userns\r\nKernel Version: 3.10.0-514.2.2.el7.x86_64\r\nOperating System: CentOS Linux 7 (Core)\r\nOSType: linux\r\nArchitecture: x86_64\r\nCPUs: 2\r\nTotal Memory: 7.388 GiB\r\nName: myserver\r\nID: OACX:URVN:ALRN:27R6:XKMD:ULVL:OO2V:SOHM:34NA:2ZRQ:72JI:ORMJ\r\nDocker Root Dir: /opt/docker/100000.100000\r\nDebug Mode (client): false\r\nDebug Mode (server): true\r\n File Descriptors: 31\r\n Goroutines: 45\r\n System Time: 2017-02-21T15:01:18.874076279Z\r\n EventsListeners: 1\r\nHttp Proxy: http://proxy01:8888/\r\nHttps Proxy: http://proxy01:8888/\r\nNo Proxy: localhost,127.0.0.1,169.254.169.254,10.0.206.192\r\nRegistry: https://index.docker.io/v1/\r\nWARNING: bridge-nf-call-iptables is disabled\r\nWARNING: bridge-nf-call-ip6tables is disabled\r\nExperimental: false\r\nInsecure Registries:\r\n 127.0.0.0/8\r\nLive Restore Enabled: false\r\n```"}}
{"actor":{"display_login":"thaJeztah"}}