Re: [PATCH] printk: Userspace format enumeration support

[Chris Down]

Joe Perches writes:
> > There are several issues with your proposed approach that make it unsuitable
> > for use as part of a reliable production environment:
> >
> > 1. It misses printk() formats without KERN_SOH
> >
> > printk() formats without KERN_SOH are legal and use MESSAGE_LOGLEVEL_DEFAULT.
> > On my test kernel, your proposed patch loses >5% of printk formats -- over 200
> > messages -- due to this, including critical ones like those about hardware or
> > other errors.
>
> There are _very_ few of those printks without KERN_<level> and those
> very few are not generally being changed.

I already specified how many are lost: 5%. That's not "very few". That's a huge 
proportion of the coverage afforded by this patch, including several important 
cases.

Relying on "they generally don't change" is not a recipe for reliability or 
success (and they do change, more data on that below).

> > 2. Users don't always have the kernel image available
> >
> > Many of our machines and many of the machines of others like us do not boot
> > using local storage, but instead use PXE or other technologies where the kernel
> > may not be stored during runtime.
> >
> > As is described in the changelog, it is necessary to be able to vary
> > remediations not only based on what is already in /dev/kmsg, but also to be
> > able to make decisions about our methodology based on what's _supported_ in the
> > running kernel at runtime, and your proposed approach makes this not viable.
>
> Indirection would alway work.
>
> You could load a separate file with output strings along with your
> kernel image.

You're moving the goalposts quite quickly here, which makes it harder to reply 
to your points. Now you're proposing an entirely separate distribution path, 
compared to interfaces that we already have precedent for in the kernel (eg.  
trace_printk). That requires a strong justification, and I'm not seeing one 
here.

> > 3. `KERN_SOH + level' can appear in other places than just printk strings
> >
> > KERN_SOH is just ASCII '\001' -- it's not distinctive or unique, even when
> > paired with a check for something that looks like a level after it. For this
> > reason, your proposed patch results in a non-trivial amount of non-printk
> > related garbage in its output. For example:
> >
> >      % binutils/strings -k /tmp/vmlinux | head -5
> >      3L)s
> >      3L)s
> >      c,[]A\
> >      c(L)c
> >      d$pL)d$`u4
> >
> > Fundamentally, one cannot use a tool which just determines whether something is
> > printable to determine semantic intent.
>
> $ kernel_strings --kernel --section ".rodata" vmlinux
>
> I got exactly 0.

"It works on my computer" is not a valid testing methodology, especially for 
something as complex as the Linux kernel. It's especially not a valid rebuttal 
to someone demonstrating that it clearly doesn't work on theirs.

Even filtering to the .rodata section, there's plenty of garbage just in the 
first five cases:

    % binutils/strings --kernel --section ".rodata" /tmp/vmlinux | head -5
    3******* Your BIOS seems to not contain a fix for K8 errata #93
    1>pBC)
    dTRAC
    6Run %s as init process
    7calling  %pS @ %i

Clearly there are cases that you are not considering. My kernel config is 
attached if you want to try and replicate, but regardless, it's really not 
valid to say "it works for me" in response to someone showing that it doesn't.

> > 4. strings(1) output cannot differentiate embedded newlines and new formats
> >
> > The following has exactly the same output from strings(1), but will manifest
> > completely differently at printk() time:
> >
> >      printk(KERN_ERR "line one\nline two\nline three\n");
> >      printk("line four\n");
>
> This is not the preferred output style and is only done in old and
> unchanging code.
>
> Your use case in your commit log is looking for _changed_ formats.

Joe, it's fine to present alternatives to people's patches, but please do your 
research before spouting things like this. It's a waste of everyone's time to 
refute things which are so easily demonstrated to be false.

Here are a bunch of recent changes to printk I found just from literally 2 
minutes of looking through `git log`:

- ea34f78f3df6: 2020, printk site deleted (which of course we also need to know.)
- a0f6d924cada: 2020, new callsite. the level is printed dynamically, so your proposed patch would not match.
- bf13718bc57a: 2020, existing printk changed. 
- 994388f228c6: 2020, printk site changed to au0828_isocdbg, reworded entirely.
- a8b62fd08505: 2020, new callsite, dynamic level.

I could find literally pages and pages of these just from the last few years.  
Your belief that these printks are only in "unchanging" code does not match 
reality.

> On Thu, 2021-02-04 at 15:37 +0000, Chris Down wrote:
> > This patch provides a solution to the issue of silently changed or
> > deleted printks:
>
> Exactly _how_ many of these use cases do you think exist?
>
> The generally preferred style for the example above would be:
>
> 	pr_err("line one\n");
> 	pr_err("line two\n");
> 	pr_err("line three\n");
> 	pr_err("line four\n");

I have no idea why you think this is so rare -- we have mixed pr_* and 
unadorned printk() all over the codebase. A number of the patches I just gave 
above are in files with mixed calls.

> > The originally posted patch _does_ differentiate between these cases, using \0
> > as a reliable separator. Its outputs are, respectively:
> >
> >      \0013line one\nline two\nline three\0\nline four\n\0
> >      \0013line one\nline two\n\0line three\nline four\n\0
> >
> > This isn't just a theoretical concern -- there are plenty of places which use
> > multiline printks, and we must be able to distinguish between that and
> > _multiple_ printks.
>
> Just like there are many places that use buffered printks as the
> example I gave earlier.  None of which your proposed solution would find.

There are always going to be cases which are not caught. The point is that the 
patch proposed in this thread captures significantly more cases than the 
`strings` case (not to mention that it avoids outputting garbage from .rodata), 
not that it covers every imaginable scenario.

> > 5. strings(1) is not contextually aware, and cannot be made to act as if it is
> >
> > strings has no idea about what it is reading, which is why it is more than
> > happy to output the kind of meaningless output shown in #3. There are plenty of
> > places across the kernel where there might be a sequence of bytes which the
> > strings utility happens to interpret as being semantically meaningful, but in
> > reality just happens to be an unrelated sequence of coincidentally printable
> > bytes that just happens to contain a \001.
> >
> > I appreciate your willingness to propose other solutions, but for these
> > reasons, the proposed strings(1) patch would not suffice as an interface for
> > printk enumeration.
>
> I think you are on a path to try to make printk output immutable.
> I think that's a _very_ bad path.

That's literally the opposite of what this patchset does. This patchset 
offloads the responsibility of worrying about userspace parsers breaking 
because of changes to kernel printks, because those userspace parsers and 
maintainers now have a mechanism to detect changes. If anything, it _reduces_ 
the risk of what you're describing.