[PATCH v2] printk/nmi: avoid direct printk()-s from __printk_nmi_flush()

[PATCH v2] printk/nmi: avoid direct printk()-s from __printk_nmi_flush()

[Sergey Senozhatsky]

From: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>

__printk_nmi_flush() can be called from nmi_panic(), therefore it has to
test whether it's executed in NMI context and thus must route the messages
through deferred printk() or via direct printk(). Except for two places
where __printk_nmi_flush() does unconditional direct printk() calls:
 - pr_err("printk_nmi_flush: internal error ...")
 - pr_cont("\n")

Factor out print_nmi_seq_line() parts into a new printk_nmi_flush_line()
function, which takes care of in_nmi(), and use it in __printk_nmi_flush()
for printing and error-reporting.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/nmi.c | 38 +++++++++++++++++++++++---------------
 1 file changed, 23 insertions(+), 15 deletions(-)

diff --git a/kernel/printk/nmi.c b/kernel/printk/nmi.c
index b69eb8a..16bab47 100644
--- a/kernel/printk/nmi.c
+++ b/kernel/printk/nmi.c
@@ -99,27 +99,33 @@ again:
 	return add;
 }
 
-/*
- * printk one line from the temporary buffer from @start index until
- * and including the @end index.
- */
-static void print_nmi_seq_line(struct nmi_seq_buf *s, int start, int end)
+static void printk_nmi_flush_line(const char *text, int len)
 {
-	const char *buf = s->buffer + start;
-
 	/*
 	 * The buffers are flushed in NMI only on panic.  The messages must
 	 * go only into the ring buffer at this stage.  Consoles will get
 	 * explicitly called later when a crashdump is not generated.
 	 */
 	if (in_nmi())
-		printk_deferred("%.*s", (end - start) + 1, buf);
+		printk_deferred("%.*s", len, text);
 	else
-		printk("%.*s", (end - start) + 1, buf);
+		printk("%.*s", len, text);
 
 }
 
 /*
+ * printk one line from the temporary buffer from @start index until
+ * and including the @end index.
+ */
+static void printk_nmi_flush_seq_line(struct nmi_seq_buf *s,
+					int start, int end)
+{
+	const char *buf = s->buffer + start;
+
+	printk_nmi_flush_line(buf, (end - start) + 1);
+}
+
+/*
  * Flush data from the associated per_CPU buffer. The function
  * can be called either via IRQ work or independently.
  */
@@ -150,9 +156,11 @@ more:
 	 * the buffer an unexpected way. If we printed something then
 	 * @len must only increase.
 	 */
-	if (i && i >= len)
-		pr_err("printk_nmi_flush: internal error: i=%d >= len=%zu\n",
-		       i, len);
+	if (i && i >= len) {
+		const char *msg = "printk_nmi_flush: internal error\n";
+
+		printk_nmi_flush_line(msg, strlen(msg));
+	}
 
 	if (!len)
 		goto out; /* Someone else has already flushed the buffer. */
@@ -166,14 +174,14 @@ more:
 	/* Print line by line. */
 	for (; i < size; i++) {
 		if (s->buffer[i] == '\n') {
-			print_nmi_seq_line(s, last_i, i);
+			printk_nmi_flush_seq_line(s, last_i, i);
 			last_i = i + 1;
 		}
 	}
 	/* Check if there was a partial line. */
 	if (last_i < size) {
-		print_nmi_seq_line(s, last_i, size - 1);
-		pr_cont("\n");
+		printk_nmi_flush_seq_line(s, last_i, size - 1);
+		printk_nmi_flush_line("\n", strlen("\n"));
 	}
 
 	/*
-- 
2.9.3

Re: [PATCH v2] printk/nmi: avoid direct printk()-s from __printk_nmi_flush()

[Andrew Morton]

On Wed, 31 Aug 2016 01:13:54 +0900 Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:

> __printk_nmi_flush() can be called from nmi_panic(), therefore it has to
> test whether it's executed in NMI context and thus must route the messages
> through deferred printk() or via direct printk().

Why?  What misbehaviour does the current code cause?

> Except for two places
> where __printk_nmi_flush() does unconditional direct printk() calls:
>  - pr_err("printk_nmi_flush: internal error ...")
>  - pr_cont("\n")
> 
> Factor out print_nmi_seq_line() parts into a new printk_nmi_flush_line()
> function, which takes care of in_nmi(), and use it in __printk_nmi_flush()
> for printing and error-reporting.

Re: [PATCH v2] printk/nmi: avoid direct printk()-s from __printk_nmi_flush()

[Sergey Senozhatsky]

Hello,

On (08/30/16 15:03), Andrew Morton wrote:
> > __printk_nmi_flush() can be called from nmi_panic(), therefore it has to
> > test whether it's executed in NMI context and thus must route the messages
> > through deferred printk() or via direct printk().
> 
> Why?  What misbehaviour does the current code cause?

the reasoning behind the `if in_nmi()' in print_nmi_seq_line()

       if (in_nmi())
               printk_deferred("%.*s", (end - start) + 1, buf);
       else
               printk("%.*s", (end - start) + 1, buf);

was as follows (per Petr's commit message)

:    In NMI context, printk() messages are stored into per-CPU buffers to
:    avoid a possible deadlock.  They are normally flushed to the main ring
:    buffer via an IRQ work.  But the work is never called when the system
:    calls panic() in the very same NMI handler.
:
:    This patch tries to flush NMI buffers before the crash dump is
:    generated.  In this case it does not risk a double release and bails out
:    when the logbuf_lock is already taken.  The aim is to get the messages
:    into the main ring buffer when possible.  It makes them better
:    accessible in the vmcore.
:
:    Then the patch tries to flush the buffers second time when other CPUs
:    are down.  It might be more aggressive and reset logbuf_lock.  The aim
:    is to get the messages available for the consequent kmsg_dump() and
:    console_flush_on_panic() calls.
:
:    The patch causes vprintk_emit() to be called even in NMI context again.
:    But it is done via printk_deferred() so that the console handling is
:    skipped.  Consoles use internal locks and we could not prevent a
:    deadlock easily.  They are explicitly called later when the crash dump
:    is not generated, see console_flush_on_panic().

doing pr_err() and pr_cont() defeats the purpose of print_nmi_seq_line(),
because in the worst case it can do something like this:

  vprintk_emit()
   /* console_trylock() */
   console_unlock()
    call_console_drivers()
     foo_write()   // possibly locked


the tricky moment here is -- if the console semaphore is unlocked and
NMI can successfully console_trylock(), then how any of underlying serial
console driver's locks can be taken? one possibility is:

	CPU0

SyS_ioctl
 do_vfs_ioctl
  tty_ioctl
   n_tty_ioctl
    tty_mode_ioctl
     set_termios
      tty_set_termios
       uart_set_termios
        uart_change_speed
         FOO_serial_set_termios
          spin_lock_irqsave(&port->lock)     // lock the output port
           ...
--> NMI
       nmi_panic()
        printk_nmi_flush_on_panic()
         __printk_nmi_flush()
          pr_cont()
           /* console_trylock() */
           console_unlock()
            call_console_drivers()
             foo_write()
              spin_lock_irqsave(&port->lock)  // already locked


as far as I can see, tty_ioctl() path does not lock console semaphore,
but grabs some tty locks instead.

	-ss

Re: [PATCH v2] printk/nmi: avoid direct printk()-s from __printk_nmi_flush()

[Andrew Morton]

On Wed, 31 Aug 2016 10:44:41 +0900 Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

> On (08/30/16 15:03), Andrew Morton wrote:
> > > __printk_nmi_flush() can be called from nmi_panic(), therefore it has to
> > > test whether it's executed in NMI context and thus must route the messages
> > > through deferred printk() or via direct printk().
> > 
> > Why?  What misbehaviour does the current code cause?
> 
> the reasoning behind the `if in_nmi()' in print_nmi_seq_line()
> 
>        if (in_nmi())
>                printk_deferred("%.*s", (end - start) + 1, buf);
>        else
>                printk("%.*s", (end - start) + 1, buf);
> 
> was as follows (per Petr's commit message)

OK, thanks, I altered the changelog thusly and scheduled the patch for 4.8:

--- txt/printk-nmi-avoid-direct-printk-s-from-__printk_nmi_flush.txt
+++ txt/printk-nmi-avoid-direct-printk-s-from-__printk_nmi_flush.txt
@@ -3,8 +3,13 @@
 
 __printk_nmi_flush() can be called from nmi_panic(), therefore it has to
 test whether it's executed in NMI context and thus must route the messages
-through deferred printk() or via direct printk(). Except for two places
-where __printk_nmi_flush() does unconditional direct printk() calls:
+through deferred printk() or via direct printk().  This is to avoid
+potential deadlocks, as described in cf9b1106c81c45cde ("printk/nmi: flush
+NMI messages on the system panic").
+
+However there remain two places where __printk_nmi_flush() does
+unconditional direct printk() calls:
+
  - pr_err("printk_nmi_flush: internal error ...")
  - pr_cont("\n")
 

Re: [PATCH v2] printk/nmi: avoid direct printk()-s from __printk_nmi_flush()

[Sergey Senozhatsky]

On (08/31/16 13:15), Andrew Morton wrote:
> > On (08/30/16 15:03), Andrew Morton wrote:
> > > > __printk_nmi_flush() can be called from nmi_panic(), therefore it has to
> > > > test whether it's executed in NMI context and thus must route the messages
> > > > through deferred printk() or via direct printk().
> > > 
> > > Why?  What misbehaviour does the current code cause?
> > 
> > the reasoning behind the `if in_nmi()' in print_nmi_seq_line()
> > 
> >        if (in_nmi())
> >                printk_deferred("%.*s", (end - start) + 1, buf);
> >        else
> >                printk("%.*s", (end - start) + 1, buf);
> > 
> > was as follows (per Petr's commit message)
> 
> OK, thanks, I altered the changelog thusly and scheduled the patch for 4.8:

thanks!

	-ss

> 
> --- txt/printk-nmi-avoid-direct-printk-s-from-__printk_nmi_flush.txt
> +++ txt/printk-nmi-avoid-direct-printk-s-from-__printk_nmi_flush.txt
> @@ -3,8 +3,13 @@
>  
>  __printk_nmi_flush() can be called from nmi_panic(), therefore it has to
>  test whether it's executed in NMI context and thus must route the messages
> -through deferred printk() or via direct printk(). Except for two places
> -where __printk_nmi_flush() does unconditional direct printk() calls:
> +through deferred printk() or via direct printk().  This is to avoid
> +potential deadlocks, as described in cf9b1106c81c45cde ("printk/nmi: flush
> +NMI messages on the system panic").
> +
> +However there remain two places where __printk_nmi_flush() does
> +unconditional direct printk() calls:
> +
>   - pr_err("printk_nmi_flush: internal error ...")
>   - pr_cont("\n")
>  
>