On Wed, 2023-12-20 at 10:11 -0500, Joe Lawrence wrote: > The livepatching kselftests rely on comparing expected vs. observed > dmesg output. After each test, new dmesg entries are determined by > the > 'comm' utility comparing a saved, pre-test copy of dmesg to post-test > dmesg output. > > Alexander reports that the 'comm --nocheck-order -13' invocation used > by > the tests can be confused when dmesg entry timestamps vary in > magnitude > (ie, "[ 98.820331]" vs. "[ 100.031067]"), in which case, > additional > messages are reported as new. The unexpected entries then spoil the > test results. > > Instead of relying on 'comm' or 'diff' to determine new testing dmesg > entries, refactor the code: > > - pre-test : log a unique canary dmesg entry > - test : run tests, log messages > - post-test : filter dmesg starting from pre-test message > > Reported-by: Alexander Gordeev <agordeev@xxxxxxxxxxxxx> > Closes: > https://lore.kernel.org/live-patching/ZYAimyPYhxVA9wKg@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx/ > Signed-off-by: Joe Lawrence <joe.lawrence@xxxxxxxxxx> I liked the solution. As I don't speak awk I had to do some manual testing to understand that the syntax you used "prints everything after the $last_dmesg_msg message on dmesg". Either way, it's better then using 'comm' utility. I tested on my x86_64 VM, and the tests passed as expected. LGTM, so Tested-by: Marcos Paulo de Souza <mpdesouza@xxxxxxxx> Reviewed-by: Marcos Paulo de Souza <mpdesouza@xxxxxxxx> > --- > .../testing/selftests/livepatch/functions.sh | 37 +++++++++-------- > -- > 1 file changed, 17 insertions(+), 20 deletions(-) > > diff --git a/tools/testing/selftests/livepatch/functions.sh > b/tools/testing/selftests/livepatch/functions.sh > index c8416c54b463..b1fd7362c2fe 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,15 @@ 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 last_dmesg_msg="livepatch kselftest timestamp: $(date > --rfc-3339=ns)" > + log "$last_dmesg_msg" > + loop_until 'dmesg | grep -q "$last_dmesg_msg"' || > + die "buffer busy? can't find canary dmesg message: > $last_dmesg_msg" > + LAST_DMESG=$(dmesg | grep "$last_dmesg_msg") > + > echo -n "TEST: $test ... " > log "===== TEST: $test =====" > } > @@ -291,23 +287,24 @@ 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.]*\] //') > > if [[ "$expect" == "$result" ]] ; then > echo "ok" > + elif [[ "$result" == "" ]] ; then > + echo -e "not ok\n\nbuffer overrun? can't find canary > dmesg entry: $LAST_DMESG\n" > + die "livepatch kselftest(s) failed" > else > 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
