Re: [PATCH] printk: inject caller information into the body of message

[Petr Mladek]

On Mon 2018-10-08 19:31:58, Tetsuo Handa wrote:
> On 2018/10/02 15:38, Sergey Senozhatsky wrote:
> > I have sketched a very silly, quick-and-dirty implementation using
> > struct cont. It derives all the good features of the existing pr_cont.
> > I didn't spend enough time on this. It's just a sketch... which compiles
> > and that's it.
> 
> Sergey and I had off-list discussion about an implementation above. But
> I concluded that I should update my version than updating Sergey's sketch.
> 
> The origin ( https://groups.google.com/forum/#!topic/syzkaller/ttZehjXiHTU ) is
> how to prefix caller information to each line of printk() messages so that syzbot
> can group messages from each context and do the better processing.
> 
> We know that Linus has refused injecting extra data into message body
> ( https://lkml.kernel.org/r/CA+55aFynkjSL1NNZbx6m1iE2HjZagGK09rAr5-HaZ4Ep2eWKOg@xxxxxxxxxxxxxx )
> 
>   On 2017/09/18 0:35, Linus Torvalds wrote:
>   > On Sat, Sep 16, 2017 at 11:26 PM, Sergey Senozhatsky
>   > <sergey.senozhatsky@xxxxxxxxx> wrote:
>   >>
>   >> so... I think we don't have to update 'struct printk_log'. we can store
>   >> that "extended data" at the beginning of every message, right after the
>   >> prefix.
>   > 
>   > No, we really can't. That just means that all the tools would have to
>   > be changed to get the normal messages without the extra crud. And
>   > since it will have lost the difference, that's not even easy to do.
>   > 
>   > So this is exactly the wrong way around.
>   > 
>   > If people want to see the extra data, it really should be extra data
>   > that you can get with a new interface from the kernel logs. Not a
>   > "let's just a add it to all lines and make every line uglier and
>   > harder to read.
>   > 
>   >               Linus
> 
> but we also know that syzbot cannot count on a new interface
> ( https://lkml.kernel.org/r/CACT4Y+aFO+yZ7ovkxJOJfz=JgsE3yr+ywLQ9kVUrOHYMBgfWdg@xxxxxxxxxxxxxx )
> 
>   On 2018/05/18 22:08, Dmitry Vyukov wrote:
>   > On Fri, May 18, 2018 at 2:54 PM, Petr Mladek <pmladek@xxxxxxxx> wrote:
>   >> On Fri 2018-05-18 14:25:57, Dmitry Vyukov wrote:
>   >>>> On Thu 2018-05-17 20:21:35, Sergey Senozhatsky wrote:
>   >>>>> Dunno...
>   >>>>> For instance, can we store context tracking info as a extended record
>   >>>>> data? We have that dict/dict_len thing. So may we can store tracking
>   >>>>> info there? Extended records will appear on the serial console /* if
>   >>>>> console supports extended data */ or can be read in via devkmsg_read().
>   >>>
>   >>> What consoles do support it?
>   >>> We are interested at least in qemu console, GCE console and Android
>   >>> phone consoles. But it would be pity if this can't be used on various
>   >>> development boards too.
>   >>
>   >> Only the netconsole is able to show the extended (dict)
>   >> information at the moment. Search for CON_EXTENDED flag.
>   > 
>   > Then we won't be able to use it. And we can't pipe from devkmsg_read
>   > in user-space, because we need this to work when kernel is broken in
>   > various ways...
> 
> and we have to allow normal consoles to inject caller information into message
> body. Since syzbot can modify kernel configurations and kernel boot command
> line options, if Linus permits, we can enable injecting caller information to
> only syzbot environments.
> 
> Regarding a concern Linus mentioned
> ( https://lkml.kernel.org/r/CA+55aFwmwdY_mMqdEyFPpRhCKRyeqj=+aCqe5nN108v8ELFvPw@xxxxxxxxxxxxxx ),
> we would be able to convert
> 
>      printk("Testing feature XYZ..");
>      this_may_blow_up_because_of_hw_bugs();
>      printk(KERN_CONT " ... ok\n");
> 
> to
> 
>      printk("Testing feature XYZ..\n");
>      this_may_blow_up_because_of_hw_bugs();
>      printk("... feature XYZ ok\n");
> 
> and eventually remove pr_cont/printk(KERN_CONT) support (i.e. printk() will always
> emit '\n').
> 
> 
> 
> >From df59a431b18888af3bdc9a90d03f1a9d63a12c3e Mon Sep 17 00:00:00 2001
> From: Tetsuo Handa <penguin-kernel@xxxxxxxxxxxxxxxxxxx>
> Date: Sun, 7 Oct 2018 10:20:38 +0900
> Subject: [PATCH v3] printk: Add line-buffered printk() API.
> 
> Sometimes we want to print a whole line without being disturbed by
> concurrent printk() from interrupts and/or other threads, for printk()
> which does not end with '\n' can be disturbed.
> 
> Mixed printk() output makes it hard to interpret. Assuming that we will go
> to a direction that we allow prefixing context identifier to each line of
> printk() output (so that we can group multiple lines into one block when
> parsing), this patch introduces API for line-buffered printk() output
> (so that we can make sure that printk() ends with '\n').
> 
> Since functions introduced by this patch are merely wrapping
> printk()/vprintk() calls in order to minimize possibility of using
> "struct cont", it is safe to replace printk()/vprintk() with this API.
> 
> Details:
> 
>   A structure named "struct printk_buffer" is introduced for buffering
>   up to LOG_LINE_MAX bytes of printk() output which did not end with '\n'.
> 
>   A caller is allowed to allocate/free "struct printk_buffer" using
>   kzalloc()/kfree() if that caller is in a location where it is possible
>   to do so.
> 
>   A macro named "DEFINE_PRINTK_BUFFER()" is defined for allocating
>   "struct printk_buffer" from the stack memory or in the .bss section.
> 
>   But since sizeof("struct printk_buffer") is nearly 1KB, it might not be
>   preferable to allocate "struct printk_buffer" from the stack memory.
>   In that case, a caller can use best-effort buffering mode. Two functions
>   get_printk_buffer() and put_printk_buffer() are provided for that mode.
> 
>   get_printk_buffer() tries to assign a "struct printk_buffer" from
>   statically preallocated array. It returns NULL if all static
>   "struct printk_buffer" are in use.
> 
>   put_printk_buffer() flushes and releases the "struct printk_buffer".
>   put_printk_buffer() must match corresponding get_printk_buffer() as with
>   rcu_read_unlock() must match corresponding rcu_read_lock().

One problem with this API is when it is used in more complicated code
and put_printk_buffer() is not called in some path. I mean leaking.
We might get out of buffers easily.

A solution might be to store some information about the owner and
put the buffer also when a non-buffered printk is called from
the same context.

It might even make it easier to use. If we are able to guess the
buffer by the context, we do not need to pass it as an argument.

Well, I would like to avoid having the buffer connected with CPU.
It would require to disable preemption in get_printk_buffer().
IMHO, it would be a unintuitive and even unwanted side effect.

Best Regards,
Petr


PS: I am sorry for the late reply. I was busy with some other
important stuff. I still have to think more about it and look
mode deeply into the implementation.

In each case, we need to be careful about the design.
The API has to be easy and safe to use. Also the implementation
should not complicate the printk design too much.

It looks promising. Also there is a high chance that it would
be much more straightforward than the current code around
the cont buffer ;-)