Re: [PATCH] selftests: livepatch: filter kobject debug messages in check_result()

[Petr Mladek <pmladek@suse.com>]

On Thu 2026-08-20 11:34:22, Yafang Shao wrote:
> On Wed, Aug 19, 2026 at 9:28 PM Petr Mladek <pmladek@suse.com> wrote:
> >
> > On Tue 2026-08-18 13:46:29, Yafang Shao wrote:
> > > CONFIG_DEBUG_KOBJECT makes kobject_add_internal(), kobject_uevent_env(),
> > > fill_kobj_path() and friends emit pr_debug() messages, and
> > > CONFIG_DEBUG_KOBJECT_RELEASE makes kobject_release() emit a pr_info()
> > > for every delayed kobject free.  All of these carry the "kobject:"
> > > prefix via pr_fmt(), e.g.:
> > >
> > >   kobject: 'test_klp_livepatch' (ffff...): kobject_release, parent ... (delayed N)
> >
> > Yeah, this is pr_info() printed only when CONFIG_DEBUG_KOBJECT_RELEASE enabled.
> >
> > >   kobject: 'test_klp_livepatch' (ffff...): kobject_add_internal: parent: 'module', set: 'module'
> >
> > This one seems to be printed by pr_debug(). It is printed
> > with CONFIG_DEBUG_KOBJECT but only when CONFIG_DYNAMIC_DEBUG
> > is not enabled.
> >
> > > The livepatch test modules' kobjects are named "test_klp_*", so these
> > > lines match the check_result() grep for "test_klp" and leak into the
> > > result.  The extra lines no longer match the expected output, so the
> > > selftests fail when either debug config is enabled.
> > >
> > > Filter out the "kobject:" lines from the result and note in the README
> > > that both configs are safe to keep enabled.
> >
> > Honestly, I do not feel comfortable with this ignore-all-kobject-messages
> > approach. We might miss real problems reported by the kobject API.
> >
> > It seems acceptable to ignore the quite specific "kobject: .*parent.*
> > (delayed" pattern.
> 
> These messages are printed using pr_info:
> 
>   pr_info("'%s' (%p): %s, parent %p (delayed %ld)\n",
>       kobject_name(kobj), kobj, __func__, kobj->parent, delay);
> 
> In addition to the specific "kobject: .*parent.*(delayed" pattern,
> several other pr_debug messages are also produced.
> For example:
> 
> # --- expected
> # +++ result
> # @@ -1,7 +1,13 @@
> #  % insmod test_modules/test_klp_livepatch.ko
> # +kobject: 'test_klp_livepatch' (000000009dbf565e):
> kobject_add_internal: parent: 'module', set: 'module'
> # +kobject: 'holders' (00000000d9fe84ca): kobject_add_internal:
> parent: 'test_klp_livepatch', set: '<NULL>'
> # +kobject: 'test_klp_livepatch' (00000000dcae1113):
> kobject_add_internal: parent: 'livepatch', set: '<NULL>'
> # +kobject: 'vmlinux' (000000007b8837e6): kobject_add_internal:
> parent: 'test_klp_livepatch', set: '<NULL>'
> #  livepatch: enabling patch 'test_klp_livepatch'
> #  livepatch: 'test_klp_livepatch': initializing patching transition
> #  livepatch: 'test_klp_livepatch': starting patching transition
> # +kobject: 'test_klp_livepatch' (000000009dbf565e): kobject_uevent_env
> # +kobject: 'test_klp_livepatch' (000000009dbf565e): fill_kobj_path:
> path = '/module/test_klp_livepatch'
> #  livepatch: 'test_klp_livepatch': completing patching transition
> #  livepatch: 'test_klp_livepatch': patching complete
> #  % echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled
> # @@ -9,4 +15,15 @@ livepatch: 'test_klp_livepatch': initial
> #  livepatch: 'test_klp_livepatch': starting unpatching transition
> #  livepatch: 'test_klp_livepatch': completing unpatching transition
> #  livepatch: 'test_klp_livepatch': unpatching complete
> # +kobject: 'test_klp_livepatch' (00000000dcae1113): kobject_cleanup,
> parent 00000000f8785d63
> # +kobject: 'test_klp_livepatch' (00000000dcae1113): auto cleanup kobject_del
> # +kobject: 'test_klp_livepatch' (00000000dcae1113): calling ktype release
> # +kobject: 'test_klp_livepatch': free name
> #  % rmmod test_klp_livepatch
> # +kobject: 'test_klp_livepatch' (000000009dbf565e): kobject_cleanup,
> parent 0000000052e5c022
> # +kobject: 'test_klp_livepatch' (000000009dbf565e): auto cleanup kobject_del
> # +kobject: 'test_klp_livepatch' (000000009dbf565e): auto cleanup 'remove' event
> # +kobject: 'test_klp_livepatch' (000000009dbf565e): kobject_uevent_env
> # +kobject: 'test_klp_livepatch' (000000009dbf565e): fill_kobj_path:
> path = '/module/test_klp_livepatch'
> # +kobject: 'test_klp_livepatch' (000000009dbf565e): calling ktype release
> # +kobject: 'test_klp_livepatch': free name
> 
> >
> > But I would prefer to ignore the other debug messages by detecting
> > the KERN_DEBUG loglevel. It seems that dmesg even allows to filter
> > the output on its own. It is a bit ugly because we want all
> > other loglevels but:
> >
> >    dmesg --level=info,notice,warn,err,crit,alert,emerg
> >
> > might do the job.
> 
> The following issues will occur:
> 
> # --- expected
> # +++ result
> # @@ -1,12 +1,8 @@
> #  % 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
> 
> This is because these messages are emitted using pr_debug:
> 
>   pr_debug("'%s': initializing %s transition\n", patch->mod->name,
>       klp_target_state == KLP_TRANSITION_PATCHED ? "patching" : "unpatching");
> 
>    pr_debug("'%s': completing %s transition\n",
>        klp_transition_patch->mod->name,
>        klp_target_state == KLP_TRANSITION_PATCHED ? "patching" : "unpatching");

I see.

> In summary, we need to filter out the pr_info messages from kobject
> while retaining the pr_debug messages from livepatch.
> Therefore, the following change should address this:
> 
> diff --git a/tools/testing/selftests/livepatch/functions.sh
> b/tools/testing/selftests/livepatch/functions.sh
> index 46991a029f7c..54789fae8055 100644
> --- a/tools/testing/selftests/livepatch/functions.sh
> +++ b/tools/testing/selftests/livepatch/functions.sh
> @@ -300,9 +300,9 @@ function start_test {
>         # find new kernel messages since the test started.
>         local last_dmesg_msg="livepatch kselftest timestamp: $(date
> --rfc-3339=ns)"
>         log "$last_dmesg_msg"
> -       loop_until 'dmesg | grep -q "$last_dmesg_msg"' ||
> +       loop_until 'dmesg --raw | grep -q "$last_dmesg_msg"' ||
>                 die "buffer busy? can't find canary dmesg message:
> $last_dmesg_msg"
> -       LAST_DMESG=$(dmesg | grep "$last_dmesg_msg")
> +       LAST_DMESG=$(dmesg --raw | grep "$last_dmesg_msg")
> 
>         echo -n "TEST: $test ... "
>         log "===== TEST: $test ====="
> @@ -318,9 +318,12 @@ function check_result {

Also we should update the comment, something like:

+	# - exclude debug messages except with "livepatch:" prefix

>         # - include lines matching keywords
>         # - exclude lines matching keywords
>         # - filter out dmesg timestamp prefixes
> -       result=$(dmesg | awk -v last_dmesg="$LAST_DMESG" 'p; $0 ==
> last_dmesg { p=1 }' | \
> +       result=$(dmesg --raw | \
> +                awk -v last_dmesg="$LAST_DMESG" 'p { if ($0 !~ /^<7>/
> || $0 ~ /livepatch:/) print; next } $0 == last_dmesg { p = 1 }' | \
>                  grep -e 'livepatch:' -e 'test_klp' | \
>                  grep -v '\(tainting\|taints\) kernel' | \
> +                grep -v 'kobject: .*parent.*(delayed' | \
> +                sed 's/^<[0-9]*>//' | \
>                  sed 's/^\[[ 0-9.]*\] //' | \
>                  sed 's/^\[[ ]*[CT][0-9]*\] //')

It is more tricky that I have expected. But I think that
it is worth it because it covers many other debug messages.

Best Regards,
Petr