linux-kernel - Re: Tracing to console

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] [day] [month] [year] [list]

Date:   Fri, 14 Dec 2018 22:46:49 -0500
From:   Steven Rostedt <rostedt@...dmis.org>
To:     Bart Van Assche <Bart.VanAssche@....com>
Cc:     "linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>,
        "mingo@...hat.com" <mingo@...hat.com>
Subject: Re: Tracing to console

On Fri, 15 Jun 2018 21:01:53 +0000
Bart Van Assche <Bart.VanAssche@....com> wrote:

> Hello Steven,

Sorry about the 6 month old reply. I just noticed this email buried in
my INBOX (I triage my INBOX to find emails like this that got missed).
And yes I missed your reply as well :-/

> 
> If I run the following commands as root:
> 
> cd /sys/kernel/debug/tracing
> grep pm_ available_events > set_event
> echo function >current_tracer
> grep scsi_ available_filter_functions | while read a b; do echo $a; done >set_ftrace_filter
> echo 1 >events/printk/enable
> echo 1 >tracing_on
> echo 1 >/proc/sys/kernel/tracepoint_printk

Just for some closure. The tracepoint_printk is a special command that
only gets enabled if you pass "tp_printk" on the kernel command line.

> echo - - - >/sys/class/scsi_host/host0/scan
> 
> then the following appears on the console:
> 
> console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: console: console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: console: console: console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> console: console: console: console: console: console: console: console: console: console: console: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [ ... ]
> 
> I assume that the repeated "console: " prefix is a bug and also that the same
> line repeats over and over again is also a bug? I ran into this with commit
> 017b3f8a10ca ("scsi: snic: fix a couple of spelling mistakes: "COMPLETE"").
>

The above behavior is actually expected and not a bug. It's a "Doctor
it hurts me when I do this" issue. Don't do that ;-)

The tracepoint_printk is for cases where the system crashes before you
ever get to a command prompt, and you want to see trace events that you
can enable from the kernel command line. What you did above was like
running "ls -lR / > /dev/mem" in old kernels. It's doomed to fail.

You just told the kernel that you want all trace events to go over
printk, and you also told the kernel, you want all printk to become a
trace event. Thus you created a recursive loop. You're lucky it didn't
crash.

I hope this explains things for you.

Again, sorry that it took 6 months to reply. I believe June was a busy
time for me (vacation and work travel).

-- Steve