diff options
Diffstat (limited to 'sys/contrib/openzfs/tests/test-runner')
3 files changed, 94 insertions, 18 deletions
diff --git a/sys/contrib/openzfs/tests/test-runner/bin/test-runner.py.in b/sys/contrib/openzfs/tests/test-runner/bin/test-runner.py.in index 5bf13f5c08af..6688b6c4beb6 100755 --- a/sys/contrib/openzfs/tests/test-runner/bin/test-runner.py.in +++ b/sys/contrib/openzfs/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+. # @@ -24,6 +25,7 @@ import sys import ctypes import re import configparser +import traceback from datetime import datetime from optparse import OptionParser @@ -33,6 +35,7 @@ from select import select from subprocess import PIPE from subprocess import Popen from subprocess import check_output +from subprocess import run from threading import Timer from time import time, CLOCK_MONOTONIC from os.path import exists @@ -186,6 +189,63 @@ User: %s ''' % (self.pathname, self.identifier, self.outputdir, self.timeout, self.user) def kill_cmd(self, proc, options, kmemleak, keyboard_interrupt=False): + + """ + We're about to kill a command due to a timeout. + If we're running with the -O option, then dump debug info about the + process with the highest CPU usage to /dev/kmsg (Linux only). This can + help debug the timeout. + + Debug info includes: + - 30 lines from 'top' + - /proc/<PID>/stack output of process with highest CPU usage + - Last lines strace-ing process with highest CPU usage + """ + if exists("/dev/kmsg"): + c = """ +TOP_OUT="$(COLUMNS=160 top -b -n 1 | head -n 30)" +read -r PID CMD <<< $(echo "$TOP_OUT" | /usr/bin/awk \ +"/COMMAND/{ + print_next=1 + next +} +{ + if (print_next == 1) { + print \\$1\\" \\"\\$12 + exit + } +}") +echo "##### ZTS timeout debug #####" +echo "----- top -----" +echo "$TOP_OUT" +echo "----- /proc/$PID/stack ($CMD)) -----" +cat /proc/$PID/stack +echo "----- strace ($CMD) -----" +TMPFILE="$(mktemp --suffix=ZTS)" +/usr/bin/strace -k --stack-traces -p $PID &> "$TMPFILE" & +sleep 0.1 +killall strace +tail -n 30 $TMPFILE +rm "$TMPFILE" +echo "##### /proc/sysrq-trigger stack #####" +""" + c = "sudo bash -c '" + c + "'" + data = run(c, capture_output=True, shell=True, text=True) + out = data.stdout + try: + kp = Popen([SUDO, "sh", "-c", + "echo '" + out + "' > /dev/kmsg"]) + kp.wait() + + """ + Trigger kernel stack traces + """ + kp = Popen([SUDO, "sh", "-c", + "echo l > /proc/sysrq-trigger"]) + kp.wait() + except Exception: + pass + """ Kill a running command due to timeout, or ^C from the keyboard. If sudo is required, this user was verified previously. @@ -372,6 +432,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 +445,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 @@ -1077,7 +1139,7 @@ def filter_tests(testrun, options): testrun.filter(failed) -def fail(retstr, ret=1): +def fail(retstr, ret=255): print('%s: %s' % (sys.argv[0], retstr)) exit(ret) @@ -1126,6 +1188,9 @@ def parse_args(): parser.add_option('-o', action='callback', callback=options_cb, default=BASEDIR, dest='outputdir', type='string', metavar='outputdir', help='Specify an output directory.') + parser.add_option('-O', action='store_true', default=False, + dest='timeout_debug', + help='Dump debugging info to /dev/kmsg on test timeout') parser.add_option('-i', action='callback', callback=options_cb, default=TESTDIR, dest='testdir', type='string', metavar='testdir', help='Specify a test directory.') @@ -1183,23 +1248,27 @@ def parse_args(): def main(): options = parse_args() - testrun = TestRun(options) + try: + testrun = TestRun(options) - if options.runfiles: - testrun.read(options) - else: - find_tests(testrun, options) + if options.runfiles: + testrun.read(options) + else: + find_tests(testrun, options) + + if options.logfile: + filter_tests(testrun, options) - if options.logfile: - filter_tests(testrun, options) + if options.template: + testrun.write(options) + exit(0) - if options.template: - testrun.write(options) - exit(0) + testrun.complete_outputdirs() + testrun.run(options) + exit(testrun.summary()) - testrun.complete_outputdirs() - testrun.run(options) - exit(testrun.summary()) + except Exception: + fail("Uncaught exception in test runner:\n" + traceback.format_exc()) if __name__ == '__main__': diff --git a/sys/contrib/openzfs/tests/test-runner/bin/zts-report.py.in b/sys/contrib/openzfs/tests/test-runner/bin/zts-report.py.in index 40f5083d1294..5bc65f993734 100755 --- a/sys/contrib/openzfs/tests/test-runner/bin/zts-report.py.in +++ b/sys/contrib/openzfs/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+. # @@ -231,7 +232,7 @@ maybe = { 'cli_root/zpool_trim/zpool_trim_fault_export_import_online': ['FAIL', known_reason], 'cli_root/zpool_upgrade/zpool_upgrade_004_pos': ['FAIL', 6141], - 'cli_user/misc/arc_summary_001_pos': ['FAIL', known_reason], + 'cli_user/misc/zarcsummary_001_pos': ['FAIL', known_reason], 'delegate/setup': ['SKIP', exec_reason], 'events/zed_cksum_config': ['FAIL', known_reason], 'fault/auto_replace_002_pos': ['FAIL', known_reason], @@ -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/sys/contrib/openzfs/tests/test-runner/include/logapi.shlib b/sys/contrib/openzfs/tests/test-runner/include/logapi.shlib index 670ecfefb986..29e0c7f1c9ca 100644 --- a/sys/contrib/openzfs/tests/test-runner/include/logapi.shlib +++ b/sys/contrib/openzfs/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 |