Re: [PATCH RFC v1 05/26] printk_safe: externalize printk_context

From: Alexander Potapenko <glider@google.com>
To: Petr Mladek <pmladek@suse.com>
Cc: Vegard Nossum <vegard.nossum@oracle.com>,
	 Sergey Senozhatsky <sergey.senozhatsky@gmail.com>,
	Steven Rostedt <rostedt@goodmis.org>,
	 Dmitry Vyukov <dvyukov@google.com>,
	Linux Memory Management List <linux-mm@kvack.org>
Subject: Re: [PATCH RFC v1 05/26] printk_safe: externalize printk_context
Date: Tue, 29 Oct 2019 13:45:06 +0100	[thread overview]
Message-ID: <CAG_fn=WA9UJLUWOiLcm5ASSJ12TFGuip+3Odvu5D8PVeOCAK_w@mail.gmail.com> (raw)
In-Reply-To: <20191029120235.uncxoraf4ex2haut@pathway.suse.cz>

On Tue, Oct 29, 2019 at 1:02 PM Petr Mladek <pmladek@suse.com> wrote:
>
> On Mon 2019-10-28 14:09:29, Alexander Potapenko wrote:
> > On Thu, Oct 24, 2019 at 2:46 PM Petr Mladek <pmladek@suse.com> wrote:
> > > On Wed 2019-10-23 19:57:39, Alexander Potapenko wrote:
> > > > What I'm seeing now is that e.g. in the following case:
> > > >   ptr = kmalloc(sizeof(int), GFP_KERNEL);
> > > >   if (ptr)
> > > >     pr_info("true\n");
> > > >   else
> > > >     pr_info("false\n");
> > > >
> > > > KMSAN detects errors within pr_info(), namely in vprintk_store().
> > > > If I understand correctly, printing from that point causes printk to
> > > > use the per-cpu buffer, which is flushed once we're done with the
> > > > original printing:
> > > >
> > > > [   58.984971][ T8390] BUG: KMSAN: uninit-value in
> > > > kmsan_handle_vprintk+0xa0/0xf0
> > > > ...
> > > > [   59.061976][    C0] BUG: KMSAN: uninit-value in vsnprintf+0x3276/0x32b0
> > > > ...
> > > > [   59.062457][    C0] BUG: KMSAN: uninit-value in format_decode+0x17f/0x1900
> > > > ...
> > > > [   59.062961][    C0] BUG: KMSAN: uninit-value in format_decode+0x17f/0x1900
> > >
> > > Please, do you have an explanation where the uninitialized values come
> > > from? Is it a false positive? Or is there really a bug how the
> > > printk() parameters are passed?
> > I believe these are true bugs.
> > The problem is, when we pass an uninitialized argument into printk(),
> > KMSAN will report an error every time this uninitialized argument is
> > used.
>
> I see, thanks for explanation.
>
> > E.g. for an uninitialized format string there'll be at least
> > strlen(fmt) reports in format_decode(), followed by several reports in
> > vsnprintf().
> > Although these reports seem to be real, printing only the first of
> > them should be more than enough.
>
> Isn't this a generic problem? I mean that uninitialized values
> can be passed and used also in many other locations.
More or less, yes.
> printk() is special because this problem causes infinite loop. But it
> would make sense to report also any other problematic value only once.
Yes, printk is a bit different, because finding errors in it causes
other printk() calls which now don't cause infinite loops, but may
produce out-of-order error messages.

>
> > In the future we'll actually want KMSAN to check every printk()
> > argument (which will require parsing the format string to figure out
> > the arguments' lengths), but disable reports within printk.
>
> What is the motivation for this, please?
>
> It looks to me that you want to do very paranoid checks of variables
> passed to printk()? Do you want to prevent printk() crashes? Or
> do you want to make sure that printk() produces correct values?
Simply passing an uninitialized value to printk() may result in
cryptic error messages from printk guts, which may be harder to
understand without knowing how printk works.
The idea is to check the arguments right before printk, so that we can
print a really simple diagnostic message.
> From my POV, printk() is debugging tool. It is used to show values
> that people are interested in. On one hand, it might make sense to warn
> people that a particular value was not initalized. On the other hand,
> printk() is not important for the kernel behavior. It just
> reads values and does not affect any behavior.
>
> I would like to understand how many printk-related code is
> worth the effort.
I think overall you're right.
The feature I'm talking about isn't a critical part of KMSAN
functionality, so in order to keep the code simple I'd better drop it,
as long as we're able to report bugs when uninitialized memory is
passed to printk.

The only change to printk that I'll probably still have to make is to
initialize the result of vscnprintf() here:
https://github.com/google/kmsan/blob/master/kernel/printk/printk.c#L1921
Passing uninitialized data to vscnprintf() causes its result to also
be uninitialized, which causes an avalanche of new reports in
vprintk_store()
I'll send the updated patch (together with other KMSAN patches) your way today.

> Best Regards,
> Petr

-- 
Alexander Potapenko
Software Engineer

Google Germany GmbH
Erika-Mann-Straße, 33
80636 München

Geschäftsführer: Paul Manicle, Halimah DeLaine Prado
Registergericht und -nummer: Hamburg, HRB 86891
Sitz der Gesellschaft: Hamburg