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.