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

[Alexander Potapenko <glider@google.com>]

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:
> > On Mon, Oct 21, 2019 at 11:09 AM Petr Mladek <pmladek@suse.com> wrote:
> > >
> > > On Fri 2019-10-18 11:42:43, glider@google.com wrote:
> > > > Petr Mladek suggested we use
> > > >   this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK
> > > > instead of checking the spinlock status in kmsan_pr_err()
> > >
> > > I would like to understand why the check is needed.
> > >
> > > My guess is that it prevents a infinite recursion.
> > > Is this the case? It might be possible to debug this using
> > > trace_printk().
> > This indeed used to prevent infinite recursion, however looks like the
> > check isn't needed anymore.
> > When I remove it, KMSAN doesn't hang, probably because printk is doing
> > a better job at deadlock prevention.
>
> Great.
>
> > 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.
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.
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.

> > ...
> > [   59.063338][    C0] Lost 6207 message(s)!
>
> This message comes from report_message_lost(). It means that many
> recursive messages did not fit into the limited per-CPU buffers.
>
> > So it turns out we'd better disable reporting under logbuf_lock,
> > otherwise these lost messages will confuse the developers.
> > Because the first pr_info() isn't called by KMSAN itself, the tool
> > still needs a way to know it's running inside printk.
>
> OK. Well, I still would like to understand why the recursive messages
> are printed at all. Is it a bug in the printk() code or a false positive?
>
> There should be no recursive messages if we fix the bug or make
> some annotations to prevent the false positives.
>
> That said, I am not completely against disabling the recursive
> messages. But it would be pity to hide some real bugs.
>
> 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