[PATCH v4 2/2] selftests/livepatch: filter debug messages in check_result()

[Yafang Shao <laoar.shao@gmail.com>]

CONFIG_DEBUG_KOBJECT makes kobject_add_internal(), kobject_uevent_env(),
fill_kobj_path() and friends emit pr_debug() messages, and
CONFIG_DEBUG_KOBJECT_RELEASE makes kobject_release() emit a pr_info()
for every delayed kobject free.  All of these carry the "kobject:" prefix
via pr_fmt(), e.g.:

 # --- expected
 # +++ result
 # @@ -1,7 +1,13 @@
 #  % insmod test_modules/test_klp_livepatch.ko
 # +kobject: 'test_klp_livepatch' (000000009dbf565e): kobject_add_internal: parent: 'module', set: 'module'
 # +kobject: 'holders' (000000002856f0ae): kobject_add_internal: parent: 'test_klp_livepatch', set: '<NULL>'
 # +kobject: 'test_klp_livepatch' (00000000dcae1113): kobject_add_internal: parent: 'livepatch', set: '<NULL>'
 # +kobject: 'vmlinux' (000000007b8837e6): kobject_add_internal: parent: 'test_klp_livepatch', set: '<NULL>'
 #  livepatch: enabling patch 'test_klp_livepatch'
 #  livepatch: 'test_klp_livepatch': initializing patching transition
 #  livepatch: 'test_klp_livepatch': starting patching transition
 # +kobject: 'test_klp_livepatch' (000000009dbf565e): kobject_uevent_env
 # +kobject: 'test_klp_livepatch' (000000009dbf565e): fill_kobj_path: path = '/module/test_klp_livepatch'
 #  livepatch: 'test_klp_livepatch': completing patching transition
 #  livepatch: 'test_klp_livepatch': patching complete
 #  % echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled
 # @@ -9,4 +15,17 @@ livepatch: 'test_klp_livepatch': initial
 #  livepatch: 'test_klp_livepatch': starting unpatching transition
 #  livepatch: 'test_klp_livepatch': completing unpatching transition
 #  livepatch: 'test_klp_livepatch': unpatching complete
 # +kobject: 'test_klp_livepatch' (00000000dcae1113): kobject_release, parent 00000000f8785d63 (delayed 2000)
 # +kobject: 'test_klp_livepatch' (00000000dcae1113): kobject_cleanup, parent 00000000f8785d63
 # +kobject: 'test_klp_livepatch' (00000000dcae1113): auto cleanup kobject_del
 # +kobject: 'test_klp_livepatch' (00000000dcae1113): calling ktype release
 # +kobject: 'test_klp_livepatch': free name
 #  % rmmod test_klp_livepatch
 # +kobject: 'test_klp_livepatch' (000000009dbf565e): kobject_release, parent 0000000052e5c022 (delayed 3000)
 # +kobject: 'test_klp_livepatch' (000000009dbf565e): kobject_cleanup, parent 0000000052e5c022
 # +kobject: 'test_klp_livepatch' (000000009dbf565e): auto cleanup kobject_del
 # +kobject: 'test_klp_livepatch' (000000009dbf565e): auto cleanup 'remove' event
 # +kobject: 'test_klp_livepatch' (000000009dbf565e): kobject_uevent_env
 # +kobject: 'test_klp_livepatch' (000000009dbf565e): fill_kobj_path: path = '/module/test_klp_livepatch'
 # +kobject: 'test_klp_livepatch' (000000009dbf565e): calling ktype release
 # +kobject: 'test_klp_livepatch': free name
 #
 # ERROR: livepatch kselftest(s) failed
 not ok 1 selftests: livepatch: test-livepatch.sh # exit=1

The livepatch test modules' kobjects are named "test_klp_*", so these
lines match the check_result() grep for "test_klp" and leak into the
result.  The extra lines no longer match the expected output, so the
selftests fail when either debug config is enabled.

Filtering out every "kobject:" line also hides real WARN()s, e.g. the
one kobject_get() emits for an object whose refcount was not
initialized.  Filtering with "dmesg --level=..." is not enough either,
since the tests enable livepatch pr_debug() through dynamic_debug/control
and expect its messages.  Read the log with "dmesg --raw" and drop only
the debug-level messages without the "livepatch:" prefix, plus the
specific delayed-release info message.

Suggested-by: Petr Mladek <pmladek@suse.com>
Signed-off-by: Yafang Shao <laoar.shao@gmail.com>
Acked-by: Song Liu <song@kernel.org>
Reviewed-by: Petr Mladek <pmladek@suse.com>
Tested-by: Petr Mladek <pmladek@suse.com>
---
 tools/testing/selftests/livepatch/functions.sh | 12 +++++++++---
 1 file changed, 9 insertions(+), 3 deletions(-)

diff --git a/tools/testing/selftests/livepatch/functions.sh b/tools/testing/selftests/livepatch/functions.sh
index 30dc677b2f45..8352c8d509a5 100644
--- a/tools/testing/selftests/livepatch/functions.sh
+++ b/tools/testing/selftests/livepatch/functions.sh
@@ -306,9 +306,9 @@ function start_test {
 	# 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"' ||
+	loop_until 'dmesg -r | grep -q "$last_dmesg_msg"' ||
 		die "buffer busy? can't find canary dmesg message: $last_dmesg_msg"
-	LAST_DMESG=$(dmesg | grep "$last_dmesg_msg")
+	LAST_DMESG=$(dmesg -r | grep "$last_dmesg_msg")
 
 	echo -n "TEST: $test ... "
 	log "===== TEST: $test ====="
@@ -321,12 +321,18 @@ function check_result {
 	local result
 
 	# Test results include any new dmesg entry since LAST_DMESG, then:
+	# - exclude debug messages except with "livepatch:" prefix
 	# - 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 }' | \
+	# - exclude the delayed kobject release messages when CONFIG_DEBUG_KOBJECT_RELEASE is on
+	result=$(dmesg -r | \
+		 awk -v last_dmesg="$LAST_DMESG" \
+		 'p { if ($0 !~ /^<7>/ || $0 ~ /livepatch:/) print; next } $0 == last_dmesg { p = 1 }' | \
 		 grep -e 'livepatch:' -e 'test_klp' | \
 		 grep -v '\(tainting\|taints\) kernel' | \
+		 grep -v 'kobject: .*parent.*(delayed' | \
+		 sed 's/^<[0-9]*>//' | \
 		 sed 's/^\[[ 0-9.]*\] //' | \
 		 sed 's/^\[[ ]*[CT][0-9]*\] //')
 
-- 
2.52.0