Re: selftests/livepatch fails on s390

Joe Lawrence
2023-12-18T22:45:01Z

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