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

[Kevin Wolf <kwolf@redhat.com>]

Am 10.05.2019 um 12:29 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 when called with -pretty. This includes:
> 
>   - formatting as "  TEST    iotest: nnn"
>   - calculating time diff at the end
>   - only dumping config on failure (when -pretty enabled)
> 
> The existing output is mostly preserved although the dumping of the
> old time at the start "Ns ..." was removed to keep the logic simple.
> The timestamp mode can still be used to see which tests are "hanging".
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> Message-Id: <20190503143904.31211-1-alex.bennee@linaro.org>

I played with it a bit more and ended up with the following patch to be
applied on top. Maybe you like some parts of it.

I'm now printing an \r at the end of the line that is printed at the
start of the test case. Normally that will be overwritten by the result
line which contains the same information again, but if you're running
multiple tests in parallel, it will be overwritten by something else -
which I think isn't a big problem because at the end, the result line
will still appear somewhere.

I fixed some bugs, too, like the "not run" list being broken.

Kevin


diff --git a/tests/qemu-iotests/check b/tests/qemu-iotests/check
index 4cfe2362f5..463ff82854 100755
--- a/tests/qemu-iotests/check
+++ b/tests/qemu-iotests/check
@@ -27,7 +27,7 @@ bad=""
 notrun=""
 casenotrun=""
 interrupt=true
-pretty=false
+make_check=false
 
 # by default don't output timestamps
 timestamp=${TIMESTAMP:=false}
@@ -274,7 +274,7 @@ other options
     -o options          -o options to pass to qemu-img create/convert
     -T                  output timestamps
     -c mode             cache mode
-    -pretty             pretty print output for make check
+    -make-check         print short output for make check
 
 testlist options
     -g group[,group...]        include tests from these groups
@@ -422,8 +422,8 @@ testlist options
                 command -v xxdiff >/dev/null 2>&1 && diff=xxdiff
             fi
             ;;
-        -pretty)   # pretty print output
-            pretty=true
+        -make-check)   # output for make check
+            make_check=true
             xpand=false
             ;;
         -n)        # show me, don't do it
@@ -643,12 +643,6 @@ _wallclock()
     date "+%H %M %S" | awk '{ print $1*3600 + $2*60 + $3 }'
 }
 
-_timestamp()
-{
-    now=$(date "+%T")
-    printf %s " [$now]"
-}
-
 _wrapup()
 {
     if $showme
@@ -671,11 +665,10 @@ END        { if (NR > 0) {
 
         if [ -f $tmp.expunged ]
         then
-            notrun=$(wc -l <$tmp.expunged | sed -e 's/  *//g')
-            try=$(expr $try - $notrun)
             list=$(echo "$list" | sed -f $tmp.expunged)
         fi
 
+        echo
         echo "" >>check.log
         date >>check.log
         echo $list | fmt | sed -e 's/^/    /' >>check.log
@@ -714,20 +707,48 @@ END        { if (NR > 0) {
 
 trap "_wrapup; exit \$status" 0 1 2 3 15
 
-# Report the test start and results, optionally pretty printing for make
-# args: $seq
+# Report the test start and results, optionally short format for make check
+# args: $seq, $starttime, $lasttime
 _report_test_start()
 {
-    if $pretty; then
-        printf "  TEST    iotest: %s" "$1"
-    else
-        printf "%s" "$1"
+    if $make_check; then
+        printf "  TEST    iotest: %s\r" "$1"
+        return
     fi
+
+    if [ -n "$3" ]; then
+        local lasttime=" (last: $3s)"
+    fi
+    printf "%-8s %-10s [%s]            %4s%-14s\r" "$1" "..." "$2" "..." "$lasttime"
 }
-# args: output
+
+# args: $seq, $starttime, $lasttime, $thistime, $status, details
 _report_test_result()
 {
-    printf "%s\n" "$1"
+    local status lasttime thistime
+
+    if $make_check; then
+        if [ -n "$5" ] && [ "$5" != "pass" ]; then
+            status=" [$5]"
+        fi
+        printf "  TEST    iotest: %s%s\n" "$1" "$status"
+        return
+    fi
+
+    if [ -n "$3" ]; then
+        lasttime=" (last: $3s)"
+    fi
+    if [ -n "$4" ]; then
+        thistime=" $4s"
+    fi
+    case "$5" in
+        "pass")     status=$(printf "\e[32m%-10s\e[0m" "$5") ;;
+        "fail")     status=$(printf "\e[1m\e[31m%-10s\e[0m" "$5") ;;
+        "not run")  status=$(printf "\e[33m%-10s\e[0m" "$5") ;;
+        *)          status=$(printf "%-10s" "$5") ;;
+    esac
+
+    printf "%-8s %s [%s] [%s] %4s%-14s %s\n" "$1" "$status" "$2" "$(date '+%T')" "$thistime" "$lasttime" "$6"
 }
 
 [ -f $TIMESTAMP_FILE ] || touch $TIMESTAMP_FILE
@@ -735,7 +756,7 @@ _report_test_result()
 FULL_IMGFMT_DETAILS=$(_full_imgfmt_details)
 FULL_HOST_DETAILS=$(_full_platform_details)
 
-if ! $pretty; then
+if ! $make_check; then
     _full_env_details
 fi
 
@@ -745,10 +766,10 @@ seq="check"
 
 for seq in $list
 do
-    _report_test_start $seq
-    err=false     # error flag
-    reason=""     # reason for error
-    results=""    # results for non-error/skip
+    err=false       # error flag
+    printdiff=false # show diff to reference output?
+    status=""       # test result summary
+    results=""      # test result details
 
     if [ -n "$TESTS_REMAINING_LOG" ] ; then
         sed -e "s/$seq//" -e 's/  / /' -e 's/^ *//' $TESTS_REMAINING_LOG > $TESTS_REMAINING_LOG.tmp
@@ -756,17 +777,23 @@ do
         sync
     fi
 
+    lasttime=$(sed -n -e "/^$seq /s/.* //p" <$TIMESTAMP_FILE)
+    starttime=$(date "+%T")
+    _report_test_start $seq $starttime $lasttime
+
     if $showme
     then
-        continue
+        status="not run"
     elif [ -f expunged ] && $expunge && egrep "^$seq([         ]|\$)" expunged >/dev/null
     then
-        echo " - expunged"
+        status="not run"
+        results="expunged"
         rm -f $seq.out.bad
         echo "/^$seq\$/d" >>$tmp.expunged
     elif [ ! -f "$source_iotests/$seq" ]
     then
-        echo " - no such test?"
+        status="not run"
+        results="no such test?"
         echo "/^$seq\$/d" >>$tmp.expunged
     else
         # really going to try and run this one
@@ -776,7 +803,6 @@ do
         rm -f $seq.casenotrun
 
         start=$(_wallclock)
-        $timestamp && _timestamp
 
         if [ "$(head -n 1 "$source_iotests/$seq")" == "#!/usr/bin/env python" ]; then
             run_command="$PYTHON $seq"
@@ -794,24 +820,26 @@ do
                     $run_command >$tmp.out 2>&1)
         fi
         sts=$?
-        $timestamp && _timestamp
         stop=$(_wallclock)
 
         if [ -f core ]
         then
             mv core $seq.core
-            reason="[dumped core] $seq.core"
+            status="fail"
+            results="[dumped core] $seq.core"
             err=true
         fi
 
         if [ -f $seq.notrun ]
         then
             # overwrites timestamp output
-            results="[not run] $(cat $seq.notrun)"
+            status="not run"
+            results="$(cat $seq.notrun)"
         else
             if [ $sts -ne 0 ]
             then
-                reason=$(printf %s "[failed, exit status $sts]")
+                status="fail"
+                results=$(printf %s "[failed, exit status $sts]")
                 err=true
             fi
 
@@ -830,31 +858,24 @@ do
                 [ -f "$source_iotests/$seq.out.nocache" ] && reference="$source_iotests/$seq.out.nocache"
             fi
 
+            thistime=$(expr $stop - $start)
             if [ ! -f "$reference" ]
             then
-                reason="- no qualified output"
+                status="fail"
+                results="no qualified output"
                 err=true
             else
                 if diff -w "$reference" $tmp.out >/dev/null 2>&1
                 then
-                    if $err
-                    then
-                        :
-                    else
-                        lasttime=$(sed -n -e "/^$seq /s/.* //p" <$TIMESTAMP_FILE)
-                        thistime=$(expr $stop - $start)
+                    if ! $err; then
+                        status="pass"
                         echo "$seq $thistime" >>$tmp.time
-
-                        if [ "X$lasttime" != X ]; then
-                            results="${results}${thistime}s (last ${lasttime}s)"
-                        else
-                            results="${results}${thistime}s"
-                        fi
                     fi
                 else
                     mv $tmp.out $seq.out.bad
-                    $diff -w "$reference" "$PWD"/$seq.out.bad
-                    reason="- output mismatch (see $seq.out.bad)"
+                    status="fail"
+                    results="output mismatch (see $seq.out.bad)"
+                    printdiff=true
                     err=true
                 fi
             fi
@@ -868,19 +889,28 @@ do
 
     # come here for each test, except when $showme is true
     #
-    if $err
-    then
-        _report_test_result " FAILED $reason"
-        if $pretty; then
-            _full_env_details
-        fi
-        bad="$bad $seq"
-        n_bad=$(expr $n_bad + 1)
-        quick=false
-    else
-        _report_test_result " $results"
-    fi
-    [ -f $seq.notrun ] || try=$(expr $try + 1)
+    _report_test_result $seq "$starttime" "$lasttime" "$thistime" "$status" "$results"
+
+    case "$status" in
+        "pass")
+            try=$(expr $try + 1)
+            ;;
+        "fail")
+            try=$(expr $try + 1)
+            if $make_check; then
+                _full_env_details
+            fi
+            if $printdiff; then
+                $diff -w "$reference" "$PWD"/$seq.out.bad
+            fi
+            bad="$bad $seq"
+            n_bad=$(expr $n_bad + 1)
+            quick=false
+            ;;
+        "not run")
+            notrun="$notrun $seq"
+            ;;
+    esac
 
     seq="after_$seq"
 done