linux-kernel - Re: possible trace_printk() bug in v5.19-rc1

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]

Message-ID: <3EB14A14-767B-4B66-9B28-97DDE7EECFD2@oracle.com>
Date:   Sat, 25 Jun 2022 17:15:07 +0000
From:   Chuck Lever III <chuck.lever@...cle.com>
To:     Steven Rostedt <rostedt@...dmis.org>
CC:     LKML <linux-kernel@...r.kernel.org>
Subject: Re: possible trace_printk() bug in v5.19-rc1



> On Jun 24, 2022, at 7:08 PM, Steven Rostedt <rostedt@...dmis.org> wrote:
> 
> On Mon, 20 Jun 2022 00:57:23 +0000
> Chuck Lever III <chuck.lever@...cle.com> wrote:
> 
>>> Yes, I'm sure. I just checked out v5.18 and built it with the
>>> same CONFIG. trace_printk() on that kernel generates function
>>> names as expected.  
>> 
>> I moved my development work to another system, and bisected. The
>> result:
>> 
>> 91fb02f31505 ("module: Move kallsyms support into a separate file")
> 
> Hmm, right below that it says:
> 
>   "No functional change."
> 
> I'm guessing it may not be as reliably reproducible.

So far I've seen this misbehavior 100% of the time on two different
systems running 5.19-rc. But, I agree, it's not known how broadly
reproducible this is on the cohort of systems now running 5.19-rc.


> And is this an issue with trace-cmd output or reading the trace file?

The trace_printk() call site in nfsd_file_slab_free() shows up like
this via "trace-cmd show -p":

     ksoftirqd/2-28      [002] ..s..    61.849252: nfsd_file_slab_free: nf=0000000007b6d60b
     ksoftirqd/2-28      [002] ..s..    61.849257: nfsd_file_slab_free: nf=000000004bf47e99
          <idle>-0       [005] ..s1.    61.853212: nfsd_file_slab_free: nf=0000000029187f87
          <idle>-0       [005] ..s1.    61.853223: nfsd_file_slab_free: nf=000000003cd1db63

So, it looks like the misbehavior appears only with "trace-cmd report".

[root@...et ~]# cat /etc/redhat-release 
Fedora release 35 (Thirty Five)
[root@...et ~]# trace-cmd version

trace-cmd version 2.9.2 (not-a-git-repo)

usage:
  trace-cmd [COMMAND] ...

  commands:
     record - record a trace into a trace.dat file
     set - set a ftrace configuration parameter

 ...

     check-events - parse trace event formats
     dump - read out the meta data from a trace file

[root@...et ~]# 

--
Chuck Lever