Re: selftests/livepatch fails on s390

From: Joe Lawrence <joe.lawrence@redhat.com>
To: Alexander Gordeev <agordeev@linux.ibm.com>,
	Josh Poimboeuf <jpoimboe@kernel.org>,
	Jiri Kosina <jikos@kernel.org>, Miroslav Benes <mbenes@suse.cz>,
	Petr Mladek <pmladek@suse.com>
Cc: linux-kselftest@vger.kernel.org, live-patching@vger.kernel.org,
	linux-s390@vger.kernel.org
Subject: Re: selftests/livepatch fails on s390
Date: Mon, 18 Dec 2023 17:44:54 -0500	[thread overview]
Message-ID: <ZYDLZkXdJ22AXtLW@redhat.com> (raw)
In-Reply-To: <cf087c7e-d24d-5cee-eadd-dd1fe26efe39@redhat.com>

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

