Re: [PATCH v8 09/21] tracing/remotes: selftests: Add a test for the dmesg tracefs file

[sashiko-bot@kernel.org]

Thank you for your contribution! Sashiko AI review found 2 potential
issues to consider:
- [Low] tracing/remotes: selftests: dmesg.tc fails when
  CONFIG_PRINTK_CALLER=y
- [Low] tracing/remotes: selftests: unpinned writes in test_dmesg() race
  with poll
--

commit 3fde60957549859280fe5d4a8fc22ed359270e5c
Author: Vincent Donnefort <vdonnefort@google.com>

tracing/remotes: selftests: Add a test for the dmesg tracefs file

This commit adds ftrace selftests for the trace remote dmesg tracefs file
to verify dmesg redirection on both the test remote and hypervisor remote.

> diff --git a/tools/testing/selftests/ftrace/test.d/remotes/dmesg.tc b/tools/testing/selftests/ftrace/test.d/remotes/dmesg.tc
> new file mode 100644
> index 0000000000000..a5dcdd91e516b
> --- /dev/null
> +++ b/tools/testing/selftests/ftrace/test.d/remotes/dmesg.tc
> @@ -0,0 +1,86 @@
[ ... ]
> +    nr_events=128
> +    for i in $(seq 1 $nr_events); do
> +        echo $i > write_event
> +    done

[Severity: Low]
Can unpinned writes to write_event here race with the periodic dmesg poller
and log events out of order?

Enabling dmesg starts the 100 ms periodic poll_work, and each write_event
records into the current CPU's ring buffer.  If this loop migrates from a
CPU that was already polled or drained in the current cycle to a CPU that
is drained later in the same cycle, newer events on the second CPU are
printed to dmesg before earlier events on the first CPU, which remain unseen
until the next poll cycle and cause check_trace() to fail its monotonic
timestamp and sequential ID checks.  Pinning the writer loop to a single
CPU with taskset, as trace_pipe.tc does when writing concurrently with a
reader, would avoid this.

> +    sleep 1
> +    output=$(mktemp $TMPDIR/remote_test.XXXXXX)
> +    dmesg | awk -v ts=$last_ts '
> +    /^\[ *[0-9]+\.[0-9]+\]/ {
> +        t=$0; sub(/^[[ \t]*/, "", t); sub(/].*/, "", t);
> +        if (t+0 > ts+0) print $0
> +    }' | grep "selftest id=" | sed 's/^[^]]*] //'> $output
> +
> +    check_trace 1 $nr_events $output

[Severity: Low]
Does this sed expression fail to strip the printk prefix when
CONFIG_PRINTK_CALLER=y is enabled?

With CONFIG_PRINTK_CALLER=y, dmesg prefixes each line with a second
bracketed caller ID field such as "[   12.345678][   T42] " or
"[   12.345678] [   T42] ".  Because sed 's/^[^]]*] //' only strips a
single bracketed field followed by a space, the caller ID (or the entire
prefix) remains at the start of each line in $output.

tools/testing/selftests/ftrace/test.d/remotes/functions:check_trace() {
    ...
	sed -e 's/\[[0-9]*\]\s*\([0-9]*.[0-9]*\): [a-z]* id=\([0-9]*\)/\1 \2/' $file > $tmp
}

Because check_trace() does not strip characters preceding the numeric CPU
field, cut extracts parts of the remaining printk prefix instead of the
event timestamp and ID, causing the test to fail.

-- 
Sashiko AI review · https://sashiko.dev/#/patchset/20261106180657.2460376-1-vdonnefort@google.com?part=9