On Thu 2018-05-17 16:39:03, Petr Mladek wrote:
> The commit 719f6a7040f1bdaf96fcc ("printk: Use the main logbuf in NMI when
> logbuf_lock is available") tried to detect when logbuf_lock was taken
> on another CPU. Then it looked safe to wait for the lock even in NMI.
>
> It would be safe if other locks were not involved. Ironically the same
> commit introduced an ABBA deadlock scenario. It added a spin lock into
> nmi_cpu_backtrace() to serialize logs from different CPUs. The effect
> is that also the NMI handlers are serialized. As a result, logbuf_lock
> might be blocked by NMI on another CPU:
>
> CPU0 CPU1 CPU2
>
> printk()
> vprintk_emit()
> spin_lock(&logbuf_lock)
>
> trigger_all_cpu_backtrace()
> raise()
>
> nmi_enter()
> printk_nmi_enter()
> if (this_cpu_read(printk_context)
> & PRINTK_SAFE_CONTEXT_MASK)
> // false
> else
> // looks safe to use printk_deferred()
> this_cpu_or(printk_context,
> PRINTK_NMI_DEFERRED_CONTEXT_MASK);
>
> nmi_cpu_backtrace()
> arch_spin_lock(&lock);
> show_regs()
>
> nmi_enter()
> nmi_cpu_backtrace()
> arch_spin_lock(&lock);
>
> printk()
> vprintk_func()
> vprintk_deferred()
> vprintk_emit()
> spin_lock(&logbuf_lock)
>
> DEADLOCK: between &logbuf_lock from vprintk_emit() and
> &lock from nmi_cpu_backtrace().
>
> CPU0 CPU1
> lock(logbuf_lock) lock(lock)
> lock(lock) lock(logbuf_lock)
>
> I have found this problem when stress testing trigger_all_cpu_backtrace()
> and the system frozen.
>
> Note that lockdep is not able to detect these dependencies because
> there is no support for NMI context. Let's stay on the safe side
> and always use printk_safe buffers when logbuf_lock is taken
> when entering NMI.
>
> Fixes: 719f6a7040f1bdaf96fcc ("printk: Use the main logbuf in NMI when logbuf_lock is available")
> Cc: 4.13+ <stable@xxxxxxxxxxxxxxx> # v4.13+
> Signed-off-by: Petr Mladek <pmladek@xxxxxxxx>
> ---
> kernel/printk/printk_safe.c | 9 +++------
> 1 file changed, 3 insertions(+), 6 deletions(-)
>
> diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
> index 449d67edfa4b..a2ebd749c053 100644
> --- a/kernel/printk/printk_safe.c
> +++ b/kernel/printk/printk_safe.c
> @@ -310,15 +310,12 @@ void printk_nmi_enter(void)
> {
> /*
> * The size of the extra per-CPU buffer is limited. Use it only when
> - * the main one is locked. If this CPU is not in the safe context,
> - * the lock must be taken on another CPU and we could wait for it.
> + * the main one is locked.
> */
> - if ((this_cpu_read(printk_context) & PRINTK_SAFE_CONTEXT_MASK) &&
> - raw_spin_is_locked(&logbuf_lock)) {
> + if (raw_spin_is_locked(&logbuf_lock))
> this_cpu_or(printk_context, PRINTK_NMI_CONTEXT_MASK);
Grr, the ABBA deadlock is still there. NMIs are not sent to the other
CPUs atomically. Even if we detect that logbuf_lock is available
in printk_nmi_enter() on some CPUs, it might still get locked on
another CPU before the other CPU gets NMI.
By other words, any check in printk_safe_enter() is racy and not
sufficient
=> I suggest to revert the commit 719f6a7040f1bdaf96fcc70
"printk: Use the main logbuf in NMI when logbuf_lock is available"
for-4.18 and stable until we get a better solution.
The only safe solution seems to be a trylock() in NMI in
vprintk_emit() and fallback to vprintk_safe() when the lock
is not taken. I mean something like:
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 247808333ba4..4a5a0bf221b3 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1845,7 +1845,13 @@ asmlinkage int vprintk_emit(int facility, int level,
printk_delay();
/* This stops the holder of console_sem just where we want him */
- logbuf_lock_irqsave(flags);
+ printk_safe_enter_irqsave(flags);
+ if (in_nmi() && !raw_spin_trylock(&logbuf_lock)) {
+ vprintk_nmi(fmt, args);
+ printk_safe_exit_irqrestore(flags);
+ return;
+ } else
+ raw_spin_lock(&logbuf_lock);
/*
* The printf needs to come first; we need the syslog
* prefix which might be passed-in as a parameter.
Sigh, this looks like a material for-4.19. We might need to
revisit if printk_context still makes sense, ...
Best Regards,
Petr
PS: I realized this when writing the pull request for-4.18.
I removed this patch from the pull request.
