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

Message ID 20200615172756.12912-3-joe.lawrence@redhat.com
State New
Headers show
Series
  • selftests/livepatch: small script cleanups
Related show

Commit Message

Joe Lawrence June 15, 2020, 5:27 p.m. UTC
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(-)

Comments

Petr Mladek June 17, 2020, 9:23 a.m. UTC | #1
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
Joe Lawrence June 17, 2020, 11:22 a.m. UTC | #2
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

Patch
diff mbox series

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"