CI: Add ZTS -O option, log Setup Testing Machines step

Add a -O option to zfs-test.sh to dump debug information on test
timeout.  The 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
- /proc/sysrq-trigger kernel stack traces

All debug information gets dumped to /dev/kmsg (Linux only).

In addition, print out the VM console lines from the "Setup Testing
Machines" step.  We have often see VMs timeout at this step and don't
know why.

Reviewed-by: Brian Behlendorf <[email protected]>
Signed-off-by: Tony Hutter <[email protected]>
Closes #17753

Author: tonyhutter

.github/workflows/scripts/qemu-3-deps-vm.sh

@@ -20,7 +20,7 @@ function archlinux() {
   sudo pacman -Sy --noconfirm base-devel bc cpio cryptsetup dhclient dkms \
     fakeroot fio gdb inetutils jq less linux linux-headers lsscsi nfs-utils \
     parted pax perf python-packaging python-setuptools qemu-guest-agent ksh \
-    samba sysstat rng-tools rsync wget xxhash
+    samba strace sysstat rng-tools rsync wget xxhash
   echo "##[endgroup]"
 }
 
@@ -43,7 +43,8 @@ function debian() {
     lsscsi nfs-kernel-server pamtester parted python3 python3-all-dev \
     python3-cffi python3-dev python3-distlib python3-packaging libtirpc-dev \
     python3-setuptools python3-sphinx qemu-guest-agent rng-tools rpm2cpio \
-    rsync samba sysstat uuid-dev watchdog wget xfslibs-dev  xxhash zlib1g-dev
+    rsync samba strace sysstat uuid-dev watchdog wget xfslibs-dev xxhash \
+    zlib1g-dev
   echo "##[endgroup]"
 }
 
@@ -87,8 +88,8 @@ function rhel() {
     libuuid-devel lsscsi mdadm nfs-utils openssl-devel pam-devel pamtester \
     parted perf python3 python3-cffi python3-devel python3-packaging \
     kernel-devel python3-setuptools qemu-guest-agent rng-tools rpcgen \
-    rpm-build rsync samba sysstat systemd watchdog wget xfsprogs-devel xxhash \
-    zlib-devel
+    rpm-build rsync samba strace sysstat systemd watchdog wget xfsprogs-devel \
+    xxhash zlib-devel
   echo "##[endgroup]"
 }
 

.github/workflows/scripts/qemu-5-setup.sh

@@ -108,19 +108,30 @@ echo '*/5 * * * *  /root/cronjob.sh' > crontab.txt
 sudo crontab crontab.txt
 rm crontab.txt
 
-# check if the machines are okay
-echo "Waiting for vm's to come up...  (${VMs}x CPU=$CPU RAM=$RAM)"
-for ((i=1; i<=VMs; i++)); do
-  .github/workflows/scripts/qemu-wait-for-vm.sh vm$i
-done
-echo "All $VMs VMs are up now."
-
 # Save the VM's serial output (ttyS0) to /var/tmp/console.txt
 # - ttyS0 on the VM corresponds to a local /dev/pty/N entry
 # - use 'virsh ttyconsole' to lookup the /dev/pty/N entry
 for ((i=1; i<=VMs; i++)); do
   mkdir -p $RESPATH/vm$i
   read "pty" <<< $(sudo virsh ttyconsole vm$i)
+
+  # Create the file so we can tail it, even if there's no output.
+  touch $RESPATH/vm$i/console.txt
+
   sudo nohup bash -c "cat $pty > $RESPATH/vm$i/console.txt" &
+
+  # Write all VM boot lines to the console to aid in debugging failed boots.
+  # The boot lines from all the VMs will be munged together, so prepend each
+  # line with the vm hostname (like 'vm1:').
+  (while IFS=$'\n' read -r line; do echo "vm$i: $line" ; done < <(sudo tail -f $RESPATH/vm$i/console.txt)) &
+
 done
 echo "Console logging for ${VMs}x $OS started."
+
+
+# check if the machines are okay
+echo "Waiting for vm's to come up...  (${VMs}x CPU=$CPU RAM=$RAM)"
+for ((i=1; i<=VMs; i++)); do
+  .github/workflows/scripts/qemu-wait-for-vm.sh vm$i
+done
+echo "All $VMs VMs are up now."

.github/workflows/scripts/qemu-6-tests.sh

@@ -111,7 +111,7 @@ fi
 sudo dmesg -c > dmesg-prerun.txt
 mount > mount.txt
 df -h > df-prerun.txt
-$TDIR/zfs-tests.sh -vK -s 3GB -T $TAGS
+$TDIR/zfs-tests.sh -vKO -s 3GB -T $TAGS
 RV=$?
 df -h > df-postrun.txt
 echo $RV > tests-exitcode.txt

scripts/zfs-tests.sh

@@ -38,6 +38,7 @@ DEBUG=""
 CLEANUP="yes"
 CLEANUPALL="no"
 KMSG=""
+TIMEOUT_DEBUG=""
 LOOPBACK="yes"
 STACK_TRACER="no"
 FILESIZE="4G"
@@ -364,6 +365,7 @@ OPTIONS:
 	-k          Disable cleanup after test failure
 	-K          Log test names to /dev/kmsg
 	-f          Use files only, disables block device tests
+	-O          Dump debugging info to /dev/kmsg on test timeout
 	-S          Enable stack tracer (negative performance impact)
 	-c          Only create and populate constrained path
 	-R          Automatically rerun failing tests
@@ -402,7 +404,7 @@ $0 -x
 EOF
 }
 
-while getopts 'hvqxkKfScRmn:d:Ds:r:?t:T:u:I:' OPTION; do
+while getopts 'hvqxkKfScRmOn:d:Ds:r:?t:T:u:I:' OPTION; do
 	case $OPTION in
 	h)
 		usage
@@ -445,6 +447,9 @@ while getopts 'hvqxkKfScRmn:d:Ds:r:?t:T:u:I:' OPTION; do
 		export NFS=1
 		. "$nfsfile"
 		;;
+	O)
+		TIMEOUT_DEBUG="yes"
+		;;
 	d)
 		FILEDIR="$OPTARG"
 		;;
@@ -773,6 +778,7 @@ msg "${TEST_RUNNER}" \
     "${DEBUG:+-D}" \
     "${KMEMLEAK:+-m}" \
     "${KMSG:+-K}" \
+    "${TIMEOUT_DEBUG:+-O}" \
     "-c \"${RUNFILES}\"" \
     "-T \"${TAGS}\"" \
     "-i \"${STF_SUITE}\"" \
@@ -783,6 +789,7 @@ msg "${TEST_RUNNER}" \
     ${DEBUG:+-D} \
     ${KMEMLEAK:+-m} \
     ${KMSG:+-K} \
+    ${TIMEOUT_DEBUG:+-O} \
     -c "${RUNFILES}" \
     -T "${TAGS}" \
     -i "${STF_SUITE}" \

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

@@ -34,6 +34,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
@@ -187,6 +188,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.
@@ -1129,6 +1187,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.')