From 245adb6a4f6c0ed32e78f1960ff7a446d74afff6 Mon Sep 17 00:00:00 2001
From: Rob Norris <rob.norris@klarasystems.com>
Date: Wed, 5 Feb 2025 00:47:50 +1100
Subject: [PATCH] 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 <behlendorf1@llnl.gov>
Reviewed-by: Tino Reichardt <milky-zfs@mcmilk.de>
Signed-off-by: Rob Norris <rob.norris@klarasystems.com>
Closes #17045
---
 tests/test-runner/bin/test-runner.py.in | 5 ++++-
 tests/test-runner/bin/zts-report.py.in  | 4 +++-
 tests/test-runner/include/logapi.shlib  | 7 ++++++-
 tests/zfs-tests/callbacks/zfs_dmesg.ksh | 7 ++++++-
 tests/zfs-tests/include/libtest.shlib   | 4 +++-
 5 files changed, 22 insertions(+), 5 deletions(-)

diff --git a/tests/test-runner/bin/test-runner.py.in b/tests/test-runner/bin/test-runner.py.in
index 5bf13f5c0..2158208be 100755
--- a/tests/test-runner/bin/test-runner.py.in
+++ b/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
diff --git a/tests/test-runner/bin/zts-report.py.in b/tests/test-runner/bin/zts-report.py.in
index 40f5083d1..001970120 100755
--- a/tests/test-runner/bin/zts-report.py.in
+++ b/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*)'
diff --git a/tests/test-runner/include/logapi.shlib b/tests/test-runner/include/logapi.shlib
index 670ecfefb..29e0c7f1c 100644
--- a/tests/test-runner/include/logapi.shlib
+++ b/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
diff --git a/tests/zfs-tests/callbacks/zfs_dmesg.ksh b/tests/zfs-tests/callbacks/zfs_dmesg.ksh
index 73c654125..de31765a5 100755
--- a/tests/zfs-tests/callbacks/zfs_dmesg.ksh
+++ b/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"
diff --git a/tests/zfs-tests/include/libtest.shlib b/tests/zfs-tests/include/libtest.shlib
index 8bffe9d82..d8e7bb73e 100644
--- a/tests/zfs-tests/include/libtest.shlib
+++ b/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)"