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

[enh]

On Thu, Oct 6, 2022 at 3:23 AM Rob Landley <rob at landley.net> wrote:

> 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...)
>

yeah, you'd be surprised at the weird stuff that ends up in logs. i swear
that people don't even always look at the output they added code for
sometimes (and they _definitely_ don't do a good job of sanitizing output).
even though the GKI generic kernels mean the kernels are now consistent
across devices, (a) that doesn't mean the upstream kernel doesn't have bad
logging and (b) that says nothing about all the device drivers loaded as
kernel modules from the vendor partition.

so, yeah, "assume anything that can happen will happen".


> >> > 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...
>

d'oh! (and of course, no-one would have noticed that by definition :-( )


> 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
> _______________________________________________
> Toybox mailing list
> Toybox at lists.landley.net
> http://lists.landley.net/listinfo.cgi/toybox-landley.net
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.landley.net/pipermail/toybox-landley.net/attachments/20221006/892fa3f6/attachment.htm>