Attachment 1449418 Details for Bug 1588773 – debugging showing that docker is not draining stderr (docker-shim is sending the data)

debugging showing that docker is not draining stderr (docker-shim is sending the data)

file_1588773.txt (text/plain), 4.03 KB, created by Eric Paris on 2018-06-09 17:08:16 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Eric Paris

Created: 2018-06-09 17:08:16 UTC

Size: 4.03 KB

patch

obsolete

># date
>Sat Jun  9 16:29:39 UTC 2018
>
># strace -s 256 -f -p 2698 2>&1 | grep -v 'clock' | grep -v 'futex' | grep -v sched_yield | grep -v pselect | grep -v epoll_wait | grep -v lstat
>strace: Process 2698 attached with 36 threads
>[pid  3454] write(2, "2018-06-08 11:48:45.978652 W | etcdserver: avoid queries with large range/delete range!\n", 88 <unfinished ...>
>[snip]
>
>We have been trying to write to stdout since 2018-06-08. It is now 2018-06-09 (about 29 hours later)
>
># ls -l /proc/2698/fd/2
>l-wx------. 1 root root 64 Jun  5 01:23 /proc/2698/fd/2 -> pipe:[54772]
>
>So we look at the parent docker-shim:
>
># ls -l /proc/2681/fd | grep 54772
>lr-x------. 1 root root 64 Jun  5 01:28 13 -> pipe:[54772]
>
>And at the strace on docker-shim:
>
># strace -f -p 2681
> strace: Process 2681 attached with 10 threads
> [pid  2742] futex(0xc42003d910, FUTEX_WAIT, 0, NULL <unfinished ...>
> [pid  2689] write(22, "2018-06-08 11:40:14.210750 W | e"..., 88 <unfinished ...>
> [pid  2688] futex(0xc42003d510, FUTEX_WAIT, 0, NULL <unfinished ...>
> [pid  2687] futex(0xc4200de110, FUTEX_WAIT, 0, NULL <unfinished ...>
> [pid  2686] futex(0xc42003d110, FUTEX_WAIT, 0, NULL <unfinished ...>
> [pid  2685] read(10,  <unfinished ...>
> [pid  2684] read(6,  <unfinished ...>
> [pid  2683] futex(0x7cc420, FUTEX_WAIT, 0, NULL <unfinished ...>
> [pid  2682] restart_syscall(<... resuming interrupted futex ...> <unfinished ...>
> [pid  2681] futex(0x7b2490, FUTEX_WAIT, 0, NULL
>
>So NOTHING is trying to read from fd 13, which is stderr in the container, this explains why etcd is not moving.
>But we do see pid the docker-shim has been writing to 22 since 8 minutes before the stuck etcd.
>
># ls -l /proc/2681/fd | grep 22
>l-wx------. 1 root root 64 Jun  5 01:28 22 -> /run/docker/libcontainerd/b3bb4a925db3e97280eccb326afb146e375902cf42ae362af8ef9cea7fd8d638/init-stderr
>
>This pipe is also open by the shim as fd 21, 22, 24, and 25, but the strace only shows any usage on fd 22.
>lsof tells us that only pid 1933 also has this fifo open.
>
># ps -ef | grep 1933
>root       1933      1  3 Jun05 ?        04:10:55 /usr/bin/dockerd-current --add-runtime docker-runc=/usr/libexec/docker/docker-runc-current --default-runtime=docker-runc --authorization-plugin=rhel-push-plugin --exec-opt native.cgroupdriver=systemd --userland-proxy-path=/usr/libexec/docker/docker-proxy-current --seccomp-profile=/etc/docker/seccomp.json --selinux-enabled --log-driver json-file --log-opt max-size=50m --signature-verification=False --storage-driver overlay2 --storage-opt overlay2.size=3G --mtu=8951 --add-registry registry.access.redhat.com --add-registry registry.access.redhat.com
>
># ls -l | grep /run/docker/libcontainerd/b3bb4a925db3e97280eccb326afb146e375902cf42ae362af8ef9cea7fd8d638/init-stderr
>lr-x------. 1 root root 64 Jun  5 01:23 26 -> /run/docker/libcontainerd/b3bb4a925db3e97280eccb326afb146e375902cf42ae362af8ef9cea7fd8d638/init-stderr
>l---------. 1 root root 64 Jun  5 01:23 37 -> /run/docker/libcontainerd/b3bb4a925db3e97280eccb326afb146e375902cf42ae362af8ef9cea7fd8d638/init-stderr
>
>So docker has this open as fd 26 and 37.
>An strace of docker (1933) shows nothing listening on 26 or 37.
>
># strace -s 256 -f -p 1933 2>&1 | grep -E '\(26|\(37'
> [NADA]
>
>I wrote a little program to see how full the pipe was:
>
>#include <stdio.h>
>#include <sys/ioctl.h>
>#include <sys/types.h>
>#include <sys/stat.h>
>#include <fcntl.h>
>
>int main(int argc, char *argv[])
>{
>	int fd;
>	int err;
>	int size;
>
>	fd = open(argv[1], O_RDONLY);
>	err = ioctl(fd, FIONREAD, &size);
>	if (err < 0) {
>		printf("fart\n");
>		return 1;
>	}
>
>	printf("size: %d\n", size);
>	return 0;
>}
>
># ./pipe-size /run/docker/libcontainerd/b3bb4a925db3e97280eccb326afb146e375902cf42ae362af8ef9cea7fd8d638/init-stderr
>size: 64006
>
>And if we look at stdout:
># ./pipe-size /run/docker/libcontainerd/b3bb4a925db3e97280eccb326afb146e375902cf42ae362af8ef9cea7fd8d638/init-stdout 
>size: 0
>
>so the docker-shim is forwarding stuff to docker, and docker isn't dealing with it, then the docker-shim and the container at the end hangs forever...

Actions: View

Attachments on bug 1588773: 1449418 | 1449436