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

[Tetsuo Handa]

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