ZTS: include microsecond timestamps on all output

When reviewing test output after a failure, it's often quite difficult
to work out the order and timing of events, and to correlate test suite
output with kernel logs.

This adds timestamps to ZTS output to help with this, in three places:

- all of the standard log_XXX functions ultimately end up in _printline,
  which now prefixes output with a timestamp. An escape hatch
  environment variable is provided for user_cmd, which often calls the
  logging functions while also depending on the captured output.

- the test runner logging function log() also now prefixes its output
  with a timestamp.

- on failure, when capturing the kernel log in zfs_dmesg.ksh, the "iso"
  time format is requested.

Sponsored-by: Klara, Inc.
Sponsored-by: Wasabi Technology, Inc.
Reviewed-by: Brian Behlendorf <[email protected]>
Reviewed-by: Tino Reichardt <[email protected]>
Signed-off-by: Rob Norris <[email protected]>
Closes #17045

Author: robn

tests/test-runner/bin/test-runner.py.in

@@ -15,6 +15,7 @@
 #
 # Copyright (c) 2012, 2018 by Delphix. All rights reserved.
 # Copyright (c) 2019 Datto Inc.
+# Copyright (c) 2025, Klara, Inc.
 #
 # This script must remain compatible with Python 3.6+.
 #
@@ -372,6 +373,8 @@ User: %s
         stdout/stderr/merged in its own file.
         """
 
+        timeprefix = datetime.now().strftime('[%FT%T.%f] ')
+
         logname = getpwuid(os.getuid()).pw_name
         rer = ''
         if self.reran is True:
@@ -383,7 +386,7 @@ User: %s
             msga = 'Test: %s%s ' % (self.pathname, user)
         msgb = '[%s] [%s]%s\n' % (self.result.runtime, self.result.result, rer)
         pad = ' ' * (80 - (len(msga) + len(msgb)))
-        result_line = msga + pad + msgb
+        result_line = timeprefix + msga + pad + msgb
 
         # The result line is always written to the log file. If -q was
         # specified only failures are written to the console, otherwise

tests/test-runner/bin/zts-report.py.in

@@ -15,6 +15,7 @@
 #
 # Copyright (c) 2017 by Delphix. All rights reserved.
 # Copyright (c) 2018 by Lawrence Livermore National Security, LLC.
+# Copyright (c) 2025, Klara, Inc.
 #
 # This script must remain compatible with Python 3.6+.
 #
@@ -381,7 +382,8 @@ def process_results(pathname):
 
     prefix = '/zfs-tests/tests/(?:functional|perf/regression)/'
     pattern = \
-        r'^Test(?:\s+\(\S+\))?:' + \
+        r'^(?:\[[0-9\-T:\.]+\]\s+)?' + \
+        r'Test(?:\s+\(\S+\))?:' + \
         rf'\s*\S*{prefix}(\S+)' + \
         r'\s*\(run as (\S+)\)\s*\[(\S+)\]\s*\[(\S+)\]'
     pattern_log = r'^\s*Log directory:\s*(\S*)'

tests/test-runner/include/logapi.shlib

@@ -25,6 +25,7 @@
 # Use is subject to license terms.
 #
 # Copyright (c) 2012, 2020 by Delphix. All rights reserved.
+# Copyright (c) 2025, Klara, Inc.
 #
 
 STF_PASS=0
@@ -465,7 +466,11 @@ function _endlog
 
 function _printline
 {
-	echo "$@"
+	if [[ -n "$ZTS_LOG_SUPPRESS_TIMESTAMP" ]] ; then
+		printf '[%(%FT%T.%6N)T] %s\n' now "$*"
+	else
+		echo "$@"
+	fi
 }
 
 # Output an error message

tests/zfs-tests/callbacks/zfs_dmesg.ksh

@@ -15,6 +15,7 @@
 #
 # Copyright (c) 2016 by Delphix. All rights reserved.
 # Copyright (c) 2017 Lawrence Livermore National Security, LLC.
+# Copyright (c) 2025, Klara, Inc.
 #
 
 # $1: number of lines to output (default: 200)
@@ -25,7 +26,11 @@ echo " Tailing last $lines lines of dmesg log"
 echo "================================================================="
 
 # report and reset afterwards
-sudo dmesg -c | tail -n $lines
+dmesg_args="-c"
+if [[ $(uname) = "Linux" ]] ; then
+	dmesg_args="$dmesg_args --time-format=iso"
+fi
+sudo dmesg $dmesg_args | tail -n $lines
 
 echo "================================================================="
 echo " End of dmesg log"

tests/zfs-tests/include/libtest.shlib

@@ -2884,7 +2884,9 @@ function user_run
 	typeset out=$TEST_BASE_DIR/out
 	typeset err=$TEST_BASE_DIR/err
 
-	sudo -Eu $user env PATH="$PATH" ksh <<<"$*" >$out 2>$err
+	sudo -Eu $user \
+	    env PATH="$PATH" ZTS_LOG_SUPPRESS_TIMESTAMP=1 \
+	    ksh <<<"$*" >$out 2>$err
 	typeset res=$?
 	log_note "out: $(<$out)"
 	log_note "err: $(<$err)"