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

[PATCH] 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(), 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 | 29 ++++++++++++++++++++---------
 1 file changed, 20 insertions(+), 9 deletions(-)

diff --git a/kernel/printk/nmi.c b/kernel/printk/nmi.c
index b69eb8a..5f2c198 100644
--- a/kernel/printk/nmi.c
+++ b/kernel/printk/nmi.c
@@ -103,23 +103,32 @@ again:
  * 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 __print_nmi_seq_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 print_nmi_seq_line(struct nmi_seq_buf *s, int start, int end)
+{
+	const char *buf = s->buffer + start;
+
+	__print_nmi_seq_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 +159,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";
+
+		__print_nmi_seq_line(msg, strlen(msg));
+	}
 
 	if (!len)
 		goto out; /* Someone else has already flushed the buffer. */
@@ -173,7 +184,7 @@ more:
 	/* Check if there was a partial line. */
 	if (last_i < size) {
 		print_nmi_seq_line(s, last_i, size - 1);
-		pr_cont("\n");
+		__print_nmi_seq_line("\n", strlen("\n"));
 	}
 
 	/*
-- 
2.9.3

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

[Petr Mladek]

On Mon 2016-08-29 21:32:20, Sergey Senozhatsky wrote:
> 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(), which takes care of in_nmi(), and use
> it in __printk_nmi_flush() for printing and error-reporting.

Great catch! The check and eventually printk_deferred() need to be used
everywhere in __printk_nmi_flush().

Just some nitpicks below.

> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/nmi.c | 29 ++++++++++++++++++++---------
>  1 file changed, 20 insertions(+), 9 deletions(-)
> 
> diff --git a/kernel/printk/nmi.c b/kernel/printk/nmi.c
> index b69eb8a..5f2c198 100644
> --- a/kernel/printk/nmi.c
> +++ b/kernel/printk/nmi.c
> @@ -103,23 +103,32 @@ again:
>   * printk one line from the temporary buffer from @start index until
>   * and including the @end index.
>   */

The comment above is not longer valid.

> -static void print_nmi_seq_line(struct nmi_seq_buf *s, int start, int end)
> +static void __print_nmi_seq_line(const char *text, int len)

Also the name of the function might be confusing because it is not
longer used only for the seq buffer. I would rename it to
something like:

       printk_nmi_flush_line()

>  {
> -	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 print_nmi_seq_line(struct nmi_seq_buf *s, int start, int end)
> +{

Then I would rename also this function to something like:

     printk_nmi_flush_seq_line()

> +	const char *buf = s->buffer + start;
> +
> +	__print_nmi_seq_line(buf, (end - start) + 1);
> +}
> +

Othrewise, it looks fine. With the above suggested changes, feel
free to add:

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

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

[Sergey Senozhatsky]

On (08/29/16 17:16), Petr Mladek wrote:
[..]
> The comment above is not longer valid.

oh, yes. it shouldn't even be there.

> > -static void print_nmi_seq_line(struct nmi_seq_buf *s, int start, int end)
> > +static void __print_nmi_seq_line(const char *text, int len)
> 
> Also the name of the function might be confusing because it is not
> longer used only for the seq buffer. I would rename it to
> something like:
> 
>        printk_nmi_flush_line()

sounds good.

> > +static void print_nmi_seq_line(struct nmi_seq_buf *s, int start, int end)
> > +{
> 
> Then I would rename also this function to something like:
> 
>      printk_nmi_flush_seq_line()

sounds good.

> > +	const char *buf = s->buffer + start;
> > +
> > +	__print_nmi_seq_line(buf, (end - start) + 1);
> > +}
> > +
> 
> Othrewise, it looks fine. With the above suggested changes, feel
> free to add:
> 
> Reviewed-by: Petr Mladek <pmladek@suse.com>

thanks, will re-spin today.

	-ss

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

[Sergey Senozhatsky]

Petr,
one more question. Not related to the patch, but still related to NMI.

can NMI nest?


	CPU0

->	NMI#0
		printk_nmi_enter()
			this_cpu_write(printk_func, vprintk_nmi)
		...
=>		NMI#1
		:	printk_nmi_enter()
		:		this_cpu_write(printk_func, vprintk_nmi)
		:	this_cpu_read(printk_func)(fmt, args)
		:	^^^^^^^^^^^^^ OK, vprintk_nmi() from NMI
		:	printk_nmi_exit()
		:		this_cpu_write(printk_func, vprintk_default) <<
		return NMI#1

		this_cpu_read(printk_func)(fmt, args)
		^^^^^^^^^^^^^ vprintk_default() from NMI?
		printk_nmi_exit()
			this_cpu_write(printk_func, vprintk_default)
	return NMI#0

can this happen?
shouldn't we do something like this then? /* not tested */

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

---
 kernel/printk/internal.h | 2 ++
 kernel/printk/nmi.c      | 9 ++++++++-
 2 files changed, 10 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 7fd2838..5b7508f 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -31,6 +31,8 @@ extern raw_spinlock_t logbuf_lock;
  * via per-CPU variable.
  */
 DECLARE_PER_CPU(printk_func_t, printk_func);
+DECLARE_PER_CPU(printk_func_t, printk_func_saved);
+
 static inline __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
 {
 	return this_cpu_read(printk_func)(fmt, args);
diff --git a/kernel/printk/nmi.c b/kernel/printk/nmi.c
index 16bab47..9d83929 100644
--- a/kernel/printk/nmi.c
+++ b/kernel/printk/nmi.c
@@ -39,6 +39,7 @@
  * were handled or when IRQs are blocked.
  */
 DEFINE_PER_CPU(printk_func_t, printk_func) = vprintk_default;
+DEFINE_PER_CPU(printk_func_t, printk_func_saved);
 static int printk_nmi_irq_ready;
 atomic_t nmi_message_lost;
 
@@ -259,10 +260,16 @@ void __init printk_nmi_init(void)
 
 void printk_nmi_enter(void)
 {
+	printk_func_t func = this_cpu_read(printk_func);
+
+	if (func != vprintk_nmi)
+		this_cpu_write(printk_func_saved, func);
 	this_cpu_write(printk_func, vprintk_nmi);
 }
 
 void printk_nmi_exit(void)
 {
-	this_cpu_write(printk_func, vprintk_default);
+	printk_func_t func = this_cpu_read(printk_func_saved);
+
+	this_cpu_write(printk_func, func);
 }
-- 
2.9.3

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

[Petr Mladek]

On Tue 2016-08-30 16:58:34, Sergey Senozhatsky wrote:
> Petr,
> one more question. Not related to the patch, but still related to NMI.
> 
> can NMI nest?

AFAIK, they cannot. NMIs should be disabled until iret is called.
Therefore we should be on the safe side if iret is not called
inside the NMI handler. But this should not happen because
it would cause other problems, like using wrong return address.

Well, x86 nmi code has some hacks to handle exceptions inside
NMI handlers that use iret. But printk_nmi_enter()/printk_nmi_exit()
are never nested there. It is prevented by the nmi_state per-CPU
variable. See do_nmi() in arch/x86/kernel/nmi.c.


> shouldn't we do something like this then? /* not tested */
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> 
> ---
>  kernel/printk/internal.h | 2 ++
>  kernel/printk/nmi.c      | 9 ++++++++-
>  2 files changed, 10 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
> index 7fd2838..5b7508f 100644
> --- a/kernel/printk/internal.h
> +++ b/kernel/printk/internal.h
> @@ -31,6 +31,8 @@ extern raw_spinlock_t logbuf_lock;
>   * via per-CPU variable.
>   */
>  DECLARE_PER_CPU(printk_func_t, printk_func);
> +DECLARE_PER_CPU(printk_func_t, printk_func_saved);
> +
>  static inline __printf(1, 0) int vprintk_func(const char *fmt, va_list args)
>  {
>  	return this_cpu_read(printk_func)(fmt, args);
> diff --git a/kernel/printk/nmi.c b/kernel/printk/nmi.c
> index 16bab47..9d83929 100644
> --- a/kernel/printk/nmi.c
> +++ b/kernel/printk/nmi.c
> @@ -39,6 +39,7 @@
>   * were handled or when IRQs are blocked.
>   */
>  DEFINE_PER_CPU(printk_func_t, printk_func) = vprintk_default;
> +DEFINE_PER_CPU(printk_func_t, printk_func_saved);
>  static int printk_nmi_irq_ready;
>  atomic_t nmi_message_lost;
>  
> @@ -259,10 +260,16 @@ void __init printk_nmi_init(void)
>  
>  void printk_nmi_enter(void)
>  {
> +	printk_func_t func = this_cpu_read(printk_func);
> +
> +	if (func != vprintk_nmi)
> +		this_cpu_write(printk_func_saved, func);
>  	this_cpu_write(printk_func, vprintk_nmi);
>  }
>  
>  void printk_nmi_exit(void)
>  {
> -	this_cpu_write(printk_func, vprintk_default);
> +	printk_func_t func = this_cpu_read(printk_func_saved);
> +
> +	this_cpu_write(printk_func, func);

This would handle only one level of nesting. If nesting was possible
we would probably need something else. Fortunately, I believe that we
do not need this.

Thanks for checking the code.

Best Regards,
Petr

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

[Sergey Senozhatsky]

On (08/30/16 11:04), Petr Mladek wrote:
> On Tue 2016-08-30 16:58:34, Sergey Senozhatsky wrote:
> > Petr,
> > one more question. Not related to the patch, but still related to NMI.
> > 
> > can NMI nest?
> 
> AFAIK, they cannot. NMIs should be disabled until iret is called.
> Therefore we should be on the safe side if iret is not called
> inside the NMI handler. But this should not happen because
> it would cause other problems, like using wrong return address.
> 
> Well, x86 nmi code has some hacks to handle exceptions inside
> NMI handlers that use iret. But printk_nmi_enter()/printk_nmi_exit()
> are never nested there. It is prevented by the nmi_state per-CPU
> variable. See do_nmi() in arch/x86/kernel/nmi.c.

yes, x86 has a per-cpu nmi_state to handle the case when NMI is
loosing its NMI context. But other arch-s, as far as I can see,
don't do that. Does it mean that we are safe only on x86?

this printk_func_saved thing is still will be needed, I think,
for alt_printk.

Example:

process abc
	printk()
		alt_printk_enter()
			this_cpu_write(printk_func, vprintk_alt);
->	NMI
	:	printk_nmi_enter()
	:		this_cpu_write(printk_func, vprintk_nmi);
	:	printk_nmi_exit()
	:		this_cpu_write(printk_func, vprintk_default);
	return NMI

		printk()  <<<<  nested printk -> vprintk_default(), set by nmi_exit()
		alt_printk_exit()
	...

	-ss

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

[Petr Mladek]

On Tue 2016-08-30 18:39:18, Sergey Senozhatsky wrote:
> On (08/30/16 11:04), Petr Mladek wrote:
> > On Tue 2016-08-30 16:58:34, Sergey Senozhatsky wrote:
> > > Petr,
> > > one more question. Not related to the patch, but still related to NMI.
> > > 
> > > can NMI nest?
> > 
> > AFAIK, they cannot. NMIs should be disabled until iret is called.
> > Therefore we should be on the safe side if iret is not called
> > inside the NMI handler. But this should not happen because
> > it would cause other problems, like using wrong return address.
> > 
> > Well, x86 nmi code has some hacks to handle exceptions inside
> > NMI handlers that use iret. But printk_nmi_enter()/printk_nmi_exit()
> > are never nested there. It is prevented by the nmi_state per-CPU
> > variable. See do_nmi() in arch/x86/kernel/nmi.c.
> 
> yes, x86 has a per-cpu nmi_state to handle the case when NMI is
> loosing its NMI context. But other arch-s, as far as I can see,
> don't do that. Does it mean that we are safe only on x86?

My understanding is that the kernel would crash on the other
architectures if a double iret was called. By other words,
they would have bigger problems than the nmi_enter()/nmi_exit()
calls. So, we should be on the safe side.

> this printk_func_saved thing is still will be needed, I think,
> for alt_printk.
> 
> Example:
> 
> process abc
> 	printk()
> 		alt_printk_enter()
> 			this_cpu_write(printk_func, vprintk_alt);
> ->	NMI
> 	:	printk_nmi_enter()
> 	:		this_cpu_write(printk_func, vprintk_nmi);
> 	:	printk_nmi_exit()
> 	:		this_cpu_write(printk_func, vprintk_default);
> 	return NMI
> 
> 		printk()  <<<<  nested printk -> vprintk_default(), set by nmi_exit()
> 		alt_printk_exit()
> 	...

I see. But then we will need to be more careful because printk_func
and printk_func_saved will be manipulated in different contexts:
normal, irq, nmi. A solution might be using an atomic counter
and selecting the right vprintk_func according to the value.

Well, I am still afraid that yet another alt_printk is not
the way to go.

Best Regards,
Petr

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

[Sergey Senozhatsky]

On (08/30/16 13:19), Petr Mladek wrote:
[..]
> > yes, x86 has a per-cpu nmi_state to handle the case when NMI is
> > loosing its NMI context. But other arch-s, as far as I can see,
> > don't do that. Does it mean that we are safe only on x86?
> 
> My understanding is that the kernel would crash on the other
> architectures if a double iret was called. By other words,
> they would have bigger problems than the nmi_enter()/nmi_exit()
> calls. So, we should be on the safe side.
> 
> > this printk_func_saved thing is still will be needed, I think,
> > for alt_printk.
> > 
> > Example:
> > 
> > process abc
> > 	printk()
> > 		alt_printk_enter()
> > 			this_cpu_write(printk_func, vprintk_alt);
> > ->	NMI
> > 	:	printk_nmi_enter()
> > 	:		this_cpu_write(printk_func, vprintk_nmi);
> > 	:	printk_nmi_exit()
> > 	:		this_cpu_write(printk_func, vprintk_default);
> > 	return NMI
> > 
> > 		printk()  <<<<  nested printk -> vprintk_default(), set by nmi_exit()
> > 		alt_printk_exit()
> > 	...
> 
> I see. But then we will need to be more careful because printk_func
> and printk_func_saved will be manipulated in different contexts:
> normal, irq, nmi. A solution might be using an atomic counter
> and selecting the right vprintk_func according to the value.

yes, I thought about something like this.
... or we can use the one and only 'nmi_seq' buffer and share it between
NMI and alt_printk, adding a special prefix to every message

	if (in_nmi())
		sprintf("NMI:%s", message)
	else
		sprintf("%s", message)

so, yes, it can get hairy, but at least it will be grep-able, still
better than nothing.

> Well, I am still afraid that yet another alt_printk is not
> the way to go.

well, it might be and it might be not.

	-ss

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

[Sergey Senozhatsky]

On (08/30/16 13:19), Petr Mladek wrote:
> 
> I see. But then we will need to be more careful because printk_func
> and printk_func_saved will be manipulated in different contexts:
> normal, irq, nmi. A solution might be using an atomic counter
> and selecting the right vprintk_func according to the value.

alt_printk_enter() must be done with local IRQs disabled. so IRQ cannot
race with `normal' alt_printk. other IRQs cannot race with the current IRQ,
because we have local IRQs disabled. the only thing that can race here is - NMI.
both `normal' and IRQ alt_printk can use the same per-CPU buffer, they never
race. NMI needs to have its own.

	-ss

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

[Petr Mladek]

On Thu 2016-09-01 16:55:07, Sergey Senozhatsky wrote:
> On (08/30/16 13:19), Petr Mladek wrote:
> > 
> > I see. But then we will need to be more careful because printk_func
> > and printk_func_saved will be manipulated in different contexts:
> > normal, irq, nmi. A solution might be using an atomic counter
> > and selecting the right vprintk_func according to the value.
> 
> alt_printk_enter() must be done with local IRQs disabled. so IRQ cannot
> race with `normal' alt_printk. other IRQs cannot race with the current IRQ,
> because we have local IRQs disabled. the only thing that can race here is - NMI.
> both `normal' and IRQ alt_printk can use the same per-CPU buffer, they never
> race. NMI needs to have its own.

Yes. Well, my concern was how to atomically change the printk_func
pointer and save the previous value at the same time. You could not
use locks because NMIs are involved.

Best Regards,
Petr