zts: add a debug option to get full test output

The test runner accumulates output from individual tests, then writes it
to the log at the end. If a test hangs or crashes the system half way
through, we get no insight into how it got to where it did.

This adds a -D option for "debug". When set, all test output is written
to stdout.

Sponsored-by: Klara, Inc.
Sponsored-by: Wasabi Technology, Inc.
Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Reviewed-by: Akash B <akash-b@hpe.com>
Signed-off-by: Rob Norris <rob.norris@klarasystems.com>
Closes #16096

diff --git a/scripts/zfs-tests.sh b/scripts/zfs-tests.sh
index b5b3e4ab351fb610a4360cff868a5b560a6f336e..c25903ea1bee640dc1f8f1c0877ae4c024cf2a48 100755 (executable)
--- a/scripts/zfs-tests.sh
+++ b/scripts/zfs-tests.sh
@@ -32,6 +32,7 @@ SCRIPT_COMMON=${SCRIPT_COMMON:-${0%/*}/common.sh}
 PROG=zfs-tests.sh
 VERBOSE="no"
 QUIET=""
+DEBUG=""
 CLEANUP="yes"
 CLEANUPALL="no"
 KMSG=""
@@ -313,6 +314,7 @@ OPTIONS:
        -h          Show this message
        -v          Verbose zfs-tests.sh output
        -q          Quiet test-runner output
+       -D          Debug; show all test output immediately (noisy)
        -x          Remove all testpools, dm, lo, and files (unsafe)
        -k          Disable cleanup after test failure
        -K          Log test names to /dev/kmsg
@@ -351,7 +353,7 @@ $0 -x
 EOF
 }
 
-while getopts 'hvqxkKfScRmn:d:s:r:?t:T:u:I:' OPTION; do
+while getopts 'hvqxkKfScRmn:d:Ds:r:?t:T:u:I:' OPTION; do
        case $OPTION in
        h)
                usage
@@ -397,6 +399,9 @@ while getopts 'hvqxkKfScRmn:d:s:r:?t:T:u:I:' OPTION; do
        d)
                FILEDIR="$OPTARG"
                ;;
+       D)
+               DEBUG="yes"
+               ;;
        I)
                ITERATIONS="$OPTARG"
                if [ "$ITERATIONS" -le 0 ]; then
@@ -691,6 +696,7 @@ REPORT_FILE=$(mktemp_file zts-report)
 #
 msg "${TEST_RUNNER}" \
     "${QUIET:+-q}" \
+    "${DEBUG:+-D}" \
     "${KMEMLEAK:+-m}" \
     "${KMSG:+-K}" \
     "-c \"${RUNFILES}\"" \
@@ -700,6 +706,7 @@ msg "${TEST_RUNNER}" \
 { PATH=$STF_PATH \
     ${TEST_RUNNER} \
     ${QUIET:+-q} \
+    ${DEBUG:+-D} \
     ${KMEMLEAK:+-m} \
     ${KMSG:+-K} \
     -c "${RUNFILES}" \
@@ -726,6 +733,7 @@ if [ "$RESULT" -eq "2" ] && [ -n "$RERUN" ]; then
        { PATH=$STF_PATH \
            ${TEST_RUNNER} \
                ${QUIET:+-q} \
+               ${DEBUG:+-D} \
                ${KMEMLEAK:+-m} \
            -c "${RUNFILES}" \
            -T "${TAGS}" \

diff --git a/tests/test-runner/bin/test-runner.py.in b/tests/test-runner/bin/test-runner.py.in
index 422ebd7bc8bfd604a76931dcef5a45c1811989ec..65247f4f06fc514536525f360302ad7764015271 100755 (executable)
--- a/tests/test-runner/bin/test-runner.py.in
+++ b/tests/test-runner/bin/test-runner.py.in
@@ -113,8 +113,9 @@ class Output(object):
     This class is a slightly modified version of the 'Stream' class found
     here: http://goo.gl/aSGfv
     """
-    def __init__(self, stream):
+    def __init__(self, stream, debug=False):
         self.stream = stream
+        self.debug = debug
         self._buf = b''
         self.lines = []
 
@@ -140,6 +141,8 @@ class Output(object):
         buf = os.read(fd, 4096)
         if not buf:
             return None
+        if self.debug:
+            os.write(sys.stderr.fileno(), buf)
         if b'\n' not in buf:
             self._buf += buf
             return []
@@ -238,14 +241,14 @@ User: %s
         ret = '%s -E -u %s %s' % (SUDO, user, cmd)
         return ret.split(' ')
 
-    def collect_output(self, proc):
+    def collect_output(self, proc, debug=False):
         """
         Read from stdout/stderr as data becomes available, until the
         process is no longer running. Return the lines from the stdout and
         stderr Output objects.
         """
-        out = Output(proc.stdout)
-        err = Output(proc.stderr)
+        out = Output(proc.stdout, debug)
+        err = Output(proc.stderr, debug)
         res = []
         while proc.returncode is None:
             proc.poll()
@@ -308,7 +311,10 @@ User: %s
 
         try:
             t.start()
-            self.result.stdout, self.result.stderr = self.collect_output(proc)
+
+            out, err = self.collect_output(proc, options.debug)
+            self.result.stdout = out
+            self.result.stderr = err
 
             if kmemleak:
                 cmd = f'{SUDO} sh -c "echo scan > {KMEMLEAK_FILE}"'
@@ -624,7 +630,7 @@ Tags: %s
 
 
 class TestRun(object):
-    props = ['quiet', 'outputdir']
+    props = ['quiet', 'outputdir', 'debug']
 
     def __init__(self, options):
         self.tests = {}
@@ -644,7 +650,8 @@ class TestRun(object):
             ('post_user', ''),
             ('failsafe', ''),
             ('failsafe_user', ''),
-            ('tags', [])
+            ('tags', []),
+            ('debug', False)
         ]
 
     def __str__(self):
@@ -1067,6 +1074,8 @@ def parse_args():
                       help='Specify tests to run via config files.')
     parser.add_option('-d', action='store_true', default=False, dest='dryrun',
                       help='Dry run. Print tests, but take no other action.')
+    parser.add_option('-D', action='store_true', default=False, dest='debug',
+                      help='Write all test output to stdout as it arrives.')
     parser.add_option('-l', action='callback', callback=options_cb,
                       default=None, dest='logfile', metavar='logfile',
                       type='string',