Re: [PATCH] printk/console: Check consistent sequence number when handling race in console_unlock()

From: Petr Mladek
Date: Wed Jun 30 2021 - 03:58:15 EST


On Wed 2021-06-30 00:42:13, Sergey Senozhatsky wrote:
> On (21/06/29 16:33), Petr Mladek wrote:
> > The standard printk() tries to flush the message to the console
> > immediately. It tries to take the console lock. If the lock is
> > already taken then the current owner is responsible for flushing
> > even the new message.
> >
> > There is a small race window between checking whether a new message is
> > available and releasing the console lock. It is solved by re-checking
> > the state after releasing the console lock. If the check is positive
> > then console_unlock() tries to take the lock again and process the new
> > message as well.
> [..]
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index 142a58d124d9..87411084075e 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -2545,6 +2545,7 @@ void console_unlock(void)
> > bool do_cond_resched, retry;
> > struct printk_info info;
> > struct printk_record r;
> > + u64 next_seq;
> >
> > if (console_suspended) {
> > up_console_sem();
> > @@ -2654,8 +2655,10 @@ void console_unlock(void)
> > cond_resched();
> > }
> >
> > - console_locked = 0;
> > + /* Get consistent value of the next-to-be-used sequence number. */
> > + next_seq = console_seq;
> >
> > + console_locked = 0;
> > up_console_sem();
> >
> > /*
> > @@ -2664,7 +2667,7 @@ void console_unlock(void)
> > * there's a new owner and the console_unlock() from them will do the
> > * flush, no worries.
> > */
> > - retry = prb_read_valid(prb, console_seq, NULL);
> > + retry = prb_read_valid(prb, next_seq, NULL);
> > printk_safe_exit_irqrestore(flags);
> >
> > if (retry && console_trylock())
>
> Maybe it's too late here in my time zone, but what are the consequences
> of this race?
>
> `retry` can be falsely set, console_trylock() does not spin on owner,
> so the context that just released the lock can grab it again only if
> it's unlocked. For the context that just has released the console_sem
> and then acquired it again, because of the race, - console_seq will be
> valid after it acquires the lock, then it'll jump to `retry` and
> re-validated the console_seq - prb_read_valid(). If it's valid, it'll
> print the message; and should another CPU printk that CPU will spin on
> owner and then the current console_sem owner will yield to it via
> console_lock_spinning branch.

I am not sure that I follow it correctly. IMHO, there are two possible
races. I believe that you are talking about the 2nd scenario:

1st scenario: console_unlock() retries but the message has been proceed
in the meantime:

CPU0 CPU1

console_unlock()

// process all pending messages
next_seq = 100;
up_console_sem();

printk()
vprintk_store()
// storing message with seq = 100;

console_trylock_spinning()
//succees
console_unlock()
// show message with seq == 100
console_seq++; (101)

next_seq = 101;
up_consle_sem()

retry = prb_read_valid(prb, next_seq, NULL);
// true because next_seq == 100
goto retry;

if (!prb_read_valid(prb, console_seq, &r))
break;
// breaks because console_seq == 101

Result: CPU0 retired just to realize that the message
has already been procceed.


2nd scenario: printk() caller spins when other process is already
processing it's message


CPU0 CPU1

printk()
vprintk_store()
// storing message with seq == 100

console_trylock_spinning()
// succees
console_unlock()
// show message with seq == 100
console_seq++; (=> 101)

next_seq = 101;
up_console_sem();

printk()
vprintk_store()
// storing message with seq == 101

retry = prb_read_valid(prb, next_seq, NULL);
// true because next_seq == 101
goto retry

if (!prb_read_valid(prb, console_seq, &r))
// read messages with seq == 101

console_seq++; (=> 102)

console_lock_spinning_enable();
call_console_drivers();

console_trylock_spinning()
// spinning

if (console_lock_spinning_disable_and_check())
return;

// returns because there is a waiter

// got the console lock
console_unlock()
if (!prb_read_valid(prb, console_seq, &r))
break;
// breaks because console_seq == 102


Result: CPU1 was spinning just to realize that the message has already
been proceed.


It is not ideal. But the result is always correct.

The races have been there already before. Only the race window in 1st
scenario was a bit smaller.

Anyway, thanks for the review.

Best Regards,
Petr