[Toybox] weird timeout flake

Colin Cross ccross at google.com
Tue Oct 3 21:43:45 PDT 2023


I caught it running in strace.  There's some differences in signal
setup in the forked child, the child exits with 126 in both the good
and bad cases, but the parent exits with 127 after wait4 returns
ECHILD in the bad case.

The good case, child exits with 126, parent exits with 126:
rt_sigaction(SIGCHLD, {sa_handler=0x62dec726e4, sa_mask=[],
sa_flags=SA_NOCLDSTOP}, NULL, 8) = 0
clone(child_stack=NULL,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x7aeae52190) = 9374
strace: Process 9374 attached
[pid  9374] prctl(PR_SET_VMA, PR_SET_VMA_ANON_NAME, 0x7ae9b4b000,
16384, "stack_and_tls:main") = 0
[pid  9373] rt_sigaction(SIGTTIN, {sa_handler=SIG_IGN, sa_mask=[],
sa_flags=0}, NULL, 8) = 0
[pid  9373] rt_sigaction(SIGTTOU, {sa_handler=SIG_IGN, sa_mask=[],
sa_flags=0}, NULL, 8) = 0
[pid  9373] rt_sigaction(SIGTSTP, {sa_handler=SIG_IGN, sa_mask=[],
sa_flags=0}, NULL, 8) = 0
[pid  9373] pipe2([3, 4], 0)            = 0
[pid  9373] ppoll([{fd=4, events=POLLIN}], 1, {tv_sec=0,
tv_nsec=100000000}, NULL, 0 <unfinished ...>
[pid  9374] rt_sigaction(SIGCHLD, {sa_handler=SIG_DFL, sa_mask=[],
sa_flags=0}, NULL, 8) = 0
[pid  9374] setpgid(0, 0)               = 0
[pid  9374] execve("/", ["/"], 0x7fcb8db718 /* 26 vars */) = -1 EACCES
(Permission denied)
[pid  9374] write(2, "timeout: ", 9timeout: )    = 9
[pid  9374] write(2, "exec /", 6exec /)       = 6
[pid  9374] write(2, ": Permission denied", 19: Permission denied) = 19
[pid  9374] write(2, "\n", 1
)           = 1
[pid  9374] exit_group(126)             = ?
[pid  9374] +++ exited with 126 +++
<... ppoll resumed> )                   = ? ERESTARTNOHAND (To be
restarted if no handler)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=9374,
si_uid=2000, si_status=126, si_utime=0, si_stime=0} ---
rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0
rt_sigaction(SIGCHLD, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, NULL, 8) = 0
close(3)                                = 0
close(4)                                = 0
wait4(9374, [{WIFEXITED(s) && WEXITSTATUS(s) == 126}], 0, NULL) = 9374
exit_group(126)                         = ?
+++ exited with 126 +++

The bad case, child exits with 126, parent exits with 127:
rt_sigaction(SIGCHLD, {sa_handler=0x5fda0c26e4, sa_mask=[],
sa_flags=SA_NOCLDSTOP}, NULL, 8) = 0
clone(child_stack=NULL,
flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
child_tidptr=0x7eadf59190) = 9378
strace: Process 9378 attached
[pid  9378] prctl(PR_SET_VMA, PR_SET_VMA_ANON_NAME, 0x7eacc52000,
16384, "stack_and_tls:main") = 0
[pid  9378] rt_sigaction(SIGCHLD, {sa_handler=SIG_DFL, sa_mask=[],
sa_flags=0}, NULL, 8) = 0
[pid  9378] setpgid(0, 0)               = 0
[pid  9378] execve("/", ["/"], 0x7feb7bad98 /* 26 vars */) = -1 EACCES
(Permission denied)
[pid  9378] write(2, "timeout: ", 9timeout: )    = 9
[pid  9378] write(2, "exec /", 6exec /)       = 6
[pid  9378] write(2, ": Permission denied", 19: Permission denied) = 19
[pid  9378] write(2, "\n", 1
)           = 1
[pid  9378] exit_group(126)             = ?
[pid  9378] +++ exited with 126 +++
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=9378,
si_uid=2000, si_status=126, si_utime=0, si_stime=0} ---
rt_sigprocmask(SIG_SETMASK, [RTMIN], NULL, 8) = 0
rt_sigaction(SIGCHLD, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, NULL, 8) = 0
wait4(0, 0xe000007feb7baae0, 0, NULL)   = -1 ECHILD (No child processes)
exit_group(127)                         = ?
+++ exited with 127 +++


More information about the Toybox mailing list