| Message ID | 20231220151151.267985-1-joe.lawrence@redhat.com |
|---|---|
| State | Accepted |
| Commit | f1fea725cc93fcc3c5af9a2af63ffdc40dd2259e |
| Headers | show |
| Series | selftests/livepatch: fix and refactor new dmesg message code | expand |
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@linux.ibm.com> > Closes: > https://lore.kernel.org/live-patching/ZYAimyPYhxVA9wKg@li-008a6a4c-3549-11b2-a85c-c5cc2836eea2.ibm.com/ > Signed-off-by: Joe Lawrence <joe.lawrence@redhat.com> 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@suse.com> Reviewed-by: Marcos Paulo de Souza <mpdesouza@suse.com> > --- > .../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
On Wed, 20 Dec 2023, 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@linux.ibm.com> > Closes: https://lore.kernel.org/live-patching/ZYAimyPYhxVA9wKg@li-008a6a4c-3549-11b2-a85c-c5cc2836eea2.ibm.com/ > Signed-off-by: Joe Lawrence <joe.lawrence@redhat.com> Acked-by: Miroslav Benes <mbenes@suse.cz> M
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
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@linux.ibm.com> Closes: https://lore.kernel.org/live-patching/ZYAimyPYhxVA9wKg@li-008a6a4c-3549-11b2-a85c-c5cc2836eea2.ibm.com/ Signed-off-by: Joe Lawrence <joe.lawrence@redhat.com> --- .../testing/selftests/livepatch/functions.sh | 37 +++++++++---------- 1 file changed, 17 insertions(+), 20 deletions(-)