[PATCH] printk: CON_PRINTBUFFER console registration is a bit racy

[PATCH] printk: CON_PRINTBUFFER console registration is a bit racy

[Sergey Senozhatsky]

CON_PRINTBUFFER console registration requires us to do several
preparation steps:
- Rollback console_seq to replay logbuf messages which were already
  seen on other consoles;
- Set exclusive_console flag so console_unlock() will ->write() logbuf
  messages only to the exclusive_console driver.

The way we do it, however, is a bit racy

	logbuf_lock_irqsave(flags);
	console_seq = syslog_seq;
	console_idx = syslog_idx;
	logbuf_unlock_irqrestore(flags);
						<< preemption enabled
						<< irqs enabled
	exclusive_console = newcon;
	console_unlock();

We rollback console_seq under logbuf_lock with IRQs disabled, but
we set exclusive_console with local IRQs enabled and logbuf unlocked.
If the system oops-es or panic-s before we set exclusive_console - and
given that we have IRQs and preemption enabled there is such a
possibility - we will re-play all logbuf messages to every registered
console, which may be a bit annoying and time consuming.

Move exclusive_console assignment under the same IRQs-disabled and
logbuf_lock protected section where we rollback console_seq.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 992bb6bb7ac2..c52a986a72b3 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2705,7 +2705,6 @@ void register_console(struct console *newcon)
 		logbuf_lock_irqsave(flags);
 		console_seq = syslog_seq;
 		console_idx = syslog_idx;
-		logbuf_unlock_irqrestore(flags);
 		/*
 		 * We're about to replay the log buffer.  Only do this to the
 		 * just-registered console to avoid excessive message spam to
@@ -2713,6 +2712,7 @@ void register_console(struct console *newcon)
 		 */
 		exclusive_console = newcon;
 		exclusive_console_stop_seq = console_seq;
+		logbuf_unlock_irqrestore(flags);
 	}
 	console_unlock();
 	console_sysfs_notify();
-- 
2.19.0

Re: [PATCH] printk: CON_PRINTBUFFER console registration is a bit racy

[Petr Mladek]

On Fri 2018-09-14 11:34:28, Sergey Senozhatsky wrote:
> CON_PRINTBUFFER console registration requires us to do several
> preparation steps:
> - Rollback console_seq to replay logbuf messages which were already
>   seen on other consoles;
> - Set exclusive_console flag so console_unlock() will ->write() logbuf
>   messages only to the exclusive_console driver.
> 
> The way we do it, however, is a bit racy
> 
> 	logbuf_lock_irqsave(flags);
> 	console_seq = syslog_seq;
> 	console_idx = syslog_idx;
> 	logbuf_unlock_irqrestore(flags);
> 						<< preemption enabled
> 						<< irqs enabled
> 	exclusive_console = newcon;
> 	console_unlock();
> 
> We rollback console_seq under logbuf_lock with IRQs disabled, but
> we set exclusive_console with local IRQs enabled and logbuf unlocked.
> If the system oops-es or panic-s before we set exclusive_console - and
> given that we have IRQs and preemption enabled there is such a
> possibility - we will re-play all logbuf messages to every registered
> console, which may be a bit annoying and time consuming.
>
> Move exclusive_console assignment under the same IRQs-disabled and
> logbuf_lock protected section where we rollback console_seq.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/printk.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 992bb6bb7ac2..c52a986a72b3 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2705,7 +2705,6 @@ void register_console(struct console *newcon)
>  		logbuf_lock_irqsave(flags);
>  		console_seq = syslog_seq;
>  		console_idx = syslog_idx;
> -		logbuf_unlock_irqrestore(flags);
>  		/*
>  		 * We're about to replay the log buffer.  Only do this to the
>  		 * just-registered console to avoid excessive message spam to
> @@ -2713,6 +2712,7 @@ void register_console(struct console *newcon)
>  		 */
>  		exclusive_console = newcon;
>  		exclusive_console_stop_seq = console_seq;
> +		logbuf_unlock_irqrestore(flags);

This would make a false feeling that these variables need to
be synchronized using logbug_lock. It might either confuse people
or it could get removed during a code clean up.

A better solution would be to explicitly disable preemption
around the entire section and add a comment.

Well, I am not sure if it is worth the code complexity.

Best Regards,
Petr

Re: [PATCH] printk: CON_PRINTBUFFER console registration is a bit racy

[Sergey Senozhatsky]

On (09/14/18 10:59), Petr Mladek wrote:
> 
> Well, I am not sure if it is worth the code complexity.
>

Well, I don't think we need to bother that much here. Besides,
exclusive_console is cleared under logbuf_lock with preemption
disabled now. So we set it under logbuf_lock and !irq and we
clear it under logbuf_lock and !irq. Looks quite OK to me.

	-ss

Re: [PATCH] printk: CON_PRINTBUFFER console registration is a bit racy

[Sergey Senozhatsky]

On (09/14/18 20:19), Sergey Senozhatsky wrote:
> On (09/14/18 10:59), Petr Mladek wrote:
> > 
> > Well, I am not sure if it is worth the code complexity.
> >
> 
> Well, I don't think we need to bother that much here. Besides,
> exclusive_console is cleared under logbuf_lock with preemption
> disabled now. So we set it under logbuf_lock and !irq and we
> clear it under logbuf_lock and !irq. Looks quite OK to me.

Petr, Steven,
any opinions? The patch is rather trivial.

	-ss

Re: [PATCH] printk: CON_PRINTBUFFER console registration is a bit racy

[Petr Mladek]

On Fri 2018-09-14 20:19:53, Sergey Senozhatsky wrote:
> On (09/14/18 10:59), Petr Mladek wrote:
> > 
> > Well, I am not sure if it is worth the code complexity.
> >
> 
> Well, I don't think we need to bother that much here. Besides,
> exclusive_console is cleared under logbuf_lock with preemption
> disabled now. So we set it under logbuf_lock and !irq and we
> clear it under logbuf_lock and !irq. Looks quite OK to me.

I wanted to say that you moved exclusive_console handling under
a locked section from a reason. This reason is far from clear
from the code.

If you really want this change, please add a comment, for example:

/*
 * Set exclusive_console still with disabled interrupts to
 * reduce race window with eventual console_flush_on_panic()
 * that ignores console_lock.
 */

I am not against the change. It makes some sense and it does
not break anything. It is just not obvious and might either
get easily lost again or it might cause confusion. I mean that
it might cause false feeling that exclusive_console is
synchronized by logbuf_lock.

printk code already is complex enough without this subtle
tricks.

Best Regards,
Petr

Re: [PATCH] printk: CON_PRINTBUFFER console registration is a bit racy

[Steven Rostedt]

On Wed, 26 Sep 2018 13:37:15 +0200
Petr Mladek <pmladek@suse.com> wrote:

> If you really want this change, please add a comment, for example:
> 
> /*
>  * Set exclusive_console still with disabled interrupts to
>  * reduce race window with eventual console_flush_on_panic()
>  * that ignores console_lock.
>  */
> 
> I am not against the change. It makes some sense and it does
> not break anything. It is just not obvious and might either
> get easily lost again or it might cause confusion. I mean that
> it might cause false feeling that exclusive_console is
> synchronized by logbuf_lock.
> 
> printk code already is complex enough without this subtle
> tricks.

I'm fine with the change and agree that a comment should be added.

-- Steve

Re: [PATCH] printk: CON_PRINTBUFFER console registration is a bit racy

[Sergey Senozhatsky]

On (09/26/18 13:37), Petr Mladek wrote:
> /*
>  * Set exclusive_console still with disabled interrupts to
>  * reduce race window with eventual console_flush_on_panic()
>  * that ignores console_lock.
>  */

Looks good to me.

> I am not against the change. It makes some sense and it does
> not break anything. It is just not obvious

OK. Thanks.
Will send v2.

	-ss