[PATCH v2 0/4] selftests/livepatch: small script cleanups

[PATCH v2 0/4] selftests/livepatch: small script cleanups

[Joe Lawrence]

This is a small collection of tweaks for the shellscript side of the
livepatch tests.  If anyone else has a small cleanup (or even just a
suggestion for a low-hanging change) and would like to tack it onto the
set, let me know.

based-on: livepatching.git, for-5.9/selftests-cleanup
merge-thru: livepatching.git

v2:
- use consistent start_test messages from the original echoes [mbenes]
- move start_test invocations to just after their descriptions [mbenes]
- clean up $SAVED_DMSG on trap EXIT [pmladek]
- grep longer kernel taint line, avoid word-matching [mbenes, pmladek]
- add "===== TEST: $test =====" delimiter patch [pmladek]

Joe Lawrence (4):
  selftests/livepatch: Don't clear dmesg when running tests
  selftests/livepatch: use $(dmesg --notime) instead of manually
    filtering
  selftests/livepatch: refine dmesg 'taints' in dmesg comparison
  selftests/livepatch: add test delimiter to dmesg

 tools/testing/selftests/livepatch/README      | 16 +++---
 .../testing/selftests/livepatch/functions.sh  | 32 ++++++++++-
 .../selftests/livepatch/test-callbacks.sh     | 55 ++++---------------
 .../selftests/livepatch/test-ftrace.sh        |  4 +-
 .../selftests/livepatch/test-livepatch.sh     | 12 +---
 .../selftests/livepatch/test-shadow-vars.sh   |  4 +-
 .../testing/selftests/livepatch/test-state.sh | 21 +++----
 7 files changed, 63 insertions(+), 81 deletions(-)

-- 
2.21.3

[PATCH v2 1/4] selftests/livepatch: Don't clear dmesg when running tests

[Joe Lawrence]

Inspired by commit f131d9edc29d ("selftests/lkdtm: Don't clear dmesg
when running tests"), keep a reference dmesg copy when beginning each
test.  This way check_result() can compare against the initial copy
rather than relying upon an empty log.

Signed-off-by: Joe Lawrence <joe.lawrence@redhat.com>
---
 tools/testing/selftests/livepatch/README      | 16 +++---
 .../testing/selftests/livepatch/functions.sh  | 31 ++++++++++-
 .../selftests/livepatch/test-callbacks.sh     | 55 ++++---------------
 .../selftests/livepatch/test-ftrace.sh        |  4 +-
 .../selftests/livepatch/test-livepatch.sh     | 12 +---
 .../selftests/livepatch/test-shadow-vars.sh   |  4 +-
 .../testing/selftests/livepatch/test-state.sh | 21 +++----
 7 files changed, 62 insertions(+), 81 deletions(-)

diff --git a/tools/testing/selftests/livepatch/README b/tools/testing/selftests/livepatch/README
index 621d325425c2..0942dd5826f8 100644
--- a/tools/testing/selftests/livepatch/README
+++ b/tools/testing/selftests/livepatch/README
@@ -6,8 +6,8 @@ This is a small set of sanity tests for the kernel livepatching.
 
 The test suite loads and unloads several test kernel modules to verify
 livepatch behavior.  Debug information is logged to the kernel's message
-buffer and parsed for expected messages.  (Note: the tests will clear
-the message buffer between individual tests.)
+buffer and parsed for expected messages.  (Note: the tests will compare
+the message buffer for only the duration of each individual test.)
 
 
 Config
@@ -35,9 +35,9 @@ Adding tests
 ------------
 
 See the common functions.sh file for the existing collection of utility
-functions, most importantly setup_config() and check_result().  The
-latter function greps the kernel's ring buffer for "livepatch:" and
-"test_klp" strings, so tests be sure to include one of those strings for
-result comparison.  Other utility functions include general module
-loading and livepatch loading helpers (waiting for patch transitions,
-sysfs entries, etc.)
+functions, most importantly setup_config(), start_test() and
+check_result().  The latter function greps the kernel's ring buffer for
+"livepatch:" and "test_klp" strings, so tests be sure to include one of
+those strings for result comparison.  Other utility functions include
+general module loading and livepatch loading helpers (waiting for patch
+transitions, sysfs entries, etc.)
diff --git a/tools/testing/selftests/livepatch/functions.sh b/tools/testing/selftests/livepatch/functions.sh
index 2aab9791791d..7ac3aa20f403 100644
--- a/tools/testing/selftests/livepatch/functions.sh
+++ b/tools/testing/selftests/livepatch/functions.sh
@@ -41,6 +41,17 @@ 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}')
@@ -68,6 +79,11 @@ function set_ftrace_enabled() {
 	echo "livepatch: $result" > /dev/kmsg
 }
 
+function cleanup() {
+	pop_config
+	cleanup_dmesg_file
+}
+
 # setup_config - save the current config and set a script exit trap that
 #		 restores the original config.  Setup the dynamic debug
 #		 for verbose livepatching output and turn on
@@ -77,7 +93,7 @@ function setup_config() {
 	push_config
 	set_dynamic_debug
 	set_ftrace_enabled 1
-	trap pop_config EXIT INT TERM HUP
+	trap cleanup EXIT INT TERM HUP
 }
 
 # loop_until(cmd) - loop a command until it is successful or $MAX_RETRIES,
@@ -243,13 +259,22 @@ function set_pre_patch_ret {
 		die "failed to set pre_patch_ret parameter for $mod module"
 }
 
+function start_test {
+	local test="$1"
+
+	save_dmesg
+	echo -n "TEST: $test ... "
+}
+
 # check_result() - verify dmesg output
 #	TODO - better filter, out of order msgs, etc?
 function check_result {
 	local expect="$*"
 	local result
 
-	result=$(dmesg | grep -v 'tainting' | grep -e 'livepatch:' -e 'test_klp' | sed 's/^\[[ 0-9.]*\] //')
+	result=$(dmesg | diff --changed-group-format='%>' --unchanged-group-format='' "$SAVED_DMESG" - | \
+		 grep -v 'tainting' | grep -e 'livepatch:' -e 'test_klp' | \
+		 sed 's/^\[[ 0-9.]*\] //')
 
 	if [[ "$expect" == "$result" ]] ; then
 		echo "ok"
@@ -257,4 +282,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
 }
diff --git a/tools/testing/selftests/livepatch/test-callbacks.sh b/tools/testing/selftests/livepatch/test-callbacks.sh
index 32b57ba07f4f..90b26dbb2626 100755
--- a/tools/testing/selftests/livepatch/test-callbacks.sh
+++ b/tools/testing/selftests/livepatch/test-callbacks.sh
@@ -12,8 +12,6 @@ MOD_TARGET_BUSY=test_klp_callbacks_busy
 setup_config
 
 
-# TEST: target module before livepatch
-#
 # Test a combination of loading a kernel module and a livepatch that
 # patches a function in the first module.  Load the target module
 # before the livepatch module.  Unload them in the same order.
@@ -28,8 +26,7 @@ setup_config
 #   unpatching transition starts.  klp_objects are reverted, post-patch
 #   callbacks execute and the transition completes.
 
-echo -n "TEST: target module before livepatch ... "
-dmesg -C
+start_test "target module before livepatch"
 
 load_mod $MOD_TARGET
 load_lp $MOD_LIVEPATCH
@@ -63,8 +60,6 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 $MOD_TARGET: ${MOD_TARGET}_exit"
 
 
-# TEST: module_coming notifier
-#
 # This test is similar to the previous test, but (un)load the livepatch
 # module before the target kernel module.  This tests the livepatch
 # core's module_coming handler.
@@ -78,8 +73,7 @@ $MOD_TARGET: ${MOD_TARGET}_exit"
 # - On livepatch disable, all currently loaded klp_objects' (vmlinux and
 #   $MOD_TARGET) pre/post-unpatch callbacks are executed.
 
-echo -n "TEST: module_coming notifier ... "
-dmesg -C
+start_test "module_coming notifier"
 
 load_lp $MOD_LIVEPATCH
 load_mod $MOD_TARGET
@@ -114,8 +108,6 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 $MOD_TARGET: ${MOD_TARGET}_exit"
 
 
-# TEST: module_going notifier
-#
 # Test loading the livepatch after a targeted kernel module, then unload
 # the kernel module before disabling the livepatch.  This tests the
 # livepatch core's module_going handler.
@@ -129,8 +121,7 @@ $MOD_TARGET: ${MOD_TARGET}_exit"
 # - When the livepatch is disabled, pre and post-unpatch callbacks are
 #   run for the remaining klp_object, vmlinux.
 
-echo -n "TEST: module_going notifier ... "
-dmesg -C
+start_test "module_going notifier"
 
 load_mod $MOD_TARGET
 load_lp $MOD_LIVEPATCH
@@ -165,8 +156,6 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 % rmmod $MOD_LIVEPATCH"
 
 
-# TEST: module_coming and module_going notifiers
-#
 # This test is similar to the previous test, however the livepatch is
 # loaded first.  This tests the livepatch core's module_coming and
 # module_going handlers.
@@ -180,8 +169,7 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 #   from the $MOD_TARGET klp_object.  As such, only pre and
 #   post-unpatch callbacks are executed when this occurs.
 
-echo -n "TEST: module_coming and module_going notifiers ... "
-dmesg -C
+start_test "module_coming and module_going notifiers"
 
 load_lp $MOD_LIVEPATCH
 load_mod $MOD_TARGET
@@ -217,8 +205,6 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 % rmmod $MOD_LIVEPATCH"
 
 
-# TEST: target module not present
-#
 # A simple test of loading a livepatch without one of its patch target
 # klp_objects ever loaded ($MOD_TARGET).
 #
@@ -227,8 +213,7 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 # - As expected, only pre/post-(un)patch handlers are executed for
 #   vmlinux.
 
-echo -n "TEST: target module not present ... "
-dmesg -C
+start_test "target module not present"
 
 load_lp $MOD_LIVEPATCH
 disable_lp $MOD_LIVEPATCH
@@ -252,8 +237,6 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 % rmmod $MOD_LIVEPATCH"
 
 
-# TEST: pre-patch callback -ENODEV
-#
 # Test a scenario where a vmlinux pre-patch callback returns a non-zero
 # status (ie, failure).
 #
@@ -265,8 +248,7 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 #   The result is that the insmod command refuses to load the livepatch
 #   module.
 
-echo -n "TEST: pre-patch callback -ENODEV ... "
-dmesg -C
+start_test "pre-patch callback -ENODEV"
 
 load_mod $MOD_TARGET
 load_failing_mod $MOD_LIVEPATCH pre_patch_ret=-19
@@ -288,8 +270,6 @@ modprobe: ERROR: could not insert '$MOD_LIVEPATCH': No such device
 $MOD_TARGET: ${MOD_TARGET}_exit"
 
 
-# TEST: module_coming + pre-patch callback -ENODEV
-#
 # Similar to the previous test, setup a livepatch such that its vmlinux
 # pre-patch callback returns success.  However, when a targeted kernel
 # module is later loaded, have the livepatch return a failing status
@@ -307,8 +287,7 @@ $MOD_TARGET: ${MOD_TARGET}_exit"
 #
 # - Pre/post-unpatch callbacks are run for the vmlinux klp_object.
 
-echo -n "TEST: module_coming + pre-patch callback -ENODEV ... "
-dmesg -C
+start_test "module_coming + pre-patch callback -ENODEV"
 
 load_lp $MOD_LIVEPATCH
 set_pre_patch_ret $MOD_LIVEPATCH -19
@@ -341,8 +320,6 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 % rmmod $MOD_LIVEPATCH"
 
 
-# TEST: multiple target modules
-#
 # Test loading multiple targeted kernel modules.  This test-case is
 # mainly for comparing with the next test-case.
 #
@@ -353,8 +330,7 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 #   module.  Post-patch callbacks are executed and the transition
 #   completes quickly.
 
-echo -n "TEST: multiple target modules ... "
-dmesg -C
+start_test "multiple target modules"
 
 load_mod $MOD_TARGET_BUSY block_transition=N
 load_lp $MOD_LIVEPATCH
@@ -402,8 +378,6 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 $MOD_TARGET_BUSY: ${MOD_TARGET_BUSY}_exit"
 
 
-# TEST: busy target module
-#
 # A similar test as the previous one, but force the "busy" kernel module
 # to block the livepatch transition.
 #
@@ -431,8 +405,7 @@ $MOD_TARGET_BUSY: ${MOD_TARGET_BUSY}_exit"
 #   klp_object's post-patch callbacks executed, the remaining
 #   klp_object's pre-unpatch callbacks are skipped.
 
-echo -n "TEST: busy target module ... "
-dmesg -C
+start_test "busy target module"
 
 load_mod $MOD_TARGET_BUSY block_transition=Y
 load_lp_nowait $MOD_LIVEPATCH
@@ -478,8 +451,6 @@ $MOD_TARGET_BUSY: busymod_work_func exit
 $MOD_TARGET_BUSY: ${MOD_TARGET_BUSY}_exit"
 
 
-# TEST: multiple livepatches
-#
 # Test loading multiple livepatches.  This test-case is mainly for comparing
 # with the next test-case.
 #
@@ -487,8 +458,7 @@ $MOD_TARGET_BUSY: ${MOD_TARGET_BUSY}_exit"
 #   execute as each patch progresses through its (un)patching
 #   transition.
 
-echo -n "TEST: multiple livepatches ... "
-dmesg -C
+start_test "multiple livepatches"
 
 load_lp $MOD_LIVEPATCH
 load_lp $MOD_LIVEPATCH2
@@ -531,8 +501,6 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 % rmmod $MOD_LIVEPATCH"
 
 
-# TEST: atomic replace
-#
 # Load multiple livepatches, but the second as an 'atomic-replace'
 # patch.  When the latter loads, the original livepatch should be
 # disabled and *none* of its pre/post-unpatch callbacks executed.  On
@@ -547,8 +515,7 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 # - Once the atomic replace module is loaded, only its pre and post
 #   unpatch callbacks are executed.
 
-echo -n "TEST: atomic replace ... "
-dmesg -C
+start_test "atomic replace"
 
 load_lp $MOD_LIVEPATCH
 load_lp $MOD_LIVEPATCH2 replace=1
diff --git a/tools/testing/selftests/livepatch/test-ftrace.sh b/tools/testing/selftests/livepatch/test-ftrace.sh
index e2a76887f40a..9160c9ec3b6f 100755
--- a/tools/testing/selftests/livepatch/test-ftrace.sh
+++ b/tools/testing/selftests/livepatch/test-ftrace.sh
@@ -9,13 +9,11 @@ MOD_LIVEPATCH=test_klp_livepatch
 setup_config
 
 
-# TEST: livepatch interaction with ftrace_enabled sysctl
 # - turn ftrace_enabled OFF and verify livepatches can't load
 # - turn ftrace_enabled ON and verify livepatch can load
 # - verify that ftrace_enabled can't be turned OFF while a livepatch is loaded
 
-echo -n "TEST: livepatch interaction with ftrace_enabled sysctl ... "
-dmesg -C
+start_test "livepatch interaction with ftrace_enabled sysctl"
 
 set_ftrace_enabled 0
 load_failing_mod $MOD_LIVEPATCH
diff --git a/tools/testing/selftests/livepatch/test-livepatch.sh b/tools/testing/selftests/livepatch/test-livepatch.sh
index 493e3df415a1..5fe79ac34be1 100755
--- a/tools/testing/selftests/livepatch/test-livepatch.sh
+++ b/tools/testing/selftests/livepatch/test-livepatch.sh
@@ -10,13 +10,11 @@ MOD_REPLACE=test_klp_atomic_replace
 setup_config
 
 
-# TEST: basic function patching
 # - load a livepatch that modifies the output from /proc/cmdline and
 #   verify correct behavior
 # - unload the livepatch and make sure the patch was removed
 
-echo -n "TEST: basic function patching ... "
-dmesg -C
+start_test "basic function patching"
 
 load_lp $MOD_LIVEPATCH
 
@@ -47,15 +45,13 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 % rmmod $MOD_LIVEPATCH"
 
 
-# TEST: multiple livepatches
 # - load a livepatch that modifies the output from /proc/cmdline and
 #   verify correct behavior
 # - load another livepatch and verify that both livepatches are active
 # - unload the second livepatch and verify that the first is still active
 # - unload the first livepatch and verify none are active
 
-echo -n "TEST: multiple livepatches ... "
-dmesg -C
+start_test "multiple livepatches"
 
 load_lp $MOD_LIVEPATCH
 
@@ -109,7 +105,6 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 % rmmod $MOD_LIVEPATCH"
 
 
-# TEST: atomic replace livepatch
 # - load a livepatch that modifies the output from /proc/cmdline and
 #   verify correct behavior
 # - load an atomic replace livepatch and verify that only the second is active
@@ -117,8 +112,7 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 #   is still active
 # - remove the atomic replace livepatch and verify that none are active
 
-echo -n "TEST: atomic replace livepatch ... "
-dmesg -C
+start_test "atomic replace livepatch"
 
 load_lp $MOD_LIVEPATCH
 
diff --git a/tools/testing/selftests/livepatch/test-shadow-vars.sh b/tools/testing/selftests/livepatch/test-shadow-vars.sh
index 7c016548c2ea..e04cb354f56b 100755
--- a/tools/testing/selftests/livepatch/test-shadow-vars.sh
+++ b/tools/testing/selftests/livepatch/test-shadow-vars.sh
@@ -9,11 +9,9 @@ MOD_TEST=test_klp_shadow_vars
 setup_config
 
 
-# TEST: basic shadow variable API
 # - load a module that exercises the shadow variable API
 
-echo -n "TEST: basic shadow variable API ... "
-dmesg -C
+start_test "basic shadow variable API"
 
 load_mod $MOD_TEST
 unload_mod $MOD_TEST
diff --git a/tools/testing/selftests/livepatch/test-state.sh b/tools/testing/selftests/livepatch/test-state.sh
index a08212708115..38656721c958 100755
--- a/tools/testing/selftests/livepatch/test-state.sh
+++ b/tools/testing/selftests/livepatch/test-state.sh
@@ -10,10 +10,10 @@ MOD_LIVEPATCH3=test_klp_state3
 
 setup_config
 
-# TEST: Loading and removing a module that modifies the system state
 
-echo -n "TEST: system state modification ... "
-dmesg -C
+# Load and remove a module that modifies the system state
+
+start_test "system state modification"
 
 load_lp $MOD_LIVEPATCH
 disable_lp $MOD_LIVEPATCH
@@ -41,10 +41,9 @@ livepatch: '$MOD_LIVEPATCH': unpatching complete
 % rmmod $MOD_LIVEPATCH"
 
 
-# TEST: Take over system state change by a cumulative patch
+# Take over system state change by a cumulative patch
 
-echo -n "TEST: taking over system state modification ... "
-dmesg -C
+start_test "taking over system state modification"
 
 load_lp $MOD_LIVEPATCH
 load_lp $MOD_LIVEPATCH2
@@ -85,10 +84,9 @@ livepatch: '$MOD_LIVEPATCH2': unpatching complete
 % rmmod $MOD_LIVEPATCH2"
 
 
-# TEST: Take over system state change by a cumulative patch
+# Take over system state change by a cumulative patch
 
-echo -n "TEST: compatible cumulative livepatches ... "
-dmesg -C
+start_test "compatible cumulative livepatches"
 
 load_lp $MOD_LIVEPATCH2
 load_lp $MOD_LIVEPATCH3
@@ -142,10 +140,9 @@ livepatch: '$MOD_LIVEPATCH2': unpatching complete
 % rmmod $MOD_LIVEPATCH3"
 
 
-# TEST: Failure caused by incompatible cumulative livepatches
+# Failure caused by incompatible cumulative livepatches
 
-echo -n "TEST: incompatible cumulative livepatches ... "
-dmesg -C
+start_test "incompatible cumulative livepatches"
 
 load_lp $MOD_LIVEPATCH2
 load_failing_mod $MOD_LIVEPATCH
-- 
2.21.3

[PATCH v2 2/4] selftests/livepatch: use $(dmesg --notime) instead of manually filtering

[Joe Lawrence]

The dmesg utility already comes with a command line switch to omit
kernel timestamps, let's use it instead of applying an extra regex to
filter them out.

Now without the '[timestamp]: ' prefix at the beginning of the log
entry, revise the filtering regex to search for the 'livepatch:'
subsystem prefix at the beginning of the line.

Signed-off-by: Joe Lawrence <joe.lawrence@redhat.com>
Reviewed-by: Petr Mladek <pmladek@suse.com>
---
 tools/testing/selftests/livepatch/README       | 8 ++++----
 tools/testing/selftests/livepatch/functions.sh | 7 +++----
 2 files changed, 7 insertions(+), 8 deletions(-)

diff --git a/tools/testing/selftests/livepatch/README b/tools/testing/selftests/livepatch/README
index 0942dd5826f8..79dafab03017 100644
--- a/tools/testing/selftests/livepatch/README
+++ b/tools/testing/selftests/livepatch/README
@@ -37,7 +37,7 @@ Adding tests
 See the common functions.sh file for the existing collection of utility
 functions, most importantly setup_config(), start_test() and
 check_result().  The latter function greps the kernel's ring buffer for
-"livepatch:" and "test_klp" strings, so tests be sure to include one of
-those strings for result comparison.  Other utility functions include
-general module loading and livepatch loading helpers (waiting for patch
-transitions, sysfs entries, etc.)
+the "^livepatch:" subsystem prefix and also any "test_klp" strings.
+Test log entries need include one of those for result comparison.  Other
+utility functions include general module loading and livepatch loading
+helpers (waiting for patch transitions, sysfs entries, etc.)
diff --git a/tools/testing/selftests/livepatch/functions.sh b/tools/testing/selftests/livepatch/functions.sh
index 7ac3aa20f403..bbbb4041f533 100644
--- a/tools/testing/selftests/livepatch/functions.sh
+++ b/tools/testing/selftests/livepatch/functions.sh
@@ -44,7 +44,7 @@ function die() {
 # save existing dmesg so we can detect new content
 function save_dmesg() {
 	SAVED_DMESG=$(mktemp --tmpdir -t klp-dmesg-XXXXXX)
-	dmesg > "$SAVED_DMESG"
+	dmesg --notime > "$SAVED_DMESG"
 }
 
 # cleanup temporary dmesg file from save_dmesg()
@@ -272,9 +272,8 @@ function check_result {
 	local expect="$*"
 	local result
 
-	result=$(dmesg | diff --changed-group-format='%>' --unchanged-group-format='' "$SAVED_DMESG" - | \
-		 grep -v 'tainting' | grep -e 'livepatch:' -e 'test_klp' | \
-		 sed 's/^\[[ 0-9.]*\] //')
+	result=$(dmesg --notime | diff --changed-group-format='%>' --unchanged-group-format='' "$SAVED_DMESG" - | \
+		 grep -v 'tainting' | grep -e '^livepatch:' -e 'test_klp')
 
 	if [[ "$expect" == "$result" ]] ; then
 		echo "ok"
-- 
2.21.3

[PATCH v2 3/4] selftests/livepatch: refine dmesg 'taints' in dmesg comparison

[Joe Lawrence]

The livepatch selftests currently grep on "taints" to filter out
"tainting kernel with TAINT_LIVEPATCH" messages which may be logged when
loading livepatch modules.

Further filter the log to drop "loading out-of-tree module taints
kernel" in the rare case the klp_test modules have been built
out-of-tree.

Look for the longer "taints kernel" or "tainting kernel" strings to
avoid inadvertent partial matching.

Signed-off-by: Joe Lawrence <joe.lawrence@redhat.com>
---
 tools/testing/selftests/livepatch/functions.sh | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/tools/testing/selftests/livepatch/functions.sh b/tools/testing/selftests/livepatch/functions.sh
index bbbb4041f533..cb8a6df8c73a 100644
--- a/tools/testing/selftests/livepatch/functions.sh
+++ b/tools/testing/selftests/livepatch/functions.sh
@@ -273,7 +273,8 @@ function check_result {
 	local result
 
 	result=$(dmesg --notime | diff --changed-group-format='%>' --unchanged-group-format='' "$SAVED_DMESG" - | \
-		 grep -v 'tainting' | grep -e '^livepatch:' -e 'test_klp')
+		 grep -e '^livepatch:' -e 'test_klp' | \
+		 grep -v '\(tainting\|taints\) kernel')
 
 	if [[ "$expect" == "$result" ]] ; then
 		echo "ok"
-- 
2.21.3

[PATCH v2 4/4] selftests/livepatch: add test delimiter to dmesg

[Joe Lawrence]

Make it bit easier to parse the kernel logs during the selftests by
adding a "===== TEST: $test =====" delimiter when each individual test
begins.

Suggested-by: Petr Mladek <pmladek@suse.com>
Signed-off-by: Joe Lawrence <joe.lawrence@redhat.com>
---
 tools/testing/selftests/livepatch/functions.sh | 1 +
 1 file changed, 1 insertion(+)

diff --git a/tools/testing/selftests/livepatch/functions.sh b/tools/testing/selftests/livepatch/functions.sh
index cb8a6df8c73a..d2b831cc710e 100644
--- a/tools/testing/selftests/livepatch/functions.sh
+++ b/tools/testing/selftests/livepatch/functions.sh
@@ -264,6 +264,7 @@ function start_test {
 
 	save_dmesg
 	echo -n "TEST: $test ... "
+	log "===== TEST: $test ====="
 }
 
 # check_result() - verify dmesg output
-- 
2.21.3

Re: [PATCH v2 0/4] selftests/livepatch: small script cleanups

[Kamalesh Babulal]

On 6/15/20 10:57 PM, Joe Lawrence wrote:
> This is a small collection of tweaks for the shellscript side of the
> livepatch tests.  If anyone else has a small cleanup (or even just a
> suggestion for a low-hanging change) and would like to tack it onto the
> set, let me know.
> 
> based-on: livepatching.git, for-5.9/selftests-cleanup
> merge-thru: livepatching.git
> 
> v2:
> - use consistent start_test messages from the original echoes [mbenes]
> - move start_test invocations to just after their descriptions [mbenes]
> - clean up $SAVED_DMSG on trap EXIT [pmladek]
> - grep longer kernel taint line, avoid word-matching [mbenes, pmladek]
> - add "===== TEST: $test =====" delimiter patch [pmladek]
> 
> Joe Lawrence (4):
>   selftests/livepatch: Don't clear dmesg when running tests
>   selftests/livepatch: use $(dmesg --notime) instead of manually
>     filtering
>   selftests/livepatch: refine dmesg 'taints' in dmesg comparison
>   selftests/livepatch: add test delimiter to dmesg
> 
>  tools/testing/selftests/livepatch/README      | 16 +++---
>  .../testing/selftests/livepatch/functions.sh  | 32 ++++++++++-
>  .../selftests/livepatch/test-callbacks.sh     | 55 ++++---------------
>  .../selftests/livepatch/test-ftrace.sh        |  4 +-
>  .../selftests/livepatch/test-livepatch.sh     | 12 +---
>  .../selftests/livepatch/test-shadow-vars.sh   |  4 +-
>  .../testing/selftests/livepatch/test-state.sh | 21 +++----
>  7 files changed, 63 insertions(+), 81 deletions(-)
> 

For the series:

Reviewed-by: Kamalesh Babulal <kamalesh@linux.vnet.ibm.com>

-- 
Kamalesh

Re: [PATCH v2 0/4] selftests/livepatch: small script cleanups

[Miroslav Benes]

On Mon, 15 Jun 2020, Joe Lawrence wrote:

> This is a small collection of tweaks for the shellscript side of the
> livepatch tests.  If anyone else has a small cleanup (or even just a
> suggestion for a low-hanging change) and would like to tack it onto the
> set, let me know.
> 
> based-on: livepatching.git, for-5.9/selftests-cleanup
> merge-thru: livepatching.git
> 
> v2:
> - use consistent start_test messages from the original echoes [mbenes]
> - move start_test invocations to just after their descriptions [mbenes]
> - clean up $SAVED_DMSG on trap EXIT [pmladek]
> - grep longer kernel taint line, avoid word-matching [mbenes, pmladek]
> - add "===== TEST: $test =====" delimiter patch [pmladek]
> 
> Joe Lawrence (4):
>   selftests/livepatch: Don't clear dmesg when running tests
>   selftests/livepatch: use $(dmesg --notime) instead of manually
>     filtering
>   selftests/livepatch: refine dmesg 'taints' in dmesg comparison
>   selftests/livepatch: add test delimiter to dmesg
> 
>  tools/testing/selftests/livepatch/README      | 16 +++---
>  .../testing/selftests/livepatch/functions.sh  | 32 ++++++++++-
>  .../selftests/livepatch/test-callbacks.sh     | 55 ++++---------------
>  .../selftests/livepatch/test-ftrace.sh        |  4 +-
>  .../selftests/livepatch/test-livepatch.sh     | 12 +---
>  .../selftests/livepatch/test-shadow-vars.sh   |  4 +-
>  .../testing/selftests/livepatch/test-state.sh | 21 +++----
>  7 files changed, 63 insertions(+), 81 deletions(-)

Acked-by: Miroslav Benes <mbenes@suse.cz>

M

Re: [PATCH v2 0/4] selftests/livepatch: small script cleanups

[Petr Mladek]

On Mon 2020-06-15 13:27:52, Joe Lawrence wrote:
> This is a small collection of tweaks for the shellscript side of the
> livepatch tests.  If anyone else has a small cleanup (or even just a
> suggestion for a low-hanging change) and would like to tack it onto the
> set, let me know.
> 
> based-on: livepatching.git, for-5.9/selftests-cleanup
> merge-thru: livepatching.git
> 
> Joe Lawrence (4):
>   selftests/livepatch: Don't clear dmesg when running tests
>   selftests/livepatch: use $(dmesg --notime) instead of manually
>     filtering
>   selftests/livepatch: refine dmesg 'taints' in dmesg comparison
>   selftests/livepatch: add test delimiter to dmesg

For the series:

Revieved-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

Re: [PATCH v2 0/4] selftests/livepatch: small script cleanups

[Yannick Cote]

For the series:

Reviewed-by: Yannick Cote <ycote@redhat.com>

On Mon, Jun 15, 2020 at 1:28 PM Joe Lawrence <joe.lawrence@redhat.com> wrote:
>
> This is a small collection of tweaks for the shellscript side of the
> livepatch tests.  If anyone else has a small cleanup (or even just a
> suggestion for a low-hanging change) and would like to tack it onto the
> set, let me know.
>
> based-on: livepatching.git, for-5.9/selftests-cleanup
> merge-thru: livepatching.git
>
> v2:
> - use consistent start_test messages from the original echoes [mbenes]
> - move start_test invocations to just after their descriptions [mbenes]
> - clean up $SAVED_DMSG on trap EXIT [pmladek]
> - grep longer kernel taint line, avoid word-matching [mbenes, pmladek]
> - add "===== TEST: $test =====" delimiter patch [pmladek]
>
> Joe Lawrence (4):
>   selftests/livepatch: Don't clear dmesg when running tests
>   selftests/livepatch: use $(dmesg --notime) instead of manually
>     filtering
>   selftests/livepatch: refine dmesg 'taints' in dmesg comparison
>   selftests/livepatch: add test delimiter to dmesg
>
>  tools/testing/selftests/livepatch/README      | 16 +++---
>  .../testing/selftests/livepatch/functions.sh  | 32 ++++++++++-
>  .../selftests/livepatch/test-callbacks.sh     | 55 ++++---------------
>  .../selftests/livepatch/test-ftrace.sh        |  4 +-
>  .../selftests/livepatch/test-livepatch.sh     | 12 +---
>  .../selftests/livepatch/test-shadow-vars.sh   |  4 +-
>  .../testing/selftests/livepatch/test-state.sh | 21 +++----
>  7 files changed, 63 insertions(+), 81 deletions(-)
>
> --
> 2.21.3
>

Re: [PATCH v2 2/4] selftests/livepatch: use $(dmesg --notime) instead of manually filtering

[Petr Mladek]

On Mon 2020-06-15 13:27:54, Joe Lawrence wrote:
> The dmesg utility already comes with a command line switch to omit
> kernel timestamps, let's use it instead of applying an extra regex to
> filter them out.
> 
> Now without the '[timestamp]: ' prefix at the beginning of the log
> entry, revise the filtering regex to search for the 'livepatch:'
> subsystem prefix at the beginning of the line.

I wanted to push this patchset and run full test after each patch.
Suddenly the tests started to fail, for example:

$/tools/testing/selftests/livepatch> ./test-livepatch.sh
TEST: basic function patching ... ok
TEST: multiple livepatches ... not ok

--- expected
+++ result
@@ -1,3 +1,9 @@
+% echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled
+livepatch: 'test_klp_livepatch': initializing unpatching transition
+livepatch: 'test_klp_livepatch': starting unpatching transition
+livepatch: 'test_klp_livepatch': completing unpatching transition
+livepatch: 'test_klp_livepatch': unpatching complete
+% rmmod test_klp_livepatch
 % modprobe test_klp_livepatch
 livepatch: enabling patch 'test_klp_livepatch'
 livepatch: 'test_klp_livepatch': initializing patching transition
@@ -20,9 +26,3 @@ livepatch: 'test_klp_atomic_replace': co
 livepatch: 'test_klp_atomic_replace': unpatching complete
 % rmmod test_klp_atomic_replace
 test_klp_livepatch: this has been live patched
-% echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled
-livepatch: 'test_klp_livepatch': initializing unpatching transition
-livepatch: 'test_klp_livepatch': starting unpatching transition
-livepatch: 'test_klp_livepatch': completing unpatching transition
-livepatch: 'test_klp_livepatch': unpatching complete
-% rmmod test_klp_livepatch

ERROR: livepatch kselftest(s) failed


The problem is a combination of:

  + 1st patch that causes that old kernel messages are not cleared
  + 2nd patch that removes time stamps from the diff
  + lost the oldest messages because internal kernel log buffer overflow
  + run the same tests more times

As a result, the diff might match with an incomplete log from
the previous run.

Everything works when this 2nd patch is not commited. The timestamp
helps to distinguish old and new messages. The lost messages
are ignored thanks to the diff parameters:

       --changed-group-format='%>' --unchanged-group-format=''

If you agree, I'll solve this problem by not committing this patch
into livepatch.git repo.

It would be great to add a comment that the timestamp is actually
important. But it might be done in a followup patch.

Best Regards,
Petr


> --- a/tools/testing/selftests/livepatch/functions.sh
> +++ b/tools/testing/selftests/livepatch/functions.sh
> @@ -272,9 +272,8 @@ function check_result {
>  	local expect="$*"
>  	local result
>  
> -	result=$(dmesg | diff --changed-group-format='%>' --unchanged-group-format='' "$SAVED_DMESG" - | \
> -		 grep -v 'tainting' | grep -e 'livepatch:' -e 'test_klp' | \
> -		 sed 's/^\[[ 0-9.]*\] //')
> +	result=$(dmesg --notime | diff --changed-group-format='%>' --unchanged-group-format='' "$SAVED_DMESG" - | \
> +		 grep -v 'tainting' | grep -e '^livepatch:' -e 'test_klp')
>  
>  	if [[ "$expect" == "$result" ]] ; then
>  		echo "ok"
> -- 
> 2.21.3

Re: [PATCH v2 2/4] selftests/livepatch: use $(dmesg --notime) instead of manually filtering

[Joe Lawrence]

On 6/17/20 5:23 AM, Petr Mladek wrote:
> On Mon 2020-06-15 13:27:54, Joe Lawrence wrote:
>> The dmesg utility already comes with a command line switch to omit
>> kernel timestamps, let's use it instead of applying an extra regex to
>> filter them out.
>>
>> Now without the '[timestamp]: ' prefix at the beginning of the log
>> entry, revise the filtering regex to search for the 'livepatch:'
>> subsystem prefix at the beginning of the line.
> 
> I wanted to push this patchset and run full test after each patch.
> Suddenly the tests started to fail, for example:
> 

Hi Petr,

Thank you for running additional tests on your end.  I ran this on 
x86_64, ppc64le and s390 across a bunch of hosts and VMs, but never 
repeatedly so I never saw this interesting combination of issues.

> $/tools/testing/selftests/livepatch> ./test-livepatch.sh
> TEST: basic function patching ... ok
> TEST: multiple livepatches ... not ok
> 
> --- expected
> +++ result
> @@ -1,3 +1,9 @@
> +% echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled
> +livepatch: 'test_klp_livepatch': initializing unpatching transition
> +livepatch: 'test_klp_livepatch': starting unpatching transition
> +livepatch: 'test_klp_livepatch': completing unpatching transition
> +livepatch: 'test_klp_livepatch': unpatching complete
> +% rmmod test_klp_livepatch
>   % modprobe test_klp_livepatch
>   livepatch: enabling patch 'test_klp_livepatch'
>   livepatch: 'test_klp_livepatch': initializing patching transition
> @@ -20,9 +26,3 @@ livepatch: 'test_klp_atomic_replace': co
>   livepatch: 'test_klp_atomic_replace': unpatching complete
>   % rmmod test_klp_atomic_replace
>   test_klp_livepatch: this has been live patched
> -% echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled
> -livepatch: 'test_klp_livepatch': initializing unpatching transition
> -livepatch: 'test_klp_livepatch': starting unpatching transition
> -livepatch: 'test_klp_livepatch': completing unpatching transition
> -livepatch: 'test_klp_livepatch': unpatching complete
> -% rmmod test_klp_livepatch
> 
> ERROR: livepatch kselftest(s) failed
> 
> 
> The problem is a combination of:
> 
>    + 1st patch that causes that old kernel messages are not cleared
>    + 2nd patch that removes time stamps from the diff
>    + lost the oldest messages because internal kernel log buffer overflow
>    + run the same tests more times
> 
> As a result, the diff might match with an incomplete log from
> the previous run.
D'oh.  The referenced commit f131d9edc29d uses dmesg without any 
options, so it didn't suffer this gotcha.

> Everything works when this 2nd patch is not commited. The timestamp
> helps to distinguish old and new messages. The lost messages
> are ignored thanks to the diff parameters:
> 
>         --changed-group-format='%>' --unchanged-group-format=''
> 
> If you agree, I'll solve this problem by not committing this patch
> into livepatch.git repo.
> 

Very good catch and explanation.  I'd be okay w/skipping the 2nd patch, 
hopefully the others don't conflict too much by removing it.

> It would be great to add a comment that the timestamp is actually
> important. But it might be done in a followup patch.
> 

Yeah, something that subtle should probably have a comment to that 
effect.  We all thought this was the "easy" change in the set, but never 
thought it through :)

-- Joe