help debugging flaky posix/tst-waitid.c test

[Adhemerval Zanella Netto]

On 13/02/25 19:11, Aurelien Jarno wrote:
> On 2025-02-12 09:33, Adhemerval Zanella Netto wrote:
>>
>>
>> On 08/02/25 12:46, Aurelien Jarno wrote:
>>> Hi,
>>>
>>> The posix/tst-waitid.c appears to be flaky, although with a low
>>> probability to fail, but that's bad for continuous integration. Under
>>> heavy load, it crashes around once over 80000 times in my tests, but
>>> there is a way to increase the probability (see below). This happens at
>>> least on aarch64, riscv64 and x86-64, so it does not seems architecture
>>> specific at a first glance.
>>>
>>> When it happens, it fails with:
>>>
>>>   tst-waitid.c:73: numeric comparison failure
>>>      left: 0 (0x0); from: siginfo.si_status
>>>     right: 19 (0x13); from: status
>>>   error: 1 test failures
>>>
>>> This happens for the test on lines 156-173, which basically:
>>> - send a SIGSTOP to the child
>>> - wait for the child to appear in "T" state in /proc/$pid/status
>>> - call waitid with WEXITED|WSTOPPED on the child
>>> - call sigwaitinfo on the child
>>>
>>> In that later call, the siginfo.si_status field on the child ends-up
>>> with 0 instead of SIGSTOP.
>>>
>>> I have done some more tests on a separate code and it seems that this
>>> happens when kill, waitid and sigwaitinfo are called very quickly after
>>> each other. My guess is that this behaviour is explained by the
>>> following comment in that code:
>>>
>>>   /* Wait the child stop.  The waitid call below will block until it has
>>>      stopped, but if we are real quick and enter the waitid system call
>>>      before the SIGCHLD has been generated, then it will be discarded and
>>>      never delivered.  */
>>>
>>> It seems that the call to support_process_state_wait (pid, stop_state)
>>> should prevent that, but I wonder if there is a small race condition
>>> left.  What I observed is that the 10ms nanosleep in
>>> support_process_state_wait between check of /proc/$pid/status makes the
>>> issue less probable. In other word, the following patch increases the
>>> chances for the tst-waitid test to fail:
>>>
>>> --- a/support/support_process_state.c
>>> +++ b/support/support_process_state.c
>>> @@ -80,9 +80,6 @@ support_process_state_wait (pid_t pid, enum support_process_state state)
>>>  
>>>        rewind (fstatus);
>>>        fflush (fstatus);
>>> -
>>> -      if (nanosleep (&(struct timespec) { 0, 10000000 }, NULL) != 0)
>>> -	FAIL_EXIT1 ("nanosleep: %m");
>>>      }
>>>  
>>>    free (line);
>>>
>>> Of course using strace here just hides the issue. Any idea how to debug
>>> or fix the issue?
>>
>> It seems that we can't really rely on siginfo_t::si_status being SIGSTOP
>> after a waitid call that returns info.si_status equal to SIGSTOP. Skimming
>> through kernel code, it seems that for CLD_STOPPED the si_status is obtained
>> from tsk->signal->group_exit_code (kernel/signal.c - do_notify_parent_cldstop),
>> but I can't really tell why on how it can be zero in this scenario.
>>
>> The tools/testing/selftests/pidfd/pidfd_wait.c also checks CLD_STOPPED,
>> but it does not check si_status.  I think we should ignore it for now.
> 
> Thanks for your feedback and for looking at that.
> 
> I have done further test, and from them and from the comment in
> tst-waitid.c, siginfo_t::si_status ends up being 0 if waitid() is called
> before SIGCHLD has been generated.
> 
> The test is waiting for the child to switch to CLD_STOPPED, but it seems
> the SIGCHLD is generated a tiny bit after. So there is a tiny window of
> time where the child is stopped but calling waitid followed by
> sigwaitinfo will return siginfo_t::si_status as 0.
> 
> In that regard the following patch is enough to fix the issue for me and
> reliably get siginfo_t::si_status being SIGSTOP (tested on 10 millions
> executions):
> 
> --- a/posix/tst-waitid.c
> +++ b/posix/tst-waitid.c
> @@ -162,6 +162,7 @@ do_test_waitd_common (idtype_t type, pid_t pid)
>       before the SIGCHLD has been generated, then it will be discarded and
>       never delivered.  */
>    support_process_state_wait (pid, stop_state);
> +  nanosleep (&(struct timespec) { 0, 10000000 }, NULL);
>  
>    fail = waitid (type, pid, &info, WEXITED|WSTOPPED);
>    TEST_COMPARE (fail, 0);
> 
> However using a fixed delay in a test is never satisfactory and maybe
> the best is to stop checking that info.si_status equal to SIGSTOP.
> 

I think a better way would to just remove the si_status check if we can not
guarantee the required synchronization.  The sleep kind of work around
sometimes require us to reevaluate when new chips and/or kernel version.