run-vmtest: make kernel_splat detection optional

run-vmtest/README.md

@@ -47,24 +47,24 @@ hung tasks and lockups. A hit adds a `kernel_splats` row to `exitstatus`, which
 turns the run red like any other failing test group. Anything fatal panics the
 VM instead, and fails the job on its own.
 
-The check runs for the default suite or when the requested runners include
-`test_progs`. Veristat-only runs skip it.
+Leave both splat list files absent to disable detection.
 
 The action carries no patterns. What a splat is, and what is benign, is policy
 that changes per arch and per kernel, so it lives with the configs. Two files
 of extended regexes, one per line, `#` comments and blank lines ignored, named
 by `run-vmtest.env` next to the allow and denylists:
 
-* `SPLAT_DENYLIST_FILE` - a matching dmesg line is a splat. **Required.**
+* `SPLAT_DENYLIST_FILE` - a matching dmesg line is a splat.
 * `SPLAT_ALLOWLIST_FILE` - a matching splat line is ignored. Optional.
 
-The denylist is required on purpose: with no patterns there is no check, so a
-missing or empty file fails the run rather than reporting a clean log.
+If either file exists, the denylist must exist and contain at least one
+pattern.
 
 See `ci/vmtest/configs/SPLAT_DENYLIST` for the set BPF CI uses.
 
-`dmesg.txt` is written to the output dir and uploaded as the `kernel-log-*`
-artifact, so the full log is always one click away.
+On failure, matching kernel log context is printed in the job log. `dmesg.txt`
+is also written to the output dir and uploaded as the `kernel-log-*` artifact
+for the full log.
 
 ## run-vmtest.env
 

run-vmtest/check-kernel-splats.sh

@@ -7,15 +7,16 @@
 # config repo rather than here:
 #
 #   SPLAT_DENYLIST_FILE   extended regexes; a matching dmesg line is a splat.
-#                         Required: with no patterns there is no check, so a
-#                         missing file fails the run instead of passing it.
+#                         Required if either splat list file exists.
 #   SPLAT_ALLOWLIST_FILE  extended regexes; a matching splat line is ignored.
 #                         Optional: no file means no exceptions.
 #
 # `#` comments and blank lines are ignored in both. See run-vmtest.env in the
 # repo that owns $VMTEST_CONFIGS.
 #
-# The whole log is written to dmesg.txt, which the workflow uploads.
+# The whole log is written to dmesg.txt, which the workflow uploads. A short
+# excerpt around unallowlisted hits is written next to the status file so the
+# host can print it after closing the folded VM log.
 #
 # $1 - log file to scan instead of running dmesg (used by the unit tests)
 
@@ -27,11 +28,20 @@ STATUS_FILE=${STATUS_FILE:-/mnt/vmtest/exitstatus}
 OUTPUT_DIR=${OUTPUT_DIR:-/mnt/vmtest}
 SPLAT_DENYLIST_FILE=${SPLAT_DENYLIST_FILE:-}
 SPLAT_ALLOWLIST_FILE=${SPLAT_ALLOWLIST_FILE:-}
+SPLAT_LOG_FILE=${SPLAT_LOG_FILE:-"$(dirname "${STATUS_FILE}")/kernel_splats.log"}
+
+rm -f "${SPLAT_LOG_FILE}"
+
+if [ ! -e "${SPLAT_DENYLIST_FILE}" ] && [ ! -e "${SPLAT_ALLOWLIST_FILE}" ]; then
+    echo "Skipping kernel splat check: no allowlist or denylist files found"
+    exit 0
+fi
 
 # Fail the row and stop. Also used when the scan cannot run: a check that is
 # not working must not look like a clean log.
 fail_check() {
     echo "$1"
+    printf '%s\n' "$1" > "${SPLAT_LOG_FILE}"
     echo "kernel_splats:1" >> "${STATUS_FILE}"
     foldable end kernel_splats
     exit 0
@@ -78,5 +88,8 @@ if [ -z "${hits}" ]; then
 fi
 
 echo "kernel_splats:1" >> "${STATUS_FILE}"
-grep -nC 30 -E -f <(printf '%s\n' "${deny}") "${log}" || true
-echo "::error title=kernel_splats::kernel splat detected, see the dmesg.txt artifact"
+first_hit=${hits%%$'\n'*}
+{
+    printf 'kernel splat detected: %s\n' "${first_hit}"
+    grep -nC 30 -F -f <(printf '%s\n' "${hits}") "${log}" || true
+} > "${SPLAT_LOG_FILE}"

run-vmtest/prepare-bpf-selftests.sh

@@ -1,6 +1,6 @@
 #!/bin/bash
 
-set -xeuo pipefail
+set -euo pipefail
 
 if [[ -z "${SELFTESTS_BPF_ALLOWLIST_FILES:-}" && -z "${SELFTESTS_BPF_DENYLIST_FILES:-}" ]]; then
    exit 0

run-vmtest/run-bpf-selftests.sh

@@ -12,7 +12,7 @@
 # Runners passed as arguments are executed. In case of no arguments,
 # all test runners are executed.
 
-set -xeuo pipefail
+set -euo pipefail
 
 SCRIPT_DIR="$(cd "$(dirname "$0")" && pwd)"
 source "${SCRIPT_DIR}/helpers.sh"
@@ -178,8 +178,4 @@ else
 	done
 fi
 
-if [ ${#TEST_NAMES[@]} -eq 0 ] || [[ "${TEST_NAMES[*]}" == *test_progs* ]]; then
-	"${SCRIPT_DIR}/check-kernel-splats.sh"
-else
-	echo "Skipping kernel splat check: test_progs not requested"
-fi
+"${SCRIPT_DIR}/check-kernel-splats.sh"

run-vmtest/run.sh

@@ -1,6 +1,6 @@
 #!/bin/bash
 
-set -xeuo pipefail
+set -euo pipefail
 trap 'exit 2' ERR
 
 source "${GITHUB_ACTION_PATH}/../helpers.sh"
@@ -117,6 +117,17 @@ rm -f $VMTEST_TOML
 
 foldable end vmtest
 
+if grep -q '^kernel_splats:1$' exitstatus; then
+  splat_error="kernel splat check failed"
+  if [[ -s kernel_splats.log ]]; then
+    cat kernel_splats.log
+    splat_error=$(head -n 1 kernel_splats.log)
+  fi
+  splat_error=${splat_error//'%'/'%25'}
+  splat_error=${splat_error//$'\r'/'%0D'}
+  printf '::error title=kernel_splats::%s\n' "${splat_error}"
+fi
+
 foldable start collect_status "Collecting exit status"
 
 exitfile="$(cat exitstatus 2>/dev/null)"

run-vmtest/tests/check_kernel_splats/cases/kasan/expected-output.txt

@@ -2,17 +2,3 @@
 Splat denylist: $VMTEST_CONFIGS/SPLAT_DENYLIST
 Splat allowlist: $VMTEST_CONFIGS/SPLAT_ALLOWLIST
 ::endgroup::
-1-[    0.000000] Linux version 6.5.0
-2-[   20.000000] ==================================================================
-3:[   20.000001] BUG: KASAN: slab-use-after-free in foo+0x42/0x100
-4-[   20.000002] Read of size 8 at addr ffff888100001234 by task test_progs/123
-5-[   20.000003]
-6-[   20.000004] CPU: 0 PID: 123 Comm: test_progs
-7-[   20.000005] Call Trace:
-8-[   20.000006]  <TASK>
-9-[   20.000007]  dump_stack_lvl+0x60/0x80
-10-[   20.000008]  print_report+0xc4/0x630
-11-[   20.000009]  kasan_report+0xb6/0xf0
-12-[   20.000010]  </TASK>
-13-[   20.000011] ==================================================================
-::error title=kernel_splats::kernel splat detected, see the dmesg.txt artifact

run-vmtest/tests/check_kernel_splats/cases/kasan/expected-splat-log.txt

@@ -0,0 +1,14 @@
+kernel splat detected: [   20.000001] BUG: KASAN: slab-use-after-free in foo+0x42/0x100
+1-[    0.000000] Linux version 6.5.0
+2-[   20.000000] ==================================================================
+3:[   20.000001] BUG: KASAN: slab-use-after-free in foo+0x42/0x100
+4-[   20.000002] Read of size 8 at addr ffff888100001234 by task test_progs/123
+5-[   20.000003]
+6-[   20.000004] CPU: 0 PID: 123 Comm: test_progs
+7-[   20.000005] Call Trace:
+8-[   20.000006]  <TASK>
+9-[   20.000007]  dump_stack_lvl+0x60/0x80
+10-[   20.000008]  print_report+0xc4/0x630
+11-[   20.000009]  kasan_report+0xb6/0xf0
+12-[   20.000010]  </TASK>
+13-[   20.000011] ==================================================================

run-vmtest/tests/check_kernel_splats/cases/mixed_allowlist/allowlist.txt

@@ -0,0 +1 @@
+WARNING: CPU: 0 PID: 100 at kernel/sched/core\.c:1234

run-vmtest/tests/check_kernel_splats/cases/mixed_allowlist/dmesg.txt

@@ -0,0 +1,5 @@
+[    0.000000] Linux version 6.5.0
+[   10.000000] WARNING: CPU: 0 PID: 100 at kernel/sched/core.c:1234 allowed+0x1/0x2
+[   10.000001] Call Trace:
+[   11.000000] BUG: KASAN: slab-out-of-bounds in real_splat+0x3/0x4
+[   11.000001] Read of size 8 at addr ffff888000000000 by task test_progs/9

run-vmtest/tests/check_kernel_splats/cases/mixed_allowlist/env

@@ -0,0 +1 @@
+export SPLAT_ALLOWLIST_FILE="${CASE_DIR}/allowlist.txt"

run-vmtest/tests/check_kernel_splats/cases/mixed_allowlist/expected-output.txt

@@ -0,0 +1,4 @@
+::group::kernel_splats - Checking kernel log for splats
+Splat denylist: $VMTEST_CONFIGS/SPLAT_DENYLIST
+Splat allowlist: $CASE_DIR/allowlist.txt
+::endgroup::

run-vmtest/tests/check_kernel_splats/cases/mixed_allowlist/expected-splat-log.txt

@@ -0,0 +1,6 @@
+kernel splat detected: [   11.000000] BUG: KASAN: slab-out-of-bounds in real_splat+0x3/0x4
+1-[    0.000000] Linux version 6.5.0
+2-[   10.000000] WARNING: CPU: 0 PID: 100 at kernel/sched/core.c:1234 allowed+0x1/0x2
+3-[   10.000001] Call Trace:
+4:[   11.000000] BUG: KASAN: slab-out-of-bounds in real_splat+0x3/0x4
+5-[   11.000001] Read of size 8 at addr ffff888000000000 by task test_progs/9

run-vmtest/tests/check_kernel_splats/cases/mixed_allowlist/expected-status.txt

@@ -0,0 +1 @@
+kernel_splats:1

run-vmtest/tests/check_kernel_splats/cases/multi/expected-output.txt

@@ -2,18 +2,3 @@
 Splat denylist: $VMTEST_CONFIGS/SPLAT_DENYLIST
 Splat allowlist: $VMTEST_CONFIGS/SPLAT_ALLOWLIST
 ::endgroup::
-1-[    0.100000] Linux version 6.5.0
-2:[   10.000000] WARNING: CPU: 0 PID: 100 at kernel/sched/core.c:1 first+0x1/0x2
-3-[   10.000001] Call Trace:
-4-[   10.000002]  ? __warn+0x80/0xc0
-5-[   10.000003] ---[ end trace ]---
-6-[   10.500000] test_progs: PASS one
-7-[   11.000000] test_progs: running two
-8:[   11.000001] BUG: KASAN: slab-out-of-bounds in second+0x3/0x4
-9-[   11.000002] Read of size 8 at addr ffff888000000000 by task test_progs/9
-10-[   11.000003] ---[ end trace ]---
-11-[  199.000000] test_progs: running three
-12:[  200.000000] watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [test_progs:9]
-13:[  200.000001] watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [test_progs:9]
-14-[  201.000000] test_progs: PASS
-::error title=kernel_splats::kernel splat detected, see the dmesg.txt artifact

run-vmtest/tests/check_kernel_splats/cases/multi/expected-splat-log.txt

@@ -0,0 +1,15 @@
+kernel splat detected: [   10.000000] WARNING: CPU: 0 PID: 100 at kernel/sched/core.c:1 first+0x1/0x2
+1-[    0.100000] Linux version 6.5.0
+2:[   10.000000] WARNING: CPU: 0 PID: 100 at kernel/sched/core.c:1 first+0x1/0x2
+3-[   10.000001] Call Trace:
+4-[   10.000002]  ? __warn+0x80/0xc0
+5-[   10.000003] ---[ end trace ]---
+6-[   10.500000] test_progs: PASS one
+7-[   11.000000] test_progs: running two
+8:[   11.000001] BUG: KASAN: slab-out-of-bounds in second+0x3/0x4
+9-[   11.000002] Read of size 8 at addr ffff888000000000 by task test_progs/9
+10-[   11.000003] ---[ end trace ]---
+11-[  199.000000] test_progs: running three
+12:[  200.000000] watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [test_progs:9]
+13:[  200.000001] watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [test_progs:9]
+14-[  201.000000] test_progs: PASS

run-vmtest/tests/check_kernel_splats/cases/no_denylist/expected-splat-log.txt

@@ -0,0 +1 @@
+No splat denylist: SPLAT_DENYLIST_FILE=/nonexistent/SPLAT_DENYLIST

run-vmtest/tests/check_kernel_splats/cases/unconfigured/dmesg.txt

@@ -0,0 +1,2 @@
+[    0.000000] Linux version 6.5.0
+[   12.345679] WARNING: CPU: 0 PID: 100 at kernel/sched/core.c:1234 do_thing+0x10/0x20

run-vmtest/tests/check_kernel_splats/cases/unconfigured/env

@@ -0,0 +1,2 @@
+export SPLAT_DENYLIST_FILE="${CASE_DIR}/missing-denylist.txt"
+export SPLAT_ALLOWLIST_FILE="${CASE_DIR}/missing-allowlist.txt"

run-vmtest/tests/check_kernel_splats/cases/unconfigured/expected-output.txt

@@ -0,0 +1 @@
+Skipping kernel splat check: no allowlist or denylist files found

run-vmtest/tests/check_kernel_splats/cases/warn/expected-output.txt

@@ -2,18 +2,3 @@
 Splat denylist: $VMTEST_CONFIGS/SPLAT_DENYLIST
 Splat allowlist: $VMTEST_CONFIGS/SPLAT_ALLOWLIST
 ::endgroup::
-1-[    0.000000] Linux version 6.5.0
-2-[    0.001234] CPU: 0
-3-[   12.345678] ------------[ cut here ]------------
-4:[   12.345679] WARNING: CPU: 0 PID: 100 at kernel/sched/core.c:1234 do_thing+0x10/0x20
-5-[   12.345680] Modules linked in:
-6-[   12.345681] CPU: 0 PID: 100 Comm: test_progs
-7-[   12.345682] RIP: 0010:do_thing+0x10/0x20
-8-[   12.345683] Call Trace:
-9-[   12.345684]  <TASK>
-10-[   12.345685]  ? __warn+0x80/0xc0
-11-[   12.345686]  ? report_bug+0xa0/0xc0
-12-[   12.345687]  </TASK>
-13-[   12.345688] ---[ end trace ]---
-14-[   13.000000] test_progs: PASS
-::error title=kernel_splats::kernel splat detected, see the dmesg.txt artifact

run-vmtest/tests/check_kernel_splats/cases/warn/expected-splat-log.txt

@@ -0,0 +1,15 @@
+kernel splat detected: [   12.345679] WARNING: CPU: 0 PID: 100 at kernel/sched/core.c:1234 do_thing+0x10/0x20
+1-[    0.000000] Linux version 6.5.0
+2-[    0.001234] CPU: 0
+3-[   12.345678] ------------[ cut here ]------------
+4:[   12.345679] WARNING: CPU: 0 PID: 100 at kernel/sched/core.c:1234 do_thing+0x10/0x20
+5-[   12.345680] Modules linked in:
+6-[   12.345681] CPU: 0 PID: 100 Comm: test_progs
+7-[   12.345682] RIP: 0010:do_thing+0x10/0x20
+8-[   12.345683] Call Trace:
+9-[   12.345684]  <TASK>
+10-[   12.345685]  ? __warn+0x80/0xc0
+11-[   12.345686]  ? report_bug+0xa0/0xc0
+12-[   12.345687]  </TASK>
+13-[   12.345688] ---[ end trace ]---
+14-[   13.000000] test_progs: PASS

run-vmtest/tests/check_kernel_splats/run-test.sh

@@ -11,6 +11,7 @@ run_case() (
 
     CASE_DIR=$(realpath "${case_dir}")
     export CASE_DIR OUTPUT_DIR="$tmpdir" STATUS_FILE="$tmpdir/exitstatus"
+    : > "${STATUS_FILE}"
 
     # Default to the configs this repo carries, which is what a job gets from
     # $VMTEST_CONFIGS. A case overrides either one through its `env` file.
@@ -30,6 +31,13 @@ run_case() (
 
     diff -u "${case_dir}/expected-output.txt" "$tmpdir/output.txt"
     diff -u "${case_dir}/expected-status.txt" "$tmpdir/exitstatus"
+
+    if [ -f "${case_dir}/expected-splat-log.txt" ]; then
+        diff -u "${case_dir}/expected-splat-log.txt" "$tmpdir/kernel_splats.log"
+    elif [ -e "$tmpdir/kernel_splats.log" ]; then
+        echo "Unexpected kernel_splats.log for ${case_dir}"
+        return 1
+    fi
 )
 
 for case_dir in cases/*/; do