test/standalone: reinstate std.ChildProcess tests

[matu3ba]

67d5bfe removed std.ChildProcess tests, suggesting to make them standalone instead. This commit does exactly that after the bug creating SIGPIPE in RealeaseFast is no more with LLVM 15.0.5.

Thanks to @x1ddos for the idea with the compile artifacts and PR improvements.

[matu3ba]

Some more history: #11701 #11736 and the last one where I tried different reduction techniques #13042.

straces created with

/usr/bin/time -v "${HOME}/dev/git/bootstrap/zig-bootstrap/musl/out/zig-x86_64-linux-musl-native/bin/zig" build -p build2 -Drelease --search-prefix "${HOME}/dev/git/bootstrap/zig-bootstrap/musl/out/x86_64-linux-musl-native" --zig-lib-dir lib -Dstatic-llvm
ZIGCACHE=$(fd -uu zig-cache) && rm -fr $ZIGCACHE && fd -uu zig-cache
strace -s 100 -ff -yy ./build2/bin/zig build -Dtest-filter=test/standalone/child_process/build.zig test-standalone &> b2w.strace && echo "b2 successful, not expected"

I compared to all other build modes on Linux glibc Arch derivate Endeavour and the only thing local to the error looked like a bunch of msyncs being in different order or not finished.

before LLVM 15.0.5:

[pid 1813335] fork(strace: Process 1813336 attached                        //////// 1813335 parent, 1813336 child
)                    = 1813336
[pid 1813335] close(0<pipe:[3990968]> <unfinished ...>                     //////// parent closes 3990968
[pid 1813336] dup2(0<pipe:[3990968]>, 0<pipe:[3990968]> <unfinished ...>
[pid 1813335] <... close resumed>)      = 0
[pid 1813336] <... dup2 resumed>)       = 0<pipe:[3990968]>
[pid 1813335] close(5<pipe:[3990969]> <unfinished ...>
[pid 1813336] dup2(5<pipe:[3990969]>, 1</home/user/dev/git/zi/zig/reinstate_childproc/b2.strace> <unfinished ...>
[pid 1813335] <... close resumed>)      = 0
[pid 1813336] <... dup2 resumed>)       = 1<pipe:[3990969]>
[pid 1813336] close(0<pipe:[3990968]> <unfinished ...>                    //////// child closes 3990968 0?
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC <unfinished ...>
[pid 1813336] <... close resumed>)      = 0
[pid 1813335] <... msync resumed>)      = 0
[pid 1813336] close(3<pipe:[3990968]> <unfinished ...>
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC <unfinished ...>
[pid 1813336] <... close resumed>)      = 0
[pid 1813335] <... msync resumed>)      = 0
[pid 1813336] close(4<pipe:[3990969]> <unfinished ...>
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC <unfinished ...>
[pid 1813336] <... close resumed>)      = 0
[pid 1813335] <... msync resumed>)      = 0
[pid 1813336] close(5<pipe:[3990969]> <unfinished ...>
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC <unfinished ...>
[pid 1813336] <... close resumed>)      = 0
[pid 1813335] <... msync resumed>)      = 0
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC <unfinished ...>
[pid 1813336] execve("/home/user/dev/git/zi/zig/reinstate_childproc/test/standalone/child_process/zig-cache/o/3e44b10c999e73196f81e2ce0f7bcded/child", ["/home/user/dev/git/zi/zig"..., "hello arg"], 0x7fff5b5f92d0 /* 83 vars */ <unfinished ...>
[pid 1813335] <... msync resumed>)      = 0
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC) = 0
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC) = 0
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC) = 0
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC) = 0
[pid 1813335] munmap(0x7fd2a7df4000, 4096 <unfinished ...>
[pid 1813336] <... execve resumed>)     = 0
[pid 1813335] <... munmap resumed>)     = 0
[pid 1813335] munmap(0x7fd2a7df3000, 4096) = 0
[pid 1813336] arch_prctl(ARCH_SET_FS, 0x25e018 <unfinished ...>
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC <unfinished ...>
[pid 1813336] <... arch_prctl resumed>) = 0
[pid 1813335] <... msync resumed>)      = 0
[pid 1813336] prlimit64(0, RLIMIT_STACK, {rlim_cur=16384*1024, rlim_max=16384*1024},  <unfinished ...>
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC <unfinished ...>
[pid 1813336] <... prlimit64 resumed>NULL) = 0
[pid 1813335] <... msync resumed>)      = 0
[pid 1813336] rt_sigaction(SIGSEGV, {sa_handler=0x232230, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_RESETHAND|SA_SIGINFO, sa_restorer=0x243090},  <unfinished ...>
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC <unfinished ...>
[pid 1813336] <... rt_sigaction resumed>NULL, 8) = 0
[pid 1813335] <... msync resumed>)      = 0
[pid 1813336] rt_sigaction(SIGILL, {sa_handler=0x232230, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_RESETHAND|SA_SIGINFO, sa_restorer=0x243090},  <unfinished ...>
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC <unfinished ...>
[pid 1813336] <... rt_sigaction resumed>NULL, 8) = 0
[pid 1813335] <... msync resumed>)      = 0
[pid 1813336] rt_sigaction(SIGBUS, {sa_handler=0x232230, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_RESETHAND|SA_SIGINFO, sa_restorer=0x243090},  <unfinished ...>
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC <unfinished ...>
[pid 1813336] <... rt_sigaction resumed>NULL, 8) = 0
[pid 1813335] <... msync resumed>)      = 0
[pid 1813336] rt_sigaction(SIGFPE, {sa_handler=0x232230, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_RESETHAND|SA_SIGINFO, sa_restorer=0x243090},  <unfinished ...>
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC <unfinished ...>
[pid 1813336] <... rt_sigaction resumed>NULL, 8) = 0
[pid 1813335] <... msync resumed>)      = 0
[pid 1813336] write(1<pipe:[3990969]>, "hello from stdout", 17 <unfinished ...>
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC <unfinished ...>
[pid 1813336] <... write resumed>)      = 17
[pid 1813335] <... msync resumed>)      = 0
[pid 1813336] read(0,  <unfinished ...>
[pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC <unfinished ...>
[pid 1813336] <... read resumed>0x7ffda26f5180, 16) = -1 EBADF (Ungültiger Dateideskriptor)
[pid 1813335] <... msync resumed>)      = 0
[pid 1813336] write(2</home/user/dev/git/zi/zig/reinstate_childproc/b2.strace>, "error: ", 7 <unfinished ...>
error: [pid 1813335] msync(0x7fff5b5f8000, 4096, MS_ASYNC <unfinished ...>
[pid 1813336] <... write resumed>)      = 7
[pid 1813335] <... msync resumed>)      = 0
[pid 1813336] write(2</home/user/dev/git/zi/zig/reinstate_childproc/b2.strace>, "NotOpenForReading", 17NotOpenForReading <unfinished ...>
[pid 1813335] munmap(0x7fd2a7df6000, 4096 <unfinished ...>
[pid 1813336] <... write resumed>)      = 17
[pid 1813335] <... munmap resumed>)     = 0
[pid 1813336] write(2</home/user/dev/git/zi/zig/reinstate_childproc/b2.strace>, "\n", 1
 <unfinished ...>
[pid 1813335] munmap(0x7fd2a7df5000, 4096 <unfinished ...>
[pid 1813336] <... write resumed>)      = 1
[pid 1813335] <... munmap resumed>)     = 0
[pid 1813335] write(3<pipe:[3990968]>, "hello from stdin", 16 <unfinished ...>
[pid 1813336] ioctl(2</home/user/dev/git/zi/zig/reinstate_childproc/b2.strace>, TIOCGWINSZ <unfinished ...>
[pid 1813335] <... write resumed>)      = -1 EPIPE (Datenübergabe unterbrochen (broken pipe))
[pid 1813336] <... ioctl resumed>, 0x7ffda26f5018) = -1 ENOTTY (Unpassender IOCTL (I/O-Control) für das Gerät)
[pid 1813335] --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=1813335, si_uid=1000} ---
[pid 1813336] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8a545e5000
[pid 1813336] openat(AT_FDCWD</home/user/dev/git/zi/zig/reinstate_childproc/test/standalone/child_process>, "/proc/self/exe", O_RDONLY|O_NOCTTY|O_CLOEXEC <unfinished ...>
[pid 1813335] +++ killed by SIGPIPE +++

with LLVM 15.0.5:

[pid 354279] fork(strace: Process 354280 attached
)                     = 354280
[pid 354279] close(3<pipe:[784226]> <unfinished ...>
[pid 354280] dup2(3<pipe:[784226]>, 0</dev/pts/3<char 136:3>> <unfinished ...>
[pid 354279] <... close resumed>)       = 0
[pid 354280] <... dup2 resumed>)        = 0<pipe:[784226]>
[pid 354279] close(6<pipe:[784227]> <unfinished ...>
[pid 354280] dup2(6<pipe:[784227]>, 1</home/user/dev/git/zi/zig/reinstate_childproc/b2v.strace> <unfinished ...>
[pid 354279] <... close resumed>)       = 0
[pid 354280] <... dup2 resumed>)        = 1<pipe:[784227]>
[pid 354280] close(3<pipe:[784226]> <unfinished ...>
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC <unfinished ...>
[pid 354280] <... close resumed>)       = 0
[pid 354279] <... msync resumed>)       = 0
[pid 354280] close(4<pipe:[784226]> <unfinished ...>
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC <unfinished ...>
[pid 354280] <... close resumed>)       = 0
[pid 354279] <... msync resumed>)       = 0
[pid 354280] close(5<pipe:[784227]> <unfinished ...>
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC <unfinished ...>
[pid 354280] <... close resumed>)       = 0
[pid 354279] <... msync resumed>)       = 0
[pid 354280] close(6<pipe:[784227]> <unfinished ...>
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC <unfinished ...>
[pid 354280] <... close resumed>)       = 0
[pid 354279] <... msync resumed>)       = 0
[pid 354280] execve("/home/user/dev/git/zi/zig/reinstate_childproc/test/standalone/child_process/zig-cache/o/94db26130d2b07f3e5ea20e7d204d118/child", ["/home/user/dev/git/zi/zig/reinstate_childproc/test/standalone/child_process/zig-cache/o/94db2"..., "hello arg"], 0x7fff22aebe50 /* 76 vars */ <unfinished ...>
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC) = 0
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC) = 0
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC) = 0
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC) = 0
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC) = 0
[pid 354280] <... execve resumed>)      = 0
[pid 354279] munmap(0x7f6c2710d000, 4096) = 0
[pid 354280] arch_prctl(ARCH_SET_FS, 0x25e018 <unfinished ...>
[pid 354279] munmap(0x7f6c2710e000, 4096 <unfinished ...>
[pid 354280] <... arch_prctl resumed>)  = 0
[pid 354279] <... munmap resumed>)      = 0
[pid 354280] prlimit64(0, RLIMIT_STACK, {rlim_cur=16384*1024, rlim_max=16384*1024},  <unfinished ...>
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC <unfinished ...>
[pid 354280] <... prlimit64 resumed>NULL) = 0
[pid 354279] <... msync resumed>)       = 0
[pid 354280] rt_sigaction(SIGSEGV, {sa_handler=0x232240, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_RESETHAND|SA_SIGINFO, sa_restorer=0x2430a0},  <unfinished ...>
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC <unfinished ...>
[pid 354280] <... rt_sigaction resumed>NULL, 8) = 0
[pid 354279] <... msync resumed>)       = 0
[pid 354280] rt_sigaction(SIGILL, {sa_handler=0x232240, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_RESETHAND|SA_SIGINFO, sa_restorer=0x2430a0},  <unfinished ...>
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC <unfinished ...>
[pid 354280] <... rt_sigaction resumed>NULL, 8) = 0
[pid 354279] <... msync resumed>)       = 0
[pid 354280] rt_sigaction(SIGBUS, {sa_handler=0x232240, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_RESETHAND|SA_SIGINFO, sa_restorer=0x2430a0},  <unfinished ...>
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC <unfinished ...>
[pid 354280] <... rt_sigaction resumed>NULL, 8) = 0
[pid 354279] <... msync resumed>)       = 0
[pid 354280] rt_sigaction(SIGFPE, {sa_handler=0x232240, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_RESETHAND|SA_SIGINFO, sa_restorer=0x2430a0},  <unfinished ...>
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC <unfinished ...>
[pid 354280] <... rt_sigaction resumed>NULL, 8) = 0
[pid 354279] <... msync resumed>)       = 0
[pid 354280] write(1<pipe:[784227]>, "hello from stdout", 17 <unfinished ...>
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC <unfinished ...>
[pid 354280] <... write resumed>)       = 17
[pid 354279] <... msync resumed>)       = 0
[pid 354280] read(0<pipe:[784226]>,  <unfinished ...>
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC) = 0
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC) = 0
[pid 354279] msync(0x7fff22aeb000, 4096, MS_ASYNC) = 0
[pid 354279] munmap(0x7f6c2710b000, 4096) = 0
[pid 354279] munmap(0x7f6c2710c000, 4096) = 0
[pid 354279] write(4<pipe:[784226]>, "hello from stdin", 16 <unfinished ...>
[pid 354280] <... read resumed>"hello from stdin", 16) = 16
[pid 354279] <... write resumed>)       = 16
[pid 354280] exit_group(42 <unfinished ...>
[pid 354279] close(4<pipe:[784226]> <unfinished ...>
[pid 354280] <... exit_group resumed>)  = ?
[pid 354279] <... close resumed>)       = 0
[pid 354279] read(5<pipe:[784227]>, "hello from stdout", 17) = 17
[pid 354279] wait4(354280,  <unfinished ...>
[pid 354280] +++ exited with 42 +++
[pid 354279] <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 42}], 0, NULL) = 354280
[pid 354279] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=354280, si_uid=1000, si_status=42, si_utime=0, si_stime=0} ---
[pid 354279] close(5<pipe:[784227]>)    = 0
[pid 354279] poll([{fd=7<anon_inode:[eventfd]>, events=POLLIN}], 1, 0) = 0 (Timeout)
[pid 354279] close(7<anon_inode:[eventfd]>) = 0
[pid 354279] exit_group(0)              = ?
[pid 354279] +++ exited with 0 +++
[pid 354242] <... wait4 resumed>[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 354279
[pid 354242] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=354279, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
[pid 354242] poll([{fd=3<anon_inode:[eventfd]>, events=POLLIN}], 1, 0) = 0 (Timeout)
[pid 354242] close(3<anon_inode:[eventfd]>) = 0
[pid 354242] munmap(0x7f9df2efe000, 16384) = 0
[pid 354242] munmap(0x7f9df2efc000, 8192) = 0
[pid 354242] munmap(0x7f9df2efb000, 4096) = 0
[pid 354242] exit_group(0)              = ?
[pid 354242] +++ exited with 0 +++

[matu3ba]

I'll fix things up a bit more once I know it finally works TM.
Let me know, if anything should be simplified. I think simplifying the error with parent_test_error looks nice and I dont have much of an opinion on comptime fmt.

Price question for next time: Is there a standard procedure catalogue for reporting/reducing such weird race conditions (I guess miscompilations) ?

[andrewrk]

It looks good, thank you. If you rebase this against master I will merge it.

[matu3ba]

This was added to prevent people misunderstanding what the test_runner ist for like in this PR.

[matu3ba]

@andrewrk done. I was so free to add this one line to specify the purpose of the default test runner.