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

On Wed, Aug 19, 2026 at 9:28 PM Petr Mladek <[email protected]> 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");

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 {
        # - 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]*\] //')

-- 
Regards
Yafang