diff mbox series

selftests/harness: Flush stdout before forking

Message ID 20200917041519.3284582-1-mpe@ellerman.id.au
State Accepted
Commit c8bd596f9388bceda6cf008d554cbb1a4f2244e7
Headers show
Series selftests/harness: Flush stdout before forking | expand

Commit Message

Michael Ellerman Sept. 17, 2020, 4:15 a.m. UTC
The test harness forks() a child to run each test. Both the parent and
the child print to stdout using libc functions. That can lead to
duplicated (or more) output if the libc buffers are not flushed before
forking.

It's generally not seen when running programs directly, because stdout
will usually be line buffered when it's pointing to a terminal.

This was noticed when running the seccomp_bpf test, eg:

  $ ./seccomp_bpf | tee test.log
  $ grep -c "TAP version 13" test.log
  2

But we only expect the TAP header to appear once.

It can be exacerbated using stdbuf to increase the buffer size:

  $ stdbuf -o 1MB ./seccomp_bpf > test.log
  $ grep -c "TAP version 13" test.log
  13

The fix is simple, we just flush stdout & stderr before fork. Usually
stderr is unbuffered, but that can be changed, so flush it as well
just to be safe.

Signed-off-by: Michael Ellerman <mpe@ellerman.id.au>
---
 tools/testing/selftests/kselftest_harness.h | 5 +++++
 1 file changed, 5 insertions(+)

Comments

Max Filippov Sept. 17, 2020, 4:53 a.m. UTC | #1
On Wed, Sep 16, 2020 at 9:16 PM Michael Ellerman <mpe@ellerman.id.au> wrote:
>
> The test harness forks() a child to run each test. Both the parent and
> the child print to stdout using libc functions. That can lead to
> duplicated (or more) output if the libc buffers are not flushed before
> forking.
>
> It's generally not seen when running programs directly, because stdout
> will usually be line buffered when it's pointing to a terminal.
>
> This was noticed when running the seccomp_bpf test, eg:
>
>   $ ./seccomp_bpf | tee test.log
>   $ grep -c "TAP version 13" test.log
>   2
>
> But we only expect the TAP header to appear once.
>
> It can be exacerbated using stdbuf to increase the buffer size:
>
>   $ stdbuf -o 1MB ./seccomp_bpf > test.log
>   $ grep -c "TAP version 13" test.log
>   13
>
> The fix is simple, we just flush stdout & stderr before fork. Usually
> stderr is unbuffered, but that can be changed, so flush it as well
> just to be safe.
>
> Signed-off-by: Michael Ellerman <mpe@ellerman.id.au>
> ---
>  tools/testing/selftests/kselftest_harness.h | 5 +++++
>  1 file changed, 5 insertions(+)

Tested-by: Max Filippov <jcmvbkbc@gmail.com>
Shuah Khan Sept. 17, 2020, 12:58 p.m. UTC | #2
On 9/16/20 10:53 PM, Max Filippov wrote:
> On Wed, Sep 16, 2020 at 9:16 PM Michael Ellerman <mpe@ellerman.id.au> wrote:
>>
>> The test harness forks() a child to run each test. Both the parent and
>> the child print to stdout using libc functions. That can lead to
>> duplicated (or more) output if the libc buffers are not flushed before
>> forking.
>>
>> It's generally not seen when running programs directly, because stdout
>> will usually be line buffered when it's pointing to a terminal.
>>
>> This was noticed when running the seccomp_bpf test, eg:
>>
>>    $ ./seccomp_bpf | tee test.log
>>    $ grep -c "TAP version 13" test.log
>>    2
>>
>> But we only expect the TAP header to appear once.
>>
>> It can be exacerbated using stdbuf to increase the buffer size:
>>
>>    $ stdbuf -o 1MB ./seccomp_bpf > test.log
>>    $ grep -c "TAP version 13" test.log
>>    13
>>
>> The fix is simple, we just flush stdout & stderr before fork. Usually
>> stderr is unbuffered, but that can be changed, so flush it as well
>> just to be safe.
>>
>> Signed-off-by: Michael Ellerman <mpe@ellerman.id.au>
>> ---
>>   tools/testing/selftests/kselftest_harness.h | 5 +++++
>>   1 file changed, 5 insertions(+)
> 
> Tested-by: Max Filippov <jcmvbkbc@gmail.com>
> 

Thank you both. Applying to linux-kselftest fixes for 5.9-rc7

thanks,
-- Shuah
Shuah Khan Sept. 17, 2020, 4:51 p.m. UTC | #3
On 9/17/20 6:58 AM, Shuah Khan wrote:
> On 9/16/20 10:53 PM, Max Filippov wrote:
>> On Wed, Sep 16, 2020 at 9:16 PM Michael Ellerman <mpe@ellerman.id.au> 
>> wrote:
>>>
>>> The test harness forks() a child to run each test. Both the parent and
>>> the child print to stdout using libc functions. That can lead to
>>> duplicated (or more) output if the libc buffers are not flushed before
>>> forking.
>>>
>>> It's generally not seen when running programs directly, because stdout
>>> will usually be line buffered when it's pointing to a terminal.
>>>
>>> This was noticed when running the seccomp_bpf test, eg:
>>>
>>>    $ ./seccomp_bpf | tee test.log
>>>    $ grep -c "TAP version 13" test.log
>>>    2
>>>
>>> But we only expect the TAP header to appear once.
>>>
>>> It can be exacerbated using stdbuf to increase the buffer size:
>>>
>>>    $ stdbuf -o 1MB ./seccomp_bpf > test.log
>>>    $ grep -c "TAP version 13" test.log
>>>    13
>>>
>>> The fix is simple, we just flush stdout & stderr before fork. Usually
>>> stderr is unbuffered, but that can be changed, so flush it as well
>>> just to be safe.
>>>
>>> Signed-off-by: Michael Ellerman <mpe@ellerman.id.au>
>>> ---
>>>   tools/testing/selftests/kselftest_harness.h | 5 +++++
>>>   1 file changed, 5 insertions(+)
>>
>> Tested-by: Max Filippov <jcmvbkbc@gmail.com>
>>
> 
> Thank you both. Applying to linux-kselftest fixes for 5.9-rc7
> 

Kees,

I haven't pulled this in yet. If you want to take this through seccomp
tree for dependencies:

Acked-by: Shuah Khan <skhan@linuxfoundation.org>

thanks,
-- Shuah
Kees Cook Sept. 17, 2020, 10:06 p.m. UTC | #4
On Thu, Sep 17, 2020 at 10:51:32AM -0600, Shuah Khan wrote:
> On 9/17/20 6:58 AM, Shuah Khan wrote:
> > On 9/16/20 10:53 PM, Max Filippov wrote:
> > > On Wed, Sep 16, 2020 at 9:16 PM Michael Ellerman
> > > <mpe@ellerman.id.au> wrote:
> > > > 
> > > > The test harness forks() a child to run each test. Both the parent and
> > > > the child print to stdout using libc functions. That can lead to
> > > > duplicated (or more) output if the libc buffers are not flushed before
> > > > forking.
> > > > 
> > > > It's generally not seen when running programs directly, because stdout
> > > > will usually be line buffered when it's pointing to a terminal.
> > > > 
> > > > This was noticed when running the seccomp_bpf test, eg:
> > > > 
> > > >    $ ./seccomp_bpf | tee test.log
> > > >    $ grep -c "TAP version 13" test.log
> > > >    2
> > > > 
> > > > But we only expect the TAP header to appear once.
> > > > 
> > > > It can be exacerbated using stdbuf to increase the buffer size:
> > > > 
> > > >    $ stdbuf -o 1MB ./seccomp_bpf > test.log
> > > >    $ grep -c "TAP version 13" test.log
> > > >    13
> > > > 
> > > > The fix is simple, we just flush stdout & stderr before fork. Usually
> > > > stderr is unbuffered, but that can be changed, so flush it as well
> > > > just to be safe.
> > > > 
> > > > Signed-off-by: Michael Ellerman <mpe@ellerman.id.au>
> > > > ---
> > > >   tools/testing/selftests/kselftest_harness.h | 5 +++++
> > > >   1 file changed, 5 insertions(+)
> > > 
> > > Tested-by: Max Filippov <jcmvbkbc@gmail.com>
> > > 
> > 
> > Thank you both. Applying to linux-kselftest fixes for 5.9-rc7
> > 
> 
> Kees,
> 
> I haven't pulled this in yet. If you want to take this through seccomp
> tree for dependencies:
> 
> Acked-by: Shuah Khan <skhan@linuxfoundation.org>

You can have it -- it's a global fix and more than the seccomp selftest
is likely affected. :)
Kees Cook Sept. 17, 2020, 10:07 p.m. UTC | #5
On Thu, Sep 17, 2020 at 02:15:19PM +1000, Michael Ellerman wrote:
> The test harness forks() a child to run each test. Both the parent and
> the child print to stdout using libc functions. That can lead to
> duplicated (or more) output if the libc buffers are not flushed before
> forking.
> 
> It's generally not seen when running programs directly, because stdout
> will usually be line buffered when it's pointing to a terminal.
> 
> This was noticed when running the seccomp_bpf test, eg:
> 
>   $ ./seccomp_bpf | tee test.log
>   $ grep -c "TAP version 13" test.log
>   2

Oh thank you for tracking this down! I thought seccomp wasn't killing a
child or something, and hadn't found it yet. :)

Acked-by: Kees Cook <keescook@chromium.org>
Michael Ellerman Sept. 18, 2020, 3:37 a.m. UTC | #6
Shuah Khan <skhan@linuxfoundation.org> writes:
> On 9/16/20 10:53 PM, Max Filippov wrote:
>> On Wed, Sep 16, 2020 at 9:16 PM Michael Ellerman <mpe@ellerman.id.au> wrote:
>>>
>>> The test harness forks() a child to run each test. Both the parent and
>>> the child print to stdout using libc functions. That can lead to
>>> duplicated (or more) output if the libc buffers are not flushed before
>>> forking.
>>>
>>> It's generally not seen when running programs directly, because stdout
>>> will usually be line buffered when it's pointing to a terminal.
>>>
>>> This was noticed when running the seccomp_bpf test, eg:
>>>
>>>    $ ./seccomp_bpf | tee test.log
>>>    $ grep -c "TAP version 13" test.log
>>>    2
>>>
>>> But we only expect the TAP header to appear once.
>>>
>>> It can be exacerbated using stdbuf to increase the buffer size:
>>>
>>>    $ stdbuf -o 1MB ./seccomp_bpf > test.log
>>>    $ grep -c "TAP version 13" test.log
>>>    13
>>>
>>> The fix is simple, we just flush stdout & stderr before fork. Usually
>>> stderr is unbuffered, but that can be changed, so flush it as well
>>> just to be safe.
>>>
>>> Signed-off-by: Michael Ellerman <mpe@ellerman.id.au>
>>> ---
>>>   tools/testing/selftests/kselftest_harness.h | 5 +++++
>>>   1 file changed, 5 insertions(+)
>> 
>> Tested-by: Max Filippov <jcmvbkbc@gmail.com>
>
> Thank you both. Applying to linux-kselftest fixes for 5.9-rc7

It can wait for v5.10 IMHO, but up to you.

cheers
Shuah Khan Sept. 18, 2020, 2:32 p.m. UTC | #7
On 9/17/20 9:37 PM, Michael Ellerman wrote:
> Shuah Khan <skhan@linuxfoundation.org> writes:
>> On 9/16/20 10:53 PM, Max Filippov wrote:
>>> On Wed, Sep 16, 2020 at 9:16 PM Michael Ellerman <mpe@ellerman.id.au> wrote:
>>>>
>>>> The test harness forks() a child to run each test. Both the parent and
>>>> the child print to stdout using libc functions. That can lead to
>>>> duplicated (or more) output if the libc buffers are not flushed before
>>>> forking.
>>>>
>>>> It's generally not seen when running programs directly, because stdout
>>>> will usually be line buffered when it's pointing to a terminal.
>>>>
>>>> This was noticed when running the seccomp_bpf test, eg:
>>>>
>>>>     $ ./seccomp_bpf | tee test.log
>>>>     $ grep -c "TAP version 13" test.log
>>>>     2
>>>>
>>>> But we only expect the TAP header to appear once.
>>>>
>>>> It can be exacerbated using stdbuf to increase the buffer size:
>>>>
>>>>     $ stdbuf -o 1MB ./seccomp_bpf > test.log
>>>>     $ grep -c "TAP version 13" test.log
>>>>     13
>>>>
>>>> The fix is simple, we just flush stdout & stderr before fork. Usually
>>>> stderr is unbuffered, but that can be changed, so flush it as well
>>>> just to be safe.
>>>>
>>>> Signed-off-by: Michael Ellerman <mpe@ellerman.id.au>
>>>> ---
>>>>    tools/testing/selftests/kselftest_harness.h | 5 +++++
>>>>    1 file changed, 5 insertions(+)
>>>
>>> Tested-by: Max Filippov <jcmvbkbc@gmail.com>
>>
>> Thank you both. Applying to linux-kselftest fixes for 5.9-rc7
> 
> It can wait for v5.10 IMHO, but up to you.
> 

Good to know. I will send this for 5.10-rc1 then.

thanks,
-- Shuah
diff mbox series

Patch

diff --git a/tools/testing/selftests/kselftest_harness.h b/tools/testing/selftests/kselftest_harness.h
index 4f78e4805633..f19804df244c 100644
--- a/tools/testing/selftests/kselftest_harness.h
+++ b/tools/testing/selftests/kselftest_harness.h
@@ -971,6 +971,11 @@  void __run_test(struct __fixture_metadata *f,
 
 	ksft_print_msg(" RUN           %s%s%s.%s ...\n",
 	       f->name, variant->name[0] ? "." : "", variant->name, t->name);
+
+	/* Make sure output buffers are flushed before fork */
+	fflush(stdout);
+	fflush(stderr);
+
 	t->pid = fork();
 	if (t->pid < 0) {
 		ksft_print_msg("ERROR SPAWNING TEST CHILD\n");