linux-kernel - Re: TP_printk() bug with %c, and more?

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date: Fri, 15 Mar 2024 19:03:12 +0100
From: Luca Ceresoli <luca.ceresoli@...tlin.com>
To: Steven Rostedt <rostedt@...dmis.org>
Cc: Masami Hiramatsu <mhiramat@...nel.org>, Mathieu Desnoyers
 <mathieu.desnoyers@...icios.com>, linux-kernel@...r.kernel.org,
 linux-trace-kernel@...r.kernel.org, Liam Girdwood <lgirdwood@...il.com>,
 Mark Brown <broonie@...nel.org>, Thomas Petazzoni
 <thomas.petazzoni@...tlin.com>
Subject: Re: TP_printk() bug with %c, and more?

Hello Steven,

thanks for the quick feedback!

On Fri, 15 Mar 2024 13:21:46 -0400
Steven Rostedt <rostedt@...dmis.org> wrote:

> On Fri, 15 Mar 2024 17:49:00 +0100
> Luca Ceresoli <luca.ceresoli@...tlin.com> wrote:
> 
> > Hello Linux tracing maintainers,  
> 
> Hi Luca!
> 
> > 
> > I've come across an unexpected behaviour in the kernel tracing
> > infrastructure that looks like a bug, or maybe two.
> > 
> > Cc-ing ASoC maintainers for as it appeared using ASoC traces, but it
> > does not look ASoC-specific.
> > 
> > It all started when using this trace-cmd sequence on an ARM64 board
> > running a mainline 6.8.0-rc7 kernel:
> > 
> >   trace-cmd record -e snd_soc_dapm_path ./my-play
> >   trace-cmd report
> > 
> > While this produces perfectly valid traces for other asoc events,
> > the snd_soc_dapm_path produces:
> > 
> >   snd_soc_dapm_path:    >c<* MIC1_EN <- (direct) <-
> > 
> > instead of the expected:
> > 
> >   snd_soc_dapm_path:    *MIC1 <- (direct) <- MIC1_EN
> > 
> > The originating macro is:
> > 
> > 	TP_printk("%c%s %s %s %s %s",
> > 		(int) __entry->path_node &&
> > 		(int) __entry->path_connect ? '*' : ' ',
> > 		__get_str(wname), DAPM_ARROW(__entry->path_dir),
> > 		__get_str(pname), DAPM_ARROW(__entry->path_dir),
> > 		__get_str(pnname))
> > 
> > It appears as if the %c placeholder always produces the three ">c<"
> > characters, the '*' or ' ' char is printed as the first %s, all the
> > other strings are shifted right by one position and the last string is
> > never printed.
> > 
> > On my x86_64 laptop running the default Ubuntu kernel (6.5) I'm able to
> > trace a few events having a '%c' in their TP_printk() macros and the
> > result is:
> > 
> >   intel_pipe_update_start: dev 0000:00:02.0, pipe >c<, frame=1,
> >   scanline=107856, min=2208, max=2154
> >   
> 
> What does /sys/kernel/tracing/trace show?

It is correct:

   intel_pipe_update_start: dev 0000:00:02.0, pipe B, frame=377644, scanline=1466, min=2154, max=2159

> If that's fine, then the bug is in libtraceevent and not the kernel.
> 
> I'm testing it out now, and I see %c not being processed properly by
> libtraceevent. I'll take a deeper look.

Thanks.

> > originating from:
> > 
> >   TP_printk("dev %s, pipe %c, frame=%u, scanline=%u, min=%u, max=%u",
> > 
> > Here it looks like the %c produced ">c<" again, but apparently without
> > any shifting.
> > 
> > Back on the ARM64 board I found a couple interesting clues.
> > 
> > First, using the <debugfs>/tracing/ interface instead of trace-cmd, I'm
> > getting correctly formatted strings:
> > 
> > trace-cmd: snd_soc_dapm_path: >c<* HPOUT_L -> (direct) ->
> > debugfs:   snd_soc_dapm_path: *HPOUT_L <- (direct) <- HPOUT_POP_SOUND_L
> > 
> > Notice the arrows pointing to the opposite direction though. The correct
> > arrow is the one in the debugfs run.

This other issue appears a separate bug however.

Luca

-- 
Luca Ceresoli, Bootlin
Embedded Linux and Kernel engineering
https://bootlin.com