search

tokio-rs / tokio

A runtime for writing reliable asynchronous applications with Rust. Provides I/O, networking, scheduling, timers, ...
https://tokio.rs
MIT License
26.86k stars 2.48k forks source link

tokio::process::ChildStdin cannot detect the termination of the child process on Linux? #2174

Closed masnagam closed 4 years ago

masnagam commented 4 years ago

Version

Platform

Docker rust:1.40.0

$ uname -a
Linux beb1cf5e2935 4.19.76-linuxkit #1 SMP Thu Oct 17 19:31:58 UTC 2019 x86_64 GNU/Linux

Subcrates

Description

In the following situation, poll_write() on tokio::process::ChildStdin will never called when killing the child process.

  1. Spawn a child process
  2. Spawn a task to write data to the stdin of the child process until pending
  3. Kill the child process
  4. Wait for the task to finish

I expected that the task ends with a broken pipe error, but it never ends actually. This issue doesn't occur on macOS. I haven't checked on Windows.

I prepared a reproduction environment for Linux. Try the following code on Linux or VS Code Remote Container:

It seems that there is some issue in tokio-process, tokio-io or mio.

ipetkov commented 4 years ago

In the provided example, the child process (cat) is spawned with its stdin and stdout redirected from/to the parent. When the input is written, cat will immediately block while trying to write to it's stdout, since the parent never tries to read from that pipe.

Although the child.kill() is succeeding, I'm not sure why the kernel doesn't appear to kill the process. On macOS I get a broken pipe error from cat and the program will exit (maybe on linux the kill waits until the write to stdout terminates?)

Can you try setting .stdout(Stdio::null()) and see if the problem still occurs? If it does, can you check if the state of the cat process and see if it is a zombie process or still considered active?

masnagam commented 4 years ago

I confirmed in the Docker container case that cat is killed by child.kill(), using ps aux | grep cat.

Can you try setting .stdout(Stdio::null()) and see if the problem still occurs?

Yes, sure.

Maybe, it's difficult.. Because if we set .stdout(Stdio::null()), the input data is consumed quickly and it's not easy to block in input.write_all(&data).await. But, anyway, I'll try that.

masnagam commented 4 years ago

We can reproduce the same issue with null stdout. However, the reproduction rate is not 100%, maybe, due to the reason as I wrote the previous comment.

I confirmed that the cat process doesn't exist by using ps aux | grep cat in the Docker container.

masnagam commented 4 years ago

Updated the test program in order to check the task states: https://github.com/masnagam/rust-case-studies/commit/294849f5243e8a0b6c1956a8b288b64fba7afe23

When the issue occurs, the task is blocked at input.write_all(&data).await:

Waiting for the task...: writing(true) shutdown(false)

When the task ends due to a broken pipe error:

Input error: Broken pipe (os error 32)
Waiting for the task...: writing(false) shutdown(false)
Done

In this case SIGCHLD occurs.

masnagam commented 4 years ago

There might be some issues regarding signal handlings in tokio.

The SIGCHLD for the child process cat is handled in Reaper::poll(). However, the SIGCHLD seems not to handle in ChildStdin and the Reaper seems not to notify the SIGCHLD of ChildStdin.

Is my understanding correct?

If correct, I think that it's necessary to wake up the pending write_all() task in some way.

ipetkov commented 4 years ago

Thanks for the detailed notes, I can confirm that I'm also able to successfully reproduce this on linux myself.

It appears that the root of the issue is that a task waiting to write to the child's stdin is not being woken up if the pipe reader goes away, even though the child process is being successfully killed and reaped.

As far as I can tell, the PollEvented wrapper around the child's stdin handle is correctly registering for hup interest (aka the other end of the pipe hung up and we should wake to then run into an error or complete). My theory as to what could be going wrong:

ipetkov commented 4 years ago

I slightly tweaked the program as follows:

I ran the program via strace, the output is below (pasting it here so people can take a look, I can come back later and annotate the report with what I can see happening given my understanding of the tokio internals)

strace output 
execve("./target/debug/tokio-process-stdio-hup", ["./target/debug/tokio-process-std"...], 0x7fff0a8e0838 /* 21 vars */) = 0
brk(NULL)                               = 0x561cd1408000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=28038, ...}) = 0
mmap(NULL, 28038, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f8af0e18000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P\16\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=14560, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8af0e16000
mmap(NULL, 2109712, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f8af09f4000
mprotect(0x7f8af09f7000, 2093056, PROT_NONE) = 0
mmap(0x7f8af0bf6000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f8af0bf6000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/librt.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\"\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=31680, ...}) = 0
mmap(NULL, 2128864, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f8af07ec000
mprotect(0x7f8af07f3000, 2093056, PROT_NONE) = 0
mmap(0x7f8af09f2000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7f8af09f2000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000b\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=144976, ...}) = 0
mmap(NULL, 2221184, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f8af05cd000
mprotect(0x7f8af05e7000, 2093056, PROT_NONE) = 0
mmap(0x7f8af07e6000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x19000) = 0x7f8af07e6000
mmap(0x7f8af07e8000, 13440, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f8af07e8000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libgcc_s.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\300*\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=96616, ...}) = 0
mmap(NULL, 2192432, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f8af03b5000
mprotect(0x7f8af03cc000, 2093056, PROT_NONE) = 0
mmap(0x7f8af05cb000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16000) = 0x7f8af05cb000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\34\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=2030544, ...}) = 0
mmap(NULL, 4131552, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f8aeffc4000
mprotect(0x7f8af01ab000, 2097152, PROT_NONE) = 0
mmap(0x7f8af03ab000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1e7000) = 0x7f8af03ab000
mmap(0x7f8af03b1000, 15072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f8af03b1000
close(3)                                = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8af0e14000
arch_prctl(ARCH_SET_FS, 0x7f8af0e15400) = 0
mprotect(0x7f8af03ab000, 16384, PROT_READ) = 0
mprotect(0x7f8af05cb000, 4096, PROT_READ) = 0
mprotect(0x7f8af07e6000, 4096, PROT_READ) = 0
mprotect(0x7f8af09f2000, 4096, PROT_READ) = 0
mprotect(0x7f8af0bf6000, 4096, PROT_READ) = 0
mprotect(0x561cd064d000, 69632, PROT_READ) = 0
mprotect(0x7f8af0e1f000, 4096, PROT_READ) = 0
munmap(0x7f8af0e18000, 28038)           = 0
set_tid_address(0x7f8af0e156d0)         = 3543
set_robust_list(0x7f8af0e156e0, 24)     = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7f8af05d2cb0, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f8af05df890}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0x7f8af05d2d50, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f8af05df890}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[PIPE], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f8af0002f20}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
brk(NULL)                               = 0x561cd1408000
brk(0x561cd1429000)                     = 0x561cd1429000
openat(AT_FDCWD, "/proc/self/maps", O_RDONLY|O_CLOEXEC) = 3
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
read(3, "561cd0262000-561cd044e000 r-xp 0"..., 1024) = 1024
read(3, "f8af03b5000 rw-p 00000000 00:00 "..., 1024) = 1024
read(3, "73                       /lib/x8"..., 1024) = 1024
read(3, " 2068                       /lib"..., 1024) = 541
close(3)                                = 0
sched_getaffinity(3543, 32, [0, 1])     = 8
rt_sigaction(SIGSEGV, {sa_handler=0x561cd03c95d0, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7f8af05df890}, NULL, 8) = 0
rt_sigaction(SIGBUS, {sa_handler=0x561cd03c95d0, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7f8af05df890}, NULL, 8) = 0
sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8af0e1d000
sigaltstack({ss_sp=0x7f8af0e1d000, ss_flags=0, ss_size=8192}, NULL) = 0
openat(AT_FDCWD, "/proc/cpuinfo", O_RDONLY|O_CLOEXEC) = 3
fcntl(3, F_GETFD)                       = 0x1 (flags FD_CLOEXEC)
getrandom("\x42\xfc\xb4\x6f\xd1\xc1\x49\xbd\x8e\x99\x9f\xe9\xb6\xf5\xe0\xf2", 16, GRND_NONBLOCK) = 16
read(3, "processor\t: 0\nvendor_id\t: Genuin"..., 8192) = 1714
read(3, "", 8192)                       = 0
close(3)                                = 0
futex(0x7f8af0bf70c8, FUTEX_WAKE_PRIVATE, 2147483647) = 0
epoll_create1(EPOLL_CLOEXEC)            = 3
pipe2([4, 5], O_NONBLOCK|O_CLOEXEC)     = 0
epoll_ctl(3, EPOLL_CTL_ADD, 4, {EPOLLIN|EPOLLET, {u32=4294967295, u64=18446744073709551615}}) = 0
pipe2([6, 7], O_CLOEXEC)                = 0
openat(AT_FDCWD, "/dev/null", O_WRONLY|O_CLOEXEC) = 8
prlimit64(0, RLIMIT_NOFILE, NULL, {rlim_cur=1024, rlim_max=1024*1024}) = 0
prlimit64(0, RLIMIT_NOFILE, NULL, {rlim_cur=1024, rlim_max=1024*1024}) = 0
prlimit64(0, RLIMIT_NOFILE, NULL, {rlim_cur=1024, rlim_max=1024*1024}) = 0
prlimit64(0, RLIMIT_NOFILE, NULL, {rlim_cur=1024, rlim_max=1024*1024}) = 0
mmap(NULL, 36864, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f8af0e0b000
rt_sigprocmask(SIG_BLOCK, ~[], [], 8)   = 0
clone(strace: Process 3544 attached
 
[pid  3544] rt_sigprocmask(SIG_BLOCK, NULL, ~[KILL STOP], 8) = 0
[pid  3544] rt_sigaction(SIGHUP, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGHUP, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGINT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGINT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGQUIT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGILL, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGILL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGTRAP, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGTRAP, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGABRT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGABRT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGBUS, NULL, {sa_handler=0x561cd03c95d0, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7f8af05df890}, 8) = 0
[pid  3544] rt_sigaction(SIGBUS, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGFPE, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGFPE, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGUSR1, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGUSR1, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGSEGV, NULL, {sa_handler=0x561cd03c95d0, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7f8af05df890}, 8) = 0
[pid  3544] rt_sigaction(SIGSEGV, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGUSR2, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGUSR2, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGPIPE, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGALRM, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGALRM, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGTERM, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGTERM, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGSTKFLT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGSTKFLT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGCHLD, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGCHLD, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGCONT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGCONT, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGTSTP, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGTSTP, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGTTIN, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGTTIN, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGTTOU, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGTTOU, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGURG, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGURG, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGXCPU, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGXCPU, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGXFSZ, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGXFSZ, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGVTALRM, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGVTALRM, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGPROF, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGPROF, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGWINCH, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGWINCH, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGIO, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGIO, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGPWR, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGPWR, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGSYS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGSYS, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRTMIN, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_1, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_2, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_2, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_3, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_3, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_4, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_4, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_5, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_5, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_6, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_6, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_7, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_7, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_8, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_8, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_9, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_9, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_10, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_10, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_11, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_11, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_12, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_12, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_13, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_13, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_14, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_14, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_15, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_15, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_16, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_16, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_17, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_17, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_18, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_18, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_19, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_19, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_20, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_20, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_21, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_21, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_22, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_22, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_23, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_23, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_24, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_24, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_25, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_25, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_26, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_26, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_27, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_27, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_28, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_28, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_29, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_29, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_30, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_30, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_31, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_31, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGRT_32, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGRT_32, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f8af0002f20}, NULL, 8) = 0
[pid  3544] dup2(6, 0)                  = 0
[pid  3544] dup2(8, 1)                  = 1
[pid  3544] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  3544] execve("/home/vagrant/.cargo/bin/sh", ["sh", "-c", "exec 0<&-;"], 0x7ffca7d426c8 /* 21 vars */) = -1 ENOENT (No such file or directory)
[pid  3544] execve("/usr/local/sbin/sh", ["sh", "-c", "exec 0<&-;"], 0x7ffca7d426c8 /* 21 vars */) = -1 ENOENT (No such file or directory)
[pid  3544] execve("/usr/local/bin/sh", ["sh", "-c", "exec 0<&-;"], 0x7ffca7d426c8 /* 21 vars */) = -1 ENOENT (No such file or directory)
[pid  3544] execve("/usr/sbin/sh", ["sh", "-c", "exec 0<&-;"], 0x7ffca7d426c8 /* 21 vars */) = -1 ENOENT (No such file or directory)
[pid  3544] execve("/usr/bin/sh", ["sh", "-c", "exec 0<&-;"], 0x7ffca7d426c8 /* 21 vars */) = -1 ENOENT (No such file or directory)
[pid  3544] execve("/sbin/sh", ["sh", "-c", "exec 0<&-;"], 0x7ffca7d426c8 /* 21 vars */) = -1 ENOENT (No such file or directory)
[pid  3544] execve("/bin/sh", ["sh", "-c", "exec 0<&-;"], 0x7ffca7d426c8 /* 21 vars */ 
[pid  3543] <... clone resumed> child_stack=0x7f8af0e13ff0, flags=CLONE_VM|CLONE_VFORK|SIGCHLD) = 3544
[pid  3543] munmap(0x7f8af0e0b000, 36864) = 0
[pid  3543] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  3543] close(6)                    = 0
[pid  3543] close(8)                    = 0
[pid  3543] fcntl(7, F_GETFL)           = 0x1 (flags O_WRONLY)
[pid  3543] fcntl(7, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
[pid  3543] epoll_ctl(3, EPOLL_CTL_ADD, 7, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLET, {u32=0, u64=0}}) = 0
[pid  3543] socketpair(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0, [6, 8]) = 0
[pid  3543] rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
[pid  3543] rt_sigaction(SIGCHLD, {sa_handler=0x561cd037bbc0, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO|SA_NOCLDSTOP, sa_restorer=0x7f8af05df890}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3543] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  3543] fcntl(6, F_DUPFD_CLOEXEC, 0) = 9
[pid  3543] fcntl(9, F_GETFD)           = 0x1 (flags FD_CLOEXEC)
[pid  3543] epoll_ctl(3, EPOLL_CTL_ADD, 9, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLET, {u32=1, u64=1}}) = 0
[pid  3543] wait4(3544, 0x7ffca7d3c5e8, WNOHANG, NULL) = 0
[pid  3543] epoll_wait(3, [{EPOLLOUT, {u32=0, u64=0}}, {EPOLLOUT, {u32=1, u64=1}}], 1024, -1) = 2
[pid  3543] wait4(3544, 0x7ffca7d3c5e8, WNOHANG, NULL) = 0
[pid  3543] write(7, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
[pid  3543] write(7, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
[pid  3543] write(7, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
[pid  3543] write(7, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
[pid  3543] write(7, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
[pid  3543] write(7, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
[pid  3543] write(7, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
[pid  3543] write(7, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
[pid  3543] write(7, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = -1 EAGAIN (Resource temporarily unavailable)
[pid  3543] epoll_wait(3,  
[pid  3544] <... execve resumed> )      = 0
[pid  3544] brk(NULL)                   = 0x55a90874b000
[pid  3544] access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
[pid  3544] access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
[pid  3544] openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
[pid  3544] fstat(3, {st_mode=S_IFREG|0644, st_size=28038, ...}) = 0
[pid  3544] mmap(NULL, 28038, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f355eb9c000
[pid  3544] close(3)                    = 0
[pid  3544] access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
[pid  3544] openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
[pid  3544] read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\34\2\0\0\0\0\0"..., 832) = 832
[pid  3544] fstat(3, {st_mode=S_IFREG|0755, st_size=2030544, ...}) = 0
[pid  3544] mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f355eb9a000
[pid  3544] mmap(NULL, 4131552, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f355e58b000
[pid  3544] mprotect(0x7f355e772000, 2097152, PROT_NONE) = 0
[pid  3544] mmap(0x7f355e972000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1e7000) = 0x7f355e972000
[pid  3544] mmap(0x7f355e978000, 15072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f355e978000
[pid  3544] close(3)                    = 0
[pid  3544] arch_prctl(ARCH_SET_FS, 0x7f355eb9b540) = 0
[pid  3544] mprotect(0x7f355e972000, 16384, PROT_READ) = 0
[pid  3544] mprotect(0x55a907aad000, 8192, PROT_READ) = 0
[pid  3544] mprotect(0x7f355eba3000, 4096, PROT_READ) = 0
[pid  3544] munmap(0x7f355eb9c000, 28038) = 0
[pid  3544] getuid()                    = 1000
[pid  3544] getgid()                    = 1000
[pid  3544] getpid()                    = 3544
[pid  3544] rt_sigaction(SIGCHLD, {sa_handler=0x55a9078a4200, sa_mask=~[RTMIN RT_1], sa_flags=SA_RESTORER, sa_restorer=0x7f355e5c9f20}, NULL, 8) = 0
[pid  3544] geteuid()                   = 1000
[pid  3544] brk(NULL)                   = 0x55a90874b000
[pid  3544] brk(0x55a90876c000)         = 0x55a90876c000
[pid  3544] getppid()                   = 3543
[pid  3544] stat("/home/vagrant/rust-case-studies/tokio-process-stdio-hup", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
[pid  3544] stat(".", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
[pid  3544] geteuid()                   = 1000
[pid  3544] getegid()                   = 1000
[pid  3544] rt_sigaction(SIGINT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGINT, {sa_handler=0x55a9078a4200, sa_mask=~[RTMIN RT_1], sa_flags=SA_RESTORER, sa_restorer=0x7f355e5c9f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGQUIT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGQUIT, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1], sa_flags=SA_RESTORER, sa_restorer=0x7f355e5c9f20}, NULL, 8) = 0
[pid  3544] rt_sigaction(SIGTERM, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
[pid  3544] rt_sigaction(SIGTERM, {sa_handler=SIG_DFL, sa_mask=~[RTMIN RT_1], sa_flags=SA_RESTORER, sa_restorer=0x7f355e5c9f20}, NULL, 8) = 0
[pid  3544] fcntl(0, F_DUPFD, 10)       = 10
[pid  3544] close(0)                    = 0
[pid  3544] fcntl(10, F_SETFD, FD_CLOEXEC) = 0
[pid  3544] close(10 
[pid  3543] <... epoll_wait resumed> [{EPOLLERR, {u32=0, u64=0}}], 1024, -1) = 1
[pid  3543] wait4(3544, 0x7ffca7d3c5e8, WNOHANG, NULL) = 0
[pid  3543] epoll_wait(3,  
[pid  3544] <... close resumed> )       = 0
[pid  3544] exit_group(0)               = ?
[pid  3544] +++ exited with 0 +++
<... epoll_wait resumed> 0x561cd140ade0, 1024, -1) = -1 EINTR (Interrupted system call)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=3544, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
write(8, "\1", 1)                       = 1
rt_sigreturn({mask=[]})                 = -1 EINTR (Interrupted system call)
epoll_wait(3, [{EPOLLIN|EPOLLOUT, {u32=1, u64=1}}], 1024, -1) = 1
recvfrom(9, "\1", 128, 0, NULL, NULL)   = 1
recvfrom(9, 0x7ffca7d3c4b0, 128, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
wait4(3544, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG, NULL) = 3544
epoll_ctl(3, EPOLL_CTL_DEL, 9, 0x7ffca7d3c550) = 0
close(9)                                = 0
write(1, "Waiting for the task...: writing"..., 55Waiting for the task...: writing(true) shutdown(false)
) = 55
epoll_wait(3, [], 1024, 0)              = 0
epoll_wait(3, [], 1024, 0)              = 0
epoll_wait(3, ^Cstrace: Process 3543 detached
masnagam commented 4 years ago

Thank you for your comments and investigation.

I updated the test program according to your comments. I also added workaround patches, but these are NOT perfect solutions.

I'm not familiar with syscalls, but it seems that no EPOLLHUP was specified in epoll_ctl():

pipe2([6, 7], O_CLOEXEC)                = 0
...
[pid  3544] dup2(6, 0)                  = 0
...
[pid  3543] epoll_ctl(3, EPOLL_CTL_ADD, 7, {EPOLLIN|EPOLLPRI|EPOLLOUT|EPOLLET, {u32=0, u64=0}}) = 0
ipetkov commented 4 years ago

I updated the test program according to your comments. I also added workaround patches, but these are NOT perfect solutions.

Yes I agree completely, something is definitely amiss here. I've asked @kleimkuhler to take a look when he's got a chance since he's more familiar with the reactor/mio internals than I am :)

masnagam commented 4 years ago

Thank you for your reply.

UnixReady::hup() passed in tokio::process::unix is never used in mio like blow: https://github.com/tokio-rs/mio/blob/v0.6.20/src/sys/unix/epoll.rs#L133

According to the description below, epoll_wait() always waits for EPOLLHUP: http://man7.org/linux/man-pages/man7/epoll.7.html

That might be the reason why mio doesn't check UnixReady::hup().

In the master branch of mio, EPOLLRDHUP is used if a specified fd is readable. However, no special flags are added for a writable fd. I haven't confirmed, but a similar issue might occur in the latest mio.

kleimkuhler commented 4 years ago

According to the description below, epoll_wait() always waits for EPOLLHUP

Hi @masnagam. That is correct. EPOLLHUP does not need to be explicitly set in the events passed in to the epoll instance. However, EPOLLRDHUP does need to be explicitly listed as an event of interest in order to get wake ups when that event occurs.

EPOLLRDHUP occurs when socket has shutdown it's read half. It also occurs when a socket has observed the FIN packet sent by it's peer shutting down it's read half.

I've spent some time looking into the issue above and I have not (so far) produced something that is 100% reliable by registering interest in additional events. Even when the spawned task registers interest in EPOLLRDHUP and tries to write to when that occurs, I'm not seeing that event always occur.

What I'm still looking into is what sort of shutdown process the child process goes through when it closes. If it closes without properly calling shutdown(fd, SHUT_RD) / shutdown(fd, SHUT_RDWR), then there is nothing for the spawned task to acknowledge and no events would occur.

I'll update this issue as I continue looking into it. I have the availability to continue looking into it this evening/tomorrow.

masnagam commented 4 years ago

Thank you for your explanation, @kleimkuhler.

I updated tokio in my test program. This issue still occurs in tokio v0.2.11 (w/ mio v0.6.21).

Please let me know if there is anything I can help you.

masnagam commented 4 years ago

@kleimkuhler I slightly improved execution time by replacing tokio::time::delay_for() with rx.await. https://github.com/masnagam/rust-case-studies/commit/02e5d589fe0773f07451f1d791333b8ca5ec3177

This change improves test execution time.

ipetkov commented 4 years ago

@masnagam I believe #2218 should fix this issue once it lands

masnagam commented 4 years ago

@ipetkov @kleimkuhler Thank you for your efforts!

Unit test execution time may be improved by applying https://github.com/masnagam/rust-case-studies/commit/02e5d589fe0773f07451f1d791333b8ca5ec3177 which removes tokio::time::delay_for() and notifies of pending in write_all() by using oneshot::channel().