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

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

[Yafang Shao]

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)
  kobject: 'test_klp_livepatch' (ffff...): kobject_add_internal: parent: 'module', set: 'module'

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.

Signed-off-by: Yafang Shao <laoar.shao@gmail.com>
---
 tools/testing/selftests/livepatch/README       | 3 +++
 tools/testing/selftests/livepatch/functions.sh | 1 +
 2 files changed, 4 insertions(+)

diff --git a/tools/testing/selftests/livepatch/README b/tools/testing/selftests/livepatch/README
index d2035dd64a2b..d03461bd45bb 100644
--- a/tools/testing/selftests/livepatch/README
+++ b/tools/testing/selftests/livepatch/README
@@ -15,6 +15,9 @@ Config
 
 Set CONFIG_LIVEPATCH=y option and it's prerequisites.
 
+Note: CONFIG_DEBUG_KOBJECT and CONFIG_DEBUG_KOBJECT_RELEASE emit "kobject:"
+debug messages to the kernel log.  The tests filter these out, so they are safe
+to keep enabled.
 
 Building the tests
 ------------------
diff --git a/tools/testing/selftests/livepatch/functions.sh b/tools/testing/selftests/livepatch/functions.sh
index 17810521d069..3dae2ad20f1e 100644
--- a/tools/testing/selftests/livepatch/functions.sh
+++ b/tools/testing/selftests/livepatch/functions.sh
@@ -327,6 +327,7 @@ 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' | \
+		 grep -v 'kobject:' | \
 		 sed 's/^\[[ 0-9.]*\] //' | \
 		 sed 's/^\[[ ]*[CT][0-9]*\] //')
 
-- 
2.52.0

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

[Petr Mladek]

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.

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.

Best Regards,
Petr

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

[Yafang Shao]

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");

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

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

[Petr Mladek]

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