On Mon, Dec 18, 2023 at 11:44:23AM -0500, Joe Lawrence wrote: > > [ ... snip ... ] > > If we pre-trim the timestamps, the output is what we expect: > > $ comm --nocheck-order -13 \ > <(sed 's/^\[[ 0-9.]*\] //' /tmp/A) \ > <(sed 's/^\[[ 0-9.]*\] //' /tmp/B) > message four > > however, I'm not sure if that fix would easily apply. It looks like I > provided a disclaimer notice in check_result(): > > # Note: when comparing dmesg output, the kernel log timestamps > # help differentiate repeated testing runs. Remove them with a > # post-comparison sed filter. > > so I wonder if comm will get confused with repeated selftest runs? > Using diff/comm was a trick that I surprised worked this long :) Maybe > it can still hold, but I'll have to run a few experiements.
Hi Alexander, I tested this idea and yeah, it breaks. Google brought me back to Petr's report from when way back when I tried to omit the timestamps: https://lore.kernel.org/all/20200617092352.GT31238@alley/ that was with diff and not comm, but I could trip up the latter command with ~22 iterations of the selftests. So I took a crack at refactoring: instead of saving intermediate dmesg.saved files, on starting a test, the script logs and remembers a LAST_DMESG entry. When it later checks the test result, it dumps dmesg starting from after LAST_DMESG entry. This is *very* lightly tested, but I thought maybe you could give it a spin. Hopefully it's less brittle than diff/comm strategy. -- Joe -->8-- -->8-- -->8-- -->8-- -->8-- -->8-- -->8-- -->8-- -->8-- -->8-- diff --git a/tools/testing/selftests/livepatch/functions.sh b/tools/testing/selftests/livepatch/functions.sh index c8416c54b463..b012723e631a 100644 --- a/tools/testing/selftests/livepatch/functions.sh +++ b/tools/testing/selftests/livepatch/functions.sh @@ -42,17 +42,6 @@ function die() { exit 1 } -# save existing dmesg so we can detect new content -function save_dmesg() { - SAVED_DMESG=$(mktemp --tmpdir -t klp-dmesg-XXXXXX) - dmesg > "$SAVED_DMESG" -} - -# cleanup temporary dmesg file from save_dmesg() -function cleanup_dmesg_file() { - rm -f "$SAVED_DMESG" -} - function push_config() { DYNAMIC_DEBUG=$(grep '^kernel/livepatch' /sys/kernel/debug/dynamic_debug/control | \ awk -F'[: ]' '{print "file " $1 " line " $2 " " $4}') @@ -99,7 +88,6 @@ function set_ftrace_enabled() { function cleanup() { pop_config - cleanup_dmesg_file } # setup_config - save the current config and set a script exit trap that @@ -280,7 +268,13 @@ function set_pre_patch_ret { function start_test { local test="$1" - save_dmesg + # Dump something unique into the dmesg log, then stash the entry + # in LAST_DMESG. The check_result() function will use it to + # find new kernel messages since the test started. + local timestamp="$(date --rfc-3339=ns)" + log "livepatch kselftest timestamp: $timestamp" + LAST_DMESG=$(dmesg | grep "livepatch kselftest timestamp: $timestamp") + echo -n "TEST: $test ... " log "===== TEST: $test =====" } @@ -291,11 +285,11 @@ function check_result { local expect="$*" local result - # Note: when comparing dmesg output, the kernel log timestamps - # help differentiate repeated testing runs. Remove them with a - # post-comparison sed filter. - - result=$(dmesg | comm --nocheck-order -13 "$SAVED_DMESG" - | \ + # Test results include any new dmesg entry since LAST_DMESG, then: + # - include lines matching keywords + # - exclude lines matching keywords + # - filter out dmesg timestamp prefixes + result=$(dmesg | awk -v last_dmesg="$LAST_DMESG" 'p; $0 == last_dmesg { p=1 }' | \ grep -e 'livepatch:' -e 'test_klp' | \ grep -v '\(tainting\|taints\) kernel' | \ sed 's/^\[[ 0-9.]*\] //') @@ -306,8 +300,6 @@ function check_result { echo -e "not ok\n\n$(diff -upr --label expected --label result <(echo "$expect") <(echo "$result"))\n" die "livepatch kselftest(s) failed" fi - - cleanup_dmesg_file } # check_sysfs_rights(modname, rel_path, expected_rights) - check sysfs
