Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Kevin Wolf <kwolf@redhat.com>]

Am 03.05.2019 um 16:39 hat Alex Bennée geschrieben:
> This attempts to clean-up the output to better match the output of the
> rest of the QEMU check system. This includes:
> 
>   - formatting as "  TEST    iotest: nnn"
>   - calculating time diff at the end
>   - only dumping config on failure
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

Hm... I see that this makes the output more consistent with other tests,
which is nice when it's run in the context of make check. I also think
the more consistent new output is uglier than the old output format.

I wonder whether we should have two modes - one that blends in with make
check, and another one that is provides nice and possibly more complete
output when the script is run manually.

> @@ -709,19 +703,6 @@ trap "_wrapup; exit \$status" 0 1 2 3 15
>  FULL_IMGFMT_DETAILS=$(_full_imgfmt_details)
>  FULL_HOST_DETAILS=$(_full_platform_details)
>  
> -cat <<EOF
> -QEMU          -- "$QEMU_PROG" $QEMU_OPTIONS
> -QEMU_IMG      -- "$QEMU_IMG_PROG" $QEMU_IMG_OPTIONS
> -QEMU_IO       -- "$QEMU_IO_PROG" $QEMU_IO_OPTIONS
> -QEMU_NBD      -- "$QEMU_NBD_PROG" $QEMU_NBD_OPTIONS
> -IMGFMT        -- $FULL_IMGFMT_DETAILS
> -IMGPROTO      -- $IMGPROTO
> -PLATFORM      -- $FULL_HOST_DETAILS
> -TEST_DIR      -- $TEST_DIR
> -SOCKET_SCM_HELPER -- $SOCKET_SCM_HELPER
> -
> -EOF

At the first sight, I have two things that I like to see improved at
least in the manual mode:

* The output above is now produced for each failing case when multiple
  tests are failing. I don't usually want to have my scroll buffer
  filled with tons of these, but I just want to see as many diffs as
  possible with as little scrolling as possible.

  If we have two modes, we can unconditionally display it at the start
  (like before this patch) in manual mode and completely disable it in
  make check mode. (It's rare that I need this information, and if make
  check fails, I should be trivially able to re-run it manually.)

* I'd like to see the currently running test with its start time and
  expected duration before it has finished. When running tests in the
  background, I often look at this information to check whether what's
  running is just a long-running test case or whether it hangs.

> -
>  seq="check"
>  
>  [ -n "$TESTS_REMAINING_LOG" ] && echo $list > $TESTS_REMAINING_LOG
> @@ -729,7 +710,9 @@ seq="check"
>  for seq in $list
>  do
>      err=false
> -    printf %s "$seq"
> +    reason=""
> +    times=""
> +
>      if [ -n "$TESTS_REMAINING_LOG" ] ; then
>          sed -e "s/$seq//" -e 's/  / /' -e 's/^ *//' $TESTS_REMAINING_LOG > $TESTS_REMAINING_LOG.tmp
>          mv $TESTS_REMAINING_LOG.tmp $TESTS_REMAINING_LOG
> @@ -738,7 +721,7 @@ do
>  
>      if $showme
>      then
> -        echo
> +        echo "  TEST    iotest: $seq (not actually run)"
>          continue
>      elif [ -f expunged ] && $expunge && egrep "^$seq([         ]|\$)" expunged >/dev/null
>      then
> @@ -753,17 +736,11 @@ do
>          # really going to try and run this one
>          #
>          rm -f $seq.out.bad
> -        lasttime=$(sed -n -e "/^$seq /s/.* //p" <$TIMESTAMP_FILE)
> -        if [ "X$lasttime" != X ]; then
> -                printf %s " ${lasttime}s ..."
> -        else
> -                printf "        "        # prettier output with timestamps.
> -        fi
>          rm -f core $seq.notrun
>          rm -f $seq.casenotrun
>  
>          start=$(_wallclock)
> -        $timestamp && printf %s "        [$(date "+%T")]"
> +        $timestamp && times="[$(date "+%T")]"
>  
>          if [ "$(head -n 1 "$source_iotests/$seq")" == "#!/usr/bin/env python" ]; then
>              run_command="$PYTHON $seq"
> @@ -781,26 +758,26 @@ do
>                      $run_command >$tmp.out 2>&1)
>          fi
>          sts=$?
> -        $timestamp && _timestamp
> +        $timestamp && times="$times -> [$(date "+%T")]"
>          stop=$(_wallclock)
>  
>          if [ -f core ]
>          then
> -            printf " [dumped core]"
>              mv core $seq.core
> +            reason="dumped core $seq.core"
>              err=true
>          fi
>  
>          if [ -f $seq.notrun ]
>          then
> -            $timestamp || printf " [not run] "
> -            $timestamp && echo " [not run]" && printf %s "        $seq -- "
> +            $timestamp || reason="[not run]"
> +            $timestamp && reason="[not run] $seq -- "

I don't see this reason turn up in the output anywhere. It gets printed
only for failures, but "not run" is not a failure. So all I get is
something like this:

$ ./check -T -raw 001-010
006 - unknown test, ignored
  TEST    iotest: 001 [09:48:38] -> [09:48:39] 1s (last 1s)
  TEST    iotest: 002 [09:48:39] -> [09:48:40] 1s (last 1s)
  TEST    iotest: 003 [09:48:40] -> [09:48:40] 0s (last 1s)
  TEST    iotest: 004 [09:48:40] -> [09:48:41] 1s (last 0s)
  TEST    iotest: 005 [09:48:41] -> [09:48:41] 0s (last 0s)
not suitable for this image format: raw
  TEST    iotest: 007 [09:48:41] -> [09:48:41]
  TEST    iotest: 008 [09:48:41] -> [09:48:41] 0s (last 1s)
  TEST    iotest: 009 [09:48:41] -> [09:48:42] 1s (last 0s)
  TEST    iotest: 010 [09:48:42] -> [09:48:42] 0s (last 0s)
Not run: 007
Passed all 8 tests

Note that the "not suitable for this image format: raw" comes _before_
the test that it refers to, without including the test number. If I
didn't know that 007 was the skipped test, I would interpret it as
belonging to test 005.

The indentation for the message that we had previously felt nicer, too,
but maybe only for manual mode because none of make check is nice like
that? Actually, is there any reason for make check to even print that
message for skipped tests? It only tests a subset of tests anyway, and
we'll still get the "Not run" list at the end.

Kevin