Some arch configs (like ppc64) enable CONFIG_PRINTK_CALLER, which adds the caller id as part of the dmesg. Due to this, even though the expected vs observed are same, end testcase results are failed.
-% insmod test_modules/test_klp_livepatch.ko -livepatch: enabling patch 'test_klp_livepatch' -livepatch: 'test_klp_livepatch': initializing patching transition -livepatch: 'test_klp_livepatch': starting patching transition -livepatch: 'test_klp_livepatch': completing patching transition -livepatch: 'test_klp_livepatch': patching complete -% 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 +[ T3659] % insmod test_modules/test_klp_livepatch.ko +[ T3682] livepatch: enabling patch 'test_klp_livepatch' +[ T3682] livepatch: 'test_klp_livepatch': initializing patching transition +[ T3682] livepatch: 'test_klp_livepatch': starting patching transition +[ T826] livepatch: 'test_klp_livepatch': completing patching transition +[ T826] livepatch: 'test_klp_livepatch': patching complete +[ T3659] % echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled +[ T3659] livepatch: 'test_klp_livepatch': initializing unpatching transition +[ T3659] livepatch: 'test_klp_livepatch': starting unpatching transition +[ T789] livepatch: 'test_klp_livepatch': completing unpatching transition +[ T789] livepatch: 'test_klp_livepatch': unpatching complete +[ T3659] % rmmod test_klp_livepatch
ERROR: livepatch kselftest(s) failed not ok 1 selftests: livepatch: test-livepatch.sh # exit=1
Currently the check_result() handles the "[time]" removal from the dmesg. Enhance the check to handle removal of "[Tid]" also.
Signed-off-by: Madhavan Srinivasan maddy@linux.ibm.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 e5d06fb40233..a1730c1864a4 100644 --- a/tools/testing/selftests/livepatch/functions.sh +++ b/tools/testing/selftests/livepatch/functions.sh @@ -306,7 +306,8 @@ function check_result { result=$(dmesg | awk -v last_dmesg="$LAST_DMESG" 'p; $0 == last_dmesg { p=1 }' | \ grep -e 'livepatch:' -e 'test_klp' | \ grep -v '(tainting|taints) kernel' | \ - sed 's/^[[ 0-9.]*] //') + sed 's/^[[ 0-9.]*] //' | \ + sed 's/^[[ ]*T[0-9]*] //')
if [[ "$expect" == "$result" ]] ; then echo "ok"
On Tue, Jan 14, 2025 at 08:01:44PM +0530, Madhavan Srinivasan wrote:
Some arch configs (like ppc64) enable CONFIG_PRINTK_CALLER, which adds the caller id as part of the dmesg. Due to this, even though the expected vs observed are same, end testcase results are failed.
-% insmod test_modules/test_klp_livepatch.ko -livepatch: enabling patch 'test_klp_livepatch' -livepatch: 'test_klp_livepatch': initializing patching transition -livepatch: 'test_klp_livepatch': starting patching transition -livepatch: 'test_klp_livepatch': completing patching transition -livepatch: 'test_klp_livepatch': patching complete -% 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 +[ T3659] % insmod test_modules/test_klp_livepatch.ko +[ T3682] livepatch: enabling patch 'test_klp_livepatch' +[ T3682] livepatch: 'test_klp_livepatch': initializing patching transition +[ T3682] livepatch: 'test_klp_livepatch': starting patching transition +[ T826] livepatch: 'test_klp_livepatch': completing patching transition +[ T826] livepatch: 'test_klp_livepatch': patching complete +[ T3659] % echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled +[ T3659] livepatch: 'test_klp_livepatch': initializing unpatching transition +[ T3659] livepatch: 'test_klp_livepatch': starting unpatching transition +[ T789] livepatch: 'test_klp_livepatch': completing unpatching transition +[ T789] livepatch: 'test_klp_livepatch': unpatching complete +[ T3659] % rmmod test_klp_livepatch
ERROR: livepatch kselftest(s) failed not ok 1 selftests: livepatch: test-livepatch.sh # exit=1
Currently the check_result() handles the "[time]" removal from the dmesg. Enhance the check to handle removal of "[Tid]" also.
Signed-off-by: Madhavan Srinivasan maddy@linux.ibm.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 e5d06fb40233..a1730c1864a4 100644 --- a/tools/testing/selftests/livepatch/functions.sh +++ b/tools/testing/selftests/livepatch/functions.sh @@ -306,7 +306,8 @@ function check_result { result=$(dmesg | awk -v last_dmesg="$LAST_DMESG" 'p; $0 == last_dmesg { p=1 }' | \ grep -e 'livepatch:' -e 'test_klp' | \ grep -v '(tainting|taints) kernel' | \
sed 's/^\[[ 0-9.]*\] //')
sed 's/^\[[ 0-9.]*\] //' | \sed 's/^\[[ ]*T[0-9]*\] //')
Thanks for adding this to the filter.
If I read the PRINTK_CALLER docs correctly, there is a potential CPU identifier as well. Are there any instances where the livepatching code will use the "[C$processor_id]" (out of task context) prefix? Or would it hurt to future proof with [CT][0-9]?
Acked-by: Joe Lawrence joe.lawrence@redhat.com
-- Joe
if [[ "$expect" == "$result" ]] ; then echo "ok" -- 2.47.0
On 1/15/25 11:40 PM, Joe Lawrence wrote:
On Tue, Jan 14, 2025 at 08:01:44PM +0530, Madhavan Srinivasan wrote:
Some arch configs (like ppc64) enable CONFIG_PRINTK_CALLER, which adds the caller id as part of the dmesg. Due to this, even though the expected vs observed are same, end testcase results are failed.
-% insmod test_modules/test_klp_livepatch.ko -livepatch: enabling patch 'test_klp_livepatch' -livepatch: 'test_klp_livepatch': initializing patching transition -livepatch: 'test_klp_livepatch': starting patching transition -livepatch: 'test_klp_livepatch': completing patching transition -livepatch: 'test_klp_livepatch': patching complete -% 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 +[ T3659] % insmod test_modules/test_klp_livepatch.ko +[ T3682] livepatch: enabling patch 'test_klp_livepatch' +[ T3682] livepatch: 'test_klp_livepatch': initializing patching transition +[ T3682] livepatch: 'test_klp_livepatch': starting patching transition +[ T826] livepatch: 'test_klp_livepatch': completing patching transition +[ T826] livepatch: 'test_klp_livepatch': patching complete +[ T3659] % echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled +[ T3659] livepatch: 'test_klp_livepatch': initializing unpatching transition +[ T3659] livepatch: 'test_klp_livepatch': starting unpatching transition +[ T789] livepatch: 'test_klp_livepatch': completing unpatching transition +[ T789] livepatch: 'test_klp_livepatch': unpatching complete +[ T3659] % rmmod test_klp_livepatch
ERROR: livepatch kselftest(s) failed not ok 1 selftests: livepatch: test-livepatch.sh # exit=1
Currently the check_result() handles the "[time]" removal from the dmesg. Enhance the check to handle removal of "[Tid]" also.
Signed-off-by: Madhavan Srinivasan maddy@linux.ibm.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 e5d06fb40233..a1730c1864a4 100644 --- a/tools/testing/selftests/livepatch/functions.sh +++ b/tools/testing/selftests/livepatch/functions.sh @@ -306,7 +306,8 @@ function check_result { result=$(dmesg | awk -v last_dmesg="$LAST_DMESG" 'p; $0 == last_dmesg { p=1 }' | \ grep -e 'livepatch:' -e 'test_klp' | \ grep -v '(tainting|taints) kernel' | \
sed 's/^\[[ 0-9.]*\] //')
sed 's/^\[[ 0-9.]*\] //' | \sed 's/^\[[ ]*T[0-9]*\] //')Thanks for adding this to the filter.
If I read the PRINTK_CALLER docs correctly, there is a potential CPU identifier as well. Are there any instances where the livepatching code will use the "[C$processor_id]" (out of task context) prefix? Or would it hurt to future proof with [CT][0-9]?
Thanks for the review.
yeah, saw that case, but in my current build and boot test, seen only the Thread-id added, so sent out to fix that. I did not get to add a test to create "processor id" scenario, so cant test it at this point.
Maddy
Acked-by: Joe Lawrence joe.lawrence@redhat.com
-- Joe
if [[ "$expect" == "$result" ]] ; then echo "ok" -- 2.47.0
On Tue 2025-01-14 20:01:44, Madhavan Srinivasan wrote:
Some arch configs (like ppc64) enable CONFIG_PRINTK_CALLER, which adds the caller id as part of the dmesg. Due to this, even though the expected vs observed are same, end testcase results are failed.
CONFIG_PRINTK_CALLER is not the only culprit. We (SUSE) have it enabled as well and the selftests pass without this patch.
The difference might be in dmesg. It shows the caller only when the messages are read via the syslog syscall (-S) option. It should not show the caller when the messages are read via /dev/kmsg which should be the default.
I wonder if you define an alias to dmesg which adds the "-S" option or if /dev/kmsg is not usable from some reason.
That said, I am fine with the patch. But I would like to better understand and document why you need it. Also it would be nice to update the filter format as suggested by Joe.
Best Regards, Petr
On 1/16/25 04:29, Petr Mladek wrote:
On Tue 2025-01-14 20:01:44, Madhavan Srinivasan wrote:
Some arch configs (like ppc64) enable CONFIG_PRINTK_CALLER, which adds the caller id as part of the dmesg. Due to this, even though the expected vs observed are same, end testcase results are failed.
CONFIG_PRINTK_CALLER is not the only culprit. We (SUSE) have it enabled as well and the selftests pass without this patch.
The difference might be in dmesg. It shows the caller only when the messages are read via the syslog syscall (-S) option. It should not show the caller when the messages are read via /dev/kmsg which should be the default.
I wonder if you define an alias to dmesg which adds the "-S" option or if /dev/kmsg is not usable from some reason.
Hi Petr,
To see the thread markers on a RHEL-9.6 machine, I built and installed the latest dmesg from:
https://github.com/util-linux/util-linux
and ran Madhavan's tests. I don't think there was any alias involved:
$ alias | grep dmesg (nothing)
$ ~/util-linux/dmesg | tail -n1 [ 4361.322790] [ T98877] % rmmod test_klp_livepatch
From util-linux's 467a5b3192f1 ("dmesg: add caller_id support"):
The dmesg -S using the old syslog interface supports printing the PRINTK_CALLER field but currently standard dmesg does not support printing the field if present. There are utilities that use dmesg and so it would be optimal if dmesg supported PRINTK_CALLER as well.
does that imply that printing the thread IDs is now a (util-linux's) dmesg default?
Regards,
On Thu 2025-01-16 08:10:44, Joe Lawrence wrote:
On 1/16/25 04:29, Petr Mladek wrote:
On Tue 2025-01-14 20:01:44, Madhavan Srinivasan wrote:
Some arch configs (like ppc64) enable CONFIG_PRINTK_CALLER, which adds the caller id as part of the dmesg. Due to this, even though the expected vs observed are same, end testcase results are failed.
CONFIG_PRINTK_CALLER is not the only culprit. We (SUSE) have it enabled as well and the selftests pass without this patch.
The difference might be in dmesg. It shows the caller only when the messages are read via the syslog syscall (-S) option. It should not show the caller when the messages are read via /dev/kmsg which should be the default.
I wonder if you define an alias to dmesg which adds the "-S" option or if /dev/kmsg is not usable from some reason.
Hi Petr,
To see the thread markers on a RHEL-9.6 machine, I built and installed the latest dmesg from:
https://github.com/util-linux/util-linux
and ran Madhavan's tests. I don't think there was any alias involved:
$ alias | grep dmesg (nothing)
$ ~/util-linux/dmesg | tail -n1 [ 4361.322790] [ T98877] % rmmod test_klp_livepatch
Good to know. I havn't seen this yet.
From util-linux's 467a5b3192f1 ("dmesg: add caller_id support"):
The dmesg -S using the old syslog interface supports printing the PRINTK_CALLER field but currently standard dmesg does not support printing the field if present. There are utilities that use dmesg and so it would be optimal if dmesg supported PRINTK_CALLER as well.
does that imply that printing the thread IDs is now a (util-linux's) dmesg default?
It looks like. The caller ID information is available also via /dev/kmsg but the older dmesg version did not show it. I guess that they just added support to parse and show it. It actually makes sense to show the same output independently on whether the messages are read via syslog or /dev/kmsg.
So, we need this patch, definitely ;-)
Best Regards, Petr
Hi,
On Thu, 16 Jan 2025, Petr Mladek wrote:
On Thu 2025-01-16 08:10:44, Joe Lawrence wrote:
On 1/16/25 04:29, Petr Mladek wrote:
On Tue 2025-01-14 20:01:44, Madhavan Srinivasan wrote:
Some arch configs (like ppc64) enable CONFIG_PRINTK_CALLER, which adds the caller id as part of the dmesg. Due to this, even though the expected vs observed are same, end testcase results are failed.
CONFIG_PRINTK_CALLER is not the only culprit. We (SUSE) have it enabled as well and the selftests pass without this patch.
The difference might be in dmesg. It shows the caller only when the messages are read via the syslog syscall (-S) option. It should not show the caller when the messages are read via /dev/kmsg which should be the default.
I wonder if you define an alias to dmesg which adds the "-S" option or if /dev/kmsg is not usable from some reason.
Hi Petr,
To see the thread markers on a RHEL-9.6 machine, I built and installed the latest dmesg from:
https://github.com/util-linux/util-linux
and ran Madhavan's tests. I don't think there was any alias involved:
$ alias | grep dmesg (nothing)
$ ~/util-linux/dmesg | tail -n1 [ 4361.322790] [ T98877] % rmmod test_klp_livepatch
Good to know. I havn't seen this yet.
From util-linux's 467a5b3192f1 ("dmesg: add caller_id support"):
The dmesg -S using the old syslog interface supports printing the PRINTK_CALLER field but currently standard dmesg does not support printing the field if present. There are utilities that use dmesg and so it would be optimal if dmesg supported PRINTK_CALLER as well.
does that imply that printing the thread IDs is now a (util-linux's) dmesg default?
It looks like. The caller ID information is available also via /dev/kmsg but the older dmesg version did not show it. I guess that they just added support to parse and show it. It actually makes sense to show the same output independently on whether the messages are read via syslog or /dev/kmsg.
So, we need this patch, definitely ;-)
Yes.
Madhavan, could you add the above findings to the commit log when you submit a new version, please?
Thank you, Miroslav
linux-kselftest-mirror@lists.linaro.org
-
Joe Lawrence -
Madhavan Srinivasan -
Miroslav Benes -
Petr Mladek