[PATCH] kernel/printk: prevent deadlock at calling kmsg_dump from NMI context

[PATCH] kernel/printk: prevent deadlock at calling kmsg_dump from NMI context

[Konstantin Khlebnikov]

Function kmsg_dump could be invoked from NMI context intentionally or
accidentally because it is called at various oops/panic paths.
Kernel message dumpers are not ready to work in NMI context right now.
They could deadlock on lockbuf_lock or break internal structures.

Theoretically some dumpers could be fixed and marked as NMI-safe.
Right now it's safer to print warning once and give up.

Signed-off-by: Konstantin Khlebnikov <khlebnikov@yandex-team.ru>
---
 kernel/printk/printk.c |    3 +++
 1 file changed, 3 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1888f6a3b694..2b83820bdc57 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -3104,6 +3104,9 @@ void kmsg_dump(enum kmsg_dump_reason reason)
 	struct kmsg_dumper *dumper;
 	unsigned long flags;
 
+	if (WARN_ON_ONCE(in_nmi()))
+		return;
+
 	if ((reason > KMSG_DUMP_OOPS) && !always_kmsg_dump)
 		return;
 

Re: [PATCH] kernel/printk: prevent deadlock at calling kmsg_dump from NMI context

[Sergey Senozhatsky]

On (07/12/19 17:54), Konstantin Khlebnikov wrote:
> Function kmsg_dump could be invoked from NMI context intentionally or
> accidentally because it is called at various oops/panic paths.
> Kernel message dumpers are not ready to work in NMI context right now.
> They could deadlock on lockbuf_lock or break internal structures.

Hmm.
printk()-s from NMI go through per-CPU printk_safe/nmi - a bunch of
lockless buffers which is supposed to deal with printk() deadlocks,
including NMI printk()-s.

include/linux/hardirq.h

#define nmi_enter()
	...
	printk_nmi_enter();
	...

#define nmi_exit()
	...
	printk_nmi_exit();
	...

So we are not really supposed to deadlock.

	-ss

Re: [PATCH] kernel/printk: prevent deadlock at calling kmsg_dump from NMI context

[Konstantin Khlebnikov]

On Sat, Jul 13, 2019 at 9:10 AM Sergey Senozhatsky
<sergey.senozhatsky@gmail.com> wrote:
>
> On (07/12/19 17:54), Konstantin Khlebnikov wrote:
> > Function kmsg_dump could be invoked from NMI context intentionally or
> > accidentally because it is called at various oops/panic paths.
> > Kernel message dumpers are not ready to work in NMI context right now.
> > They could deadlock on lockbuf_lock or break internal structures.
>
> Hmm.
> printk()-s from NMI go through per-CPU printk_safe/nmi - a bunch of
> lockless buffers which is supposed to deal with printk() deadlocks,
> including NMI printk()-s.
>
> include/linux/hardirq.h
>
> #define nmi_enter()
>         ...
>         printk_nmi_enter();
>         ...
>
> #define nmi_exit()
>         ...
>         printk_nmi_exit();
>         ...
>
> So we are not really supposed to deadlock.

Yep printk() can deal with NMI, but kmsg_dump() is a different beast.
It reads printk buffer and saves content into persistent storage like ACPI ERST.

>
>         -ss

Re: [PATCH] kernel/printk: prevent deadlock at calling kmsg_dump from NMI context

[Sergey Senozhatsky]

On (07/13/19 09:46), Konstantin Khlebnikov wrote:
> > On (07/12/19 17:54), Konstantin Khlebnikov wrote:
> 
> Yep printk() can deal with NMI, but kmsg_dump() is a different beast.
> It reads printk buffer and saves content into persistent storage like ACPI ERST.

Ah, sorry! I misread your patch. Yeah, I see what you are doing.

OK. So, I guess that for kmsg_dump(KMSG_DUMP_PANIC) we should be
fine in general.

We call kmsg_dump(KMSG_DUMP_PANIC) after smp_send_stop() and after
printk_safe_flush_on_panic(). printk_safe_flush_on_panic() resets
the state of logbuf_lock, so logbuf_lock, in general case, should
be unlocked by the time we call kmsg_dump(KMSG_DUMP_PANIC).
Even for nested contexts.

	CPU0
	printk()
	 logbuf_lock_irqsave(flags)
	  -> NMI
	   panic()
	    smp_send_stop()
	     printk_safe_flush_on_panic()
	      raw_spin_lock_init(&logbuf_lock) << reinit >>
	    kmsg_dump(KMSG_DUMP_PANIC)
	     logbuf_lock_irqsave(flags)        << expected to be OK >>

So do we have strong reasons to disable NMI->panic->kmsg_dump(DUMP_PANIC)?

Other kmsg_dump(), maybe, can experience some troubles sometimes,
need to check that.

	-ss

Re: [PATCH] kernel/printk: prevent deadlock at calling kmsg_dump from NMI context

[Konstantin Khlebnikov]

On Sat, Jul 13, 2019 at 4:20 PM Sergey Senozhatsky
<sergey.senozhatsky@gmail.com> wrote:
>
> On (07/13/19 09:46), Konstantin Khlebnikov wrote:
> > > On (07/12/19 17:54), Konstantin Khlebnikov wrote:
> >
> > Yep printk() can deal with NMI, but kmsg_dump() is a different beast.
> > It reads printk buffer and saves content into persistent storage like ACPI ERST.
>
> Ah, sorry! I misread your patch. Yeah, I see what you are doing.
>
> OK. So, I guess that for kmsg_dump(KMSG_DUMP_PANIC) we should be
> fine in general.
>
> We call kmsg_dump(KMSG_DUMP_PANIC) after smp_send_stop() and after
> printk_safe_flush_on_panic(). printk_safe_flush_on_panic() resets
> the state of logbuf_lock, so logbuf_lock, in general case, should
> be unlocked by the time we call kmsg_dump(KMSG_DUMP_PANIC).
> Even for nested contexts.
>
>         CPU0
>         printk()
>          logbuf_lock_irqsave(flags)
>           -> NMI
>            panic()
>             smp_send_stop()
>              printk_safe_flush_on_panic()
>               raw_spin_lock_init(&logbuf_lock) << reinit >>
>             kmsg_dump(KMSG_DUMP_PANIC)
>              logbuf_lock_irqsave(flags)        << expected to be OK >>
>
> So do we have strong reasons to disable NMI->panic->kmsg_dump(DUMP_PANIC)?
>
> Other kmsg_dump(), maybe, can experience some troubles sometimes,
> need to check that.

Indeed, panic is especially handled and looks fine.

Sanity check in my patch could be relaxed:

       if (WARN_ON_ONCE(reason != KMSG_DUMP_PANIC && in_nmi()))
               return;

>
>         -ss

Re: [PATCH] kernel/printk: prevent deadlock at calling kmsg_dump from NMI context

[Sergey Senozhatsky]

On (07/13/19 17:03), Konstantin Khlebnikov wrote:
> > We call kmsg_dump(KMSG_DUMP_PANIC) after smp_send_stop() and after
> > printk_safe_flush_on_panic(). printk_safe_flush_on_panic() resets
> > the state of logbuf_lock, so logbuf_lock, in general case, should
> > be unlocked by the time we call kmsg_dump(KMSG_DUMP_PANIC).
> > Even for nested contexts.
> >
> >         CPU0
> >         printk()
> >          logbuf_lock_irqsave(flags)
> >           -> NMI
> >            panic()
> >             smp_send_stop()
> >              printk_safe_flush_on_panic()
> >               raw_spin_lock_init(&logbuf_lock) << reinit >>
> >             kmsg_dump(KMSG_DUMP_PANIC)
> >              logbuf_lock_irqsave(flags)        << expected to be OK >>
> >
> > So do we have strong reasons to disable NMI->panic->kmsg_dump(DUMP_PANIC)?
> >
> > Other kmsg_dump(), maybe, can experience some troubles sometimes,
> > need to check that.
> 
> Indeed, panic is especially handled and looks fine.
> 
> Sanity check in my patch could be relaxed:
> 
>        if (WARN_ON_ONCE(reason != KMSG_DUMP_PANIC && in_nmi()))
>                return;

How critical kmsg_dump() is? We deadlock only if NMI->kmsg_dump()
happens on the CPU which already holds the logbuf_lock; in any
other case logbuf_lock is owned by another CPU which is expected
to unlock it eventually. So it doesn't look like disabling all
NMI->kmsg_dump() is the only way to fix it.

When we lock logbuf_lock we increment per-CPU printk_context
(PRINTK_SAFE_CONTEXT_MASK bits); when we unlock logbuf_lock
we decrement printk_context. Thus we always can tell if the
logbuf_lock was locked on the very same CPU - this_cpu printk_context
has PRINTK_SAFE_CONTEXT_MASK bits sets - and we are about to deadlock
in a nested context (NMI), or the lock was locked on another CPU and
it's "safe" to spin on logbuf_lock and wait for logbuf_lock to become
available.

	-ss

Re: [PATCH] kernel/printk: prevent deadlock at calling kmsg_dump from NMI context

[Konstantin Khlebnikov]

On 15.07.2019 5:33, Sergey Senozhatsky wrote:
> On (07/13/19 17:03), Konstantin Khlebnikov wrote:
>>> We call kmsg_dump(KMSG_DUMP_PANIC) after smp_send_stop() and after
>>> printk_safe_flush_on_panic(). printk_safe_flush_on_panic() resets
>>> the state of logbuf_lock, so logbuf_lock, in general case, should
>>> be unlocked by the time we call kmsg_dump(KMSG_DUMP_PANIC).
>>> Even for nested contexts.
>>>
>>>          CPU0
>>>          printk()
>>>           logbuf_lock_irqsave(flags)
>>>            -> NMI
>>>             panic()
>>>              smp_send_stop()
>>>               printk_safe_flush_on_panic()
>>>                raw_spin_lock_init(&logbuf_lock) << reinit >>
>>>              kmsg_dump(KMSG_DUMP_PANIC)
>>>               logbuf_lock_irqsave(flags)        << expected to be OK >>
>>>
>>> So do we have strong reasons to disable NMI->panic->kmsg_dump(DUMP_PANIC)?
>>>
>>> Other kmsg_dump(), maybe, can experience some troubles sometimes,
>>> need to check that.
>>
>> Indeed, panic is especially handled and looks fine.
>>
>> Sanity check in my patch could be relaxed:
>>
>>         if (WARN_ON_ONCE(reason != KMSG_DUMP_PANIC && in_nmi()))
>>                 return;
> 
> How critical kmsg_dump() is? We deadlock only if NMI->kmsg_dump()
> happens on the CPU which already holds the logbuf_lock; in any
> other case logbuf_lock is owned by another CPU which is expected
> to unlock it eventually. So it doesn't look like disabling all
> NMI->kmsg_dump() is the only way to fix it.
> 
> When we lock logbuf_lock we increment per-CPU printk_context
> (PRINTK_SAFE_CONTEXT_MASK bits); when we unlock logbuf_lock
> we decrement printk_context. Thus we always can tell if the
> logbuf_lock was locked on the very same CPU - this_cpu printk_context
> has PRINTK_SAFE_CONTEXT_MASK bits sets - and we are about to deadlock
> in a nested context (NMI), or the lock was locked on another CPU and
> it's "safe" to spin on logbuf_lock and wait for logbuf_lock to become
> available.

I see no users who dumps dmesg from NMI context except panic.
This shouldn't happen. But might happen is something goes very wrong.

So, this trickery is not required.
Also spinning in NMI for handling non-fatal cases is a bad idea.

Re: [PATCH] kernel/printk: prevent deadlock at calling kmsg_dump from NMI context

[Sergey Senozhatsky]

On (07/15/19 10:38), Konstantin Khlebnikov wrote:
> > > Indeed, panic is especially handled and looks fine.
> > > 
> > > Sanity check in my patch could be relaxed:
> > > 
> > >         if (WARN_ON_ONCE(reason != KMSG_DUMP_PANIC && in_nmi()))
> > >                 return;
> > 
> > How critical kmsg_dump() is? We deadlock only if NMI->kmsg_dump()
> > happens on the CPU which already holds the logbuf_lock; in any
> > other case logbuf_lock is owned by another CPU which is expected
> > to unlock it eventually. So it doesn't look like disabling all
> > NMI->kmsg_dump() is the only way to fix it.
> > 
> > When we lock logbuf_lock we increment per-CPU printk_context
> > (PRINTK_SAFE_CONTEXT_MASK bits); when we unlock logbuf_lock
> > we decrement printk_context. Thus we always can tell if the
> > logbuf_lock was locked on the very same CPU - this_cpu printk_context
> > has PRINTK_SAFE_CONTEXT_MASK bits sets - and we are about to deadlock
> > in a nested context (NMI), or the lock was locked on another CPU and
> > it's "safe" to spin on logbuf_lock and wait for logbuf_lock to become
> > available.
> 
> I see no users who dumps dmesg from NMI context except panic.
> This shouldn't happen. But might happen is something goes very wrong.

I see. OK, if NMI->kmsg_dump() never happens (except for panic) then
we are fine, I guess.

	-ss

Re: [PATCH] kernel/printk: prevent deadlock at calling kmsg_dump from NMI context

[Petr Mladek]

On Mon 2019-07-15 11:33:38, Sergey Senozhatsky wrote:
> On (07/13/19 17:03), Konstantin Khlebnikov wrote:
> > > We call kmsg_dump(KMSG_DUMP_PANIC) after smp_send_stop()
> > 
> > Indeed, panic is especially handled and looks fine.

Just to get a picture. What other situations are we talking about,
please?

oops_exit() is one candidate. The other callers seem to be working
in normal context.


> > Sanity check in my patch could be relaxed:
> > 
> >        if (WARN_ON_ONCE(reason != KMSG_DUMP_PANIC && in_nmi()))
> >                return;
> 
> How critical kmsg_dump() is? We deadlock only if NMI->kmsg_dump()
> happens on the CPU which already holds the logbuf_lock; in any
> other case logbuf_lock is owned by another CPU which is expected
> to unlock it eventually. So it doesn't look like disabling all
> NMI->kmsg_dump() is the only way to fix it.
>
> When we lock logbuf_lock we increment per-CPU printk_context
> (PRINTK_SAFE_CONTEXT_MASK bits); when we unlock logbuf_lock
> we decrement printk_context. Thus we always can tell if the
> logbuf_lock was locked on the very same CPU - this_cpu printk_context
> has PRINTK_SAFE_CONTEXT_MASK bits sets - and we are about to deadlock
> in a nested context (NMI), or the lock was locked on another CPU and
> it's "safe" to spin on logbuf_lock and wait for logbuf_lock to become
> available.

This sounds familiar. I think that we did not consider it safe in the
end, see the commit 03fc7f9c99c1e7ae29 ("printk/nmi: Prevent deadlock
when accessing the main log buffer in NMI").

If the problem is only with Oops then the 2nd propose might be
acceptable. The system will either try to continue or it will end
up in panic() anyway.

Well, WARN() looks like an overkill, especially if there is only
one possible caller that prints the stack anyway. I would personally
do not print any message and do just:

	/*
	 * Prevent deadlock on logbuf_lock. It is safe only
	 * in panic() after smp_send_stop() and resetting
	 * the lock.
	 */
	if (in_nmi() && reason != KMSG_DUMP_PANIC)
		return;

Best Regards,
Petr

Re: [PATCH] kernel/printk: prevent deadlock at calling kmsg_dump from NMI context

[Konstantin Khlebnikov]

On 15.07.2019 10:54, Petr Mladek wrote:
> On Mon 2019-07-15 11:33:38, Sergey Senozhatsky wrote:
>> On (07/13/19 17:03), Konstantin Khlebnikov wrote:
>>>> We call kmsg_dump(KMSG_DUMP_PANIC) after smp_send_stop()
>>>
>>> Indeed, panic is especially handled and looks fine.
> 
> Just to get a picture. What other situations are we talking about,
> please?
> 
> oops_exit() is one candidate. The other callers seem to be working
> in normal context.

Oops in NMI mostly. Also I've screwed up several times with NMI watchdog
and dumping log at setting taint.

> 
> 
>>> Sanity check in my patch could be relaxed:
>>>
>>>         if (WARN_ON_ONCE(reason != KMSG_DUMP_PANIC && in_nmi()))
>>>                 return;
>>
>> How critical kmsg_dump() is? We deadlock only if NMI->kmsg_dump()
>> happens on the CPU which already holds the logbuf_lock; in any
>> other case logbuf_lock is owned by another CPU which is expected
>> to unlock it eventually. So it doesn't look like disabling all
>> NMI->kmsg_dump() is the only way to fix it.
>>
>> When we lock logbuf_lock we increment per-CPU printk_context
>> (PRINTK_SAFE_CONTEXT_MASK bits); when we unlock logbuf_lock
>> we decrement printk_context. Thus we always can tell if the
>> logbuf_lock was locked on the very same CPU - this_cpu printk_context
>> has PRINTK_SAFE_CONTEXT_MASK bits sets - and we are about to deadlock
>> in a nested context (NMI), or the lock was locked on another CPU and
>> it's "safe" to spin on logbuf_lock and wait for logbuf_lock to become
>> available.
> 
> This sounds familiar. I think that we did not consider it safe in the
> end, see the commit 03fc7f9c99c1e7ae29 ("printk/nmi: Prevent deadlock
> when accessing the main log buffer in NMI").
> 
> If the problem is only with Oops then the 2nd propose might be
> acceptable. The system will either try to continue or it will end
> up in panic() anyway.
> 
> Well, WARN() looks like an overkill, especially if there is only
> one possible caller that prints the stack anyway. I would personally
> do not print any message and do just:
> 
> 	/*
> 	 * Prevent deadlock on logbuf_lock. It is safe only
> 	 * in panic() after smp_send_stop() and resetting
> 	 * the lock.
> 	 */
> 	if (in_nmi() && reason != KMSG_DUMP_PANIC)
> 		return;
> 

WARN_ON_ONCE is useful timesaver in debugging.
It's better to know when happens something that shouldn't.

> Best Regards,
> Petr
>