bin/48284: Misleading ATF output when command times out

[gson%gson.org@localhost (Andreas Gustafsson)]

>Number:         48284
>Category:       bin
>Synopsis:       Misleading ATF output when command times out
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    bin-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Mon Oct 07 09:30:00 +0000 2013
>Originator:     Andreas Gustafsson
>Release:        NetBSD 6.1.2
>Organization:
>Environment:
System: NetBSD
Architecture: x86_64
Machine: amd64
>Description:

When a test program written using the ATF shell API contains a
sequence of atf_check commands, as in

  atf_check true 
  atf_check sleep 1000

and one of the commands times out, the atf-run output contains no
mention of the command that actually timed out, thereby giving the
impression that the timeout happened in the command previous to the
one where it actually did:

  tc-start: 1381136245.785726, tc1
  tc-so:Executing command [ true ]
  tc-end: 1381136251.805048, tc1, failed, Test case timed out after 5 seconds

>How-To-Repeat:

cat <<'EOF' >Atffile
Content-Type: application/X-atf-atffile; version="1"

prop: test-suite = "Foo"

tp: t_foo
EOF

cat <<'EOF' >t_foo
#! /usr/bin/env atf-sh

atf_test_case tc1

tc1_head() {
        atf_set "descr" "Illustrate misleading atf-run output"
        atf_set "timeout" 5
}

tc1_body() {
        atf_check true 
        atf_check sleep 1000
}

atf_init_test_cases() {
        atf_add_test_case tc1
}
EOF

chmod 755 t_foo

atf-run t_foo

>Fix:

I'm guessing that flushing stdout in atf-check.cpp between printing
the "Executing command [ ... ]" message and executing the command will
fix this.