Re: selftests/livepatch fails on s390

[Joe Lawrence <joe.lawrence@redhat.com>]

On 12/18/23 05:44, Alexander Gordeev wrote:
> Hi all,
> 
> The livepatch selftest somehow fails in -next on s390 due to what
> appears to me as 'comm' usage issue. E.g the removal of timestamp-
> less line "with link type OSD_10GIG." in the below output forces 
> 'comm' to produce the correct result in check_result() function of
> tools/testing/selftests/livepatch/functions.sh script:
> 
> [   11.229256] qeth 0.0.bd02: qdio: OSA on SC 2624 using AI:1 QEBSM:0 PRI:1 TDD:1 SIGA: W 
> [   11.250189] systemd-journald[943]: Successfully sent stream file descriptor to service manager.
> [   11.258763] qeth 0.0.bd00: Device is a OSD Express card (level: 0165)
>                with link type OSD_10GIG.
> [   11.259261] qeth 0.0.bd00: The device represents a Bridge Capable Port
> [   11.262376] qeth 0.0.bd00: MAC address b2:96:9c:49:aa:e9 successfully registered
> [   11.269654] qeth 0.0.bd00: MAC address 06:c6:b5:7d:ee:63 successfully registered
> 
> By contrast, using the 'diff' instead works as a charm. But it was
> removed with commit 2f3f651f3756 ("selftests/livepatch: Use "comm"
> instead of "diff" for dmesg").
> 
> I am attaching the contents of "$expect" and "$result" script
> variables and the output of 'dmesg' before and after test run
> dmesg-saved.txt and dmesg.txt.
> 
> Another 'dmesg' output dmesg-saved1.txt and dmesg1.txt also
> shows the same problem, which seems like something to do with
> sorting.
> 
> The minimal reproducer attached is dmesg-saved1-rep.txt and
> dmesg1-rep.txt, that could be described as:
> 
> --- dmesg-saved1-rep.txt	2023-12-17 21:08:14.171014218 +0100
> +++ dmesg1-rep.txt	2023-12-17 21:06:52.221014218 +0100
> @@ -1,3 +1,3 @@
> -[   98.820331] livepatch: 'test_klp_state2': starting patching transition
>  [  100.031067] livepatch: 'test_klp_state2': completing patching transition
>  [  284.224335] livepatch: kernel.ftrace_enabled = 1
> +[  284.232921] ===== TEST: basic shadow variable API =====
> 
> The culprit is the extra space in [   98.820331] timestamp, that from
> the script point of view produces the output with two extra lines:
> 
> [  100.031067] livepatch: 'test_klp_state2': completing patching transition
> [  284.224335] livepatch: kernel.ftrace_enabled = 1
> [  284.232921] ===== TEST: basic shadow variable API =====
> 
> If the line with [   98.820331] timestamp removed or changed to e.g
> [  100.031066] (aka 1 us less), then the result output is as expected:
> 
> [  284.232921] ===== TEST: basic shadow variable API =====
> 
> Thanks!

Hi Alexander,

You're right about the timestamp formatting.  I can repro with a a
slight variant on your example:

Assume a pre-test dmesg log has three msgs (including one with timestamp
of fewer digits):

  $ head /tmp/{A,B}
  ==> /tmp/A <==
  [ 1] message one
  [10] message two
  [11] message three

during the rest, the first message rolls off the buffer post-test and a
new fourth message is added:

  ==> /tmp/B <==
  [10] message two
  [11] message three
  [12] message four

The test's comm invocation should be only printing "lines unique to
FILE2", ie, the latest fourth message, but...

  $ comm --nocheck-order -13 /tmp/A /tmp/B
  [10] message two
  [11] message three
  [12] message four

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.

-- 
Joe