[PATCH] selftests: livepatch: handle PRINTK_CALLER in check_result()

[PATCH] selftests: livepatch: handle PRINTK_CALLER in check_result()

[Madhavan Srinivasan]

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"
-- 
2.47.0

Re: [PATCH] selftests: livepatch: handle PRINTK_CALLER in check_result()

[Joe Lawrence]

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
> 

Re: [PATCH] selftests: livepatch: handle PRINTK_CALLER in check_result()

[Madhavan Srinivasan]

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
>>
> 

Re: [PATCH] selftests: livepatch: handle PRINTK_CALLER in check_result()

[Petr Mladek]

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

Re: [PATCH] selftests: livepatch: handle PRINTK_CALLER in check_result()

[Joe Lawrence]

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,

-- 
Joe

Re: [PATCH] selftests: livepatch: handle PRINTK_CALLER in check_result()

[Petr Mladek]

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

Re: [PATCH] selftests: livepatch: handle PRINTK_CALLER in check_result()

[Miroslav Benes]

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