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
