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