[Toybox] [PATCH] dmesg: fix multi-line messages

[Rob Landley]

On 10/5/22 02:27, Juhyung Park wrote:
> Hi Rob,
> 
> This was a nit-picky patch, so I didn't bother to follow up and ping
> you again, but yes, the issue is still there.
> Just checked again against the latest master branch: b5baa040128e Fix
> comm - and make comm -123 detect missing files.

Ok, good to know.

>> Was there more context? Was this ever tracked down as a kernel bug or a dash
>> issue or something? Is the original reporter still available? Because I didn't
>> reproduce it.
> 
> This is definitely not a kernel bug. It's just how the userspace
> parses /dev/kmsg.

Yes and no: I'm not sure yet what's winding up _in_ kmsg, nor how other
implementations are processing it...

>> > The behavior is reproducible on my Ubuntu setup and my Android 10 device.
>>
>> I was going to ask you to do:
>>
>>   sudo timeout 2 cat /dev/kmsg | gzip > kmsg.gz
>>
>> And send me the kmsg.gz file on a system demonstrating this problem.
> 
> That indeed would make it much easier for you to take a look:
> https://arter97.com/kmsg.gz

"I wonder how toybox dmesg is currently displaying that..." It's showing it as 2
lines because /dev/kmem returns one log line per read and the code is depending
on that, and when I point it at the file it reads 8k and prints the first line
of that and then reads another 8k.

Sigh. Right...

> I've changed my phone since, and this kernel prints other special
> characters than just '\x0a' too, so the original patch I've sent can
> definitely be improved.
> For example, '\x09' is correctly handled as '\t' by util-linux.

I see the \x in that, which my kmsg has zero instances of. Specifically, there
are a bunch of repeats of three different lines:

$ grep '[\\]' kmsg
5,1130128,165666701805,-;[OPLUS_CHG][oplus_chg_set_input_current_limit:3714]led_on
= 0, \x09\x09cool_down = 0 \x09\x09current_limit = 2000, \x09\x09led_temp_status = 0
3,1142851,166842204503,-;ams-tof [INFO]  tof_suspend\x0a
3,1142921,166842361220,-;ams-tof [INFO]  tof_resume\x0a

One has tabs in it (for some reason?), the other has trailing newlines. (Again:
trailing. Those suspend/resume lines are adjacent in the log. So the trailing
newlines probably shouldn't be there, and the proper thing to do for display
purposes would be to remove them?)

I'm actually kind of impressed that google says
oplus_chg_set_input_current_limit matched zero documents. Same for "tof_suspend"
(which has to be in quotes because otherwise it searches for tof suspend with a
space in between). Whatever code this is, it appears to be closed source?

Searching for OPLUS_CHG brings up
https://review.lineageos.org/c/LineageOS/android_kernel_oneplus_sm8350/+/311409/1/techpack/oneplus/devicetree/lemonadev.dtsi
which gives me somewhere to start, but that's not the same as tracking down the
statement responsible for the log line you're seeing. (Is this a userspace
package doing that?)

What I _also_ see in your log file is:

5,1129644,165502273059,-;sd 0:0:0:0: [sda] Synchronizing SCSI cache
 SUBSYSTEM=scsi
 DEVICE=+scsi:0:0:0:0

With actual unescaped newlines in it, so if your kernel was escaping \x0a on
output why wouldn't those also get escaped? It looks like on your system (but
not mine) those escapes are being written INTO the log.

You say you're seeing this on your phone and on your distro? (Elliott, does that
kind of thing show up in the /dev/kmsg of android systems you've seen? I get an
access denied reading from /dev/kmem on my stock Snow Cone phone...)

>> > The reason why I wanted to fix this was to make toybox properly
>> > display multi-line printk()s such as `pr_info("%s\n%s\n%s", ...);`.

There are lines with actual newlines in them and debian's dmesg is only showing
the first line of those. The --help output doesn't seem to have an obvious way
to use that extra info, and toybox's code (which came from Elliott) is doing:

  // Drop extras after end of message text.
  if ((p = strchr(text = msg+pos, '\n'))) *p = 0;

I.E. unconditionally dropping _actual_ extra lines...

Aha, I'm seeing it in Fedora! There's a number of \escapes in their /dev/kmsg.
(From the people who brought you systemd...)

Ok, I've got a test environment for this now, and...

Try commit 62f89088fdb1.

Rob