[PATCH] printk: Fix spinlock deadlock in printk reenty

[PATCH] printk: Fix spinlock deadlock in printk reenty

[linyongting]

From: Jinling Ke <kejinling@huawei.com>

when Oops in printk, printk will call zap_locks() to reinitialize
spinlock to prevent deadlock. In arm, arm64, x86 or other
architecture smp cpu, race condition will occur in printk spinlock
logbuf_lock and then it will result other cpu that is waiting printk
spinlock in deadlock(in function raw_spin_lock). Because the cpus
deadlock, you can see the error  printk log:

"SMP: failed to stop secondary CPUs"

In arm, arm64, x86 or other architecture, spinlock variable
is divided into 2 parts, for example they are 'owner' and 'next' in arm.
When get a spinlock, the 'next' part will add 1 and wait 'next' being
equal to 'owner'. However, at this moment, the 'next' part is local
variable, but 'owner' part value is get from global variable logbuf_lock.
However,raw_spin_lock_init(&logbuf_lock) will set 'owner' part and
'next' part to zero, the result is that cpu deadlock in function
raw_spin_lock( while loop in function arch_spin_lock ).

	struct of arm spinlock
	 	union {
			u32 slock;
			struct __raw_tickets {
				u16 owner;
				u16 next;
			} tickets;
		};
	} arch_spinlock_t;
	static inline void arch_spin_lock(arch_spinlock_t *lock)
	{...
		<--- At the moment, other cpu call zap_locks()->spin_lock_init(),
		<--- set the 'owner' part to zero, but lockval.tickets.next is a
	        <--- local variable
		while (lockval.tickets.next != lockval.tickets.owner) {
			lockval.tickets.owner = ACCESS_ONCE(lock->tickets.owner);
		}
	...
	}

The solution is that In function zap_locks(), replace
raw_spin_lock_init(&logbuf_lock) with raw_spin_unlock(&logbuf_lock),
to let spin_lock stay in unlocked.

Signed-off-by: Jinling Ke <kejinling@huawei.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 f7a55e9..05b1886 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1603,7 +1603,7 @@ static void zap_locks(void)
 
 	debug_locks_off();
 	/* If a crash is occurring, make sure we can't deadlock */
-	raw_spin_lock_init(&logbuf_lock);
+	raw_spin_unlock(&logbuf_lock);
 	/* And make sure that we print immediately */
 	sema_init(&console_sem, 1);
 }
-- 
1.7.9.5

Re: [PATCH] printk: Fix spinlock deadlock in printk reenty

[Petr Mladek]

On Wed 2016-11-30 15:15:19, linyongting@huawei.com wrote:
> From: Jinling Ke <kejinling@huawei.com>
> 
> when Oops in printk, printk will call zap_locks() to reinitialize
> spinlock to prevent deadlock. In arm, arm64, x86 or other
> architecture smp cpu, race condition will occur in printk spinlock
> logbuf_lock and then it will result other cpu that is waiting printk
> spinlock in deadlock(in function raw_spin_lock). Because the cpus
> deadlock, you can see the error  printk log:
> 
> "SMP: failed to stop secondary CPUs"
> 
> In arm, arm64, x86 or other architecture, spinlock variable
> is divided into 2 parts, for example they are 'owner' and 'next' in arm.
> When get a spinlock, the 'next' part will add 1 and wait 'next' being
> equal to 'owner'. However, at this moment, the 'next' part is local
> variable, but 'owner' part value is get from global variable logbuf_lock.
> However,raw_spin_lock_init(&logbuf_lock) will set 'owner' part and
> 'next' part to zero, the result is that cpu deadlock in function
> raw_spin_lock( while loop in function arch_spin_lock ).
> 
> 	struct of arm spinlock
> 	 	union {
> 			u32 slock;
> 			struct __raw_tickets {
> 				u16 owner;
> 				u16 next;
> 			} tickets;
> 		};
> 	} arch_spinlock_t;
> 	static inline void arch_spin_lock(arch_spinlock_t *lock)
> 	{...
> 		<--- At the moment, other cpu call zap_locks()->spin_lock_init(),
> 		<--- set the 'owner' part to zero, but lockval.tickets.next is a
> 	        <--- local variable
> 		while (lockval.tickets.next != lockval.tickets.owner) {
> 			lockval.tickets.owner = ACCESS_ONCE(lock->tickets.owner);
> 		}
> 	...
> 	}
> 
> The solution is that In function zap_locks(), replace
> raw_spin_lock_init(&logbuf_lock) with raw_spin_unlock(&logbuf_lock),
> to let spin_lock stay in unlocked.
> 
> Signed-off-by: Jinling Ke <kejinling@huawei.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 f7a55e9..05b1886 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1603,7 +1603,7 @@ static void zap_locks(void)
>  
>  	debug_locks_off();
>  	/* If a crash is occurring, make sure we can't deadlock */
> -	raw_spin_lock_init(&logbuf_lock);
> +	raw_spin_unlock(&logbuf_lock);

But what if the lock was not not locked in the first place?
A solution might be to use

	if (raw_spin_is_locked(&logbuf_lock))
		raw_spin_unlock(&logbuf_lock);

But this would fail if the lock looks locked because
it was unlocked twice or when the first next waiter is
blocked from some reason.

The idea behind the current code is the best effort to
print the Oops message. It means to allow to get
the printk lock by the process that is calling zap_locks().
For this the lock_init() looks like the best solution.

Note that we are going to remove zap_lock() completely.
See https://lkml.kernel.org/r/20161027154933.1211-7-sergey.senozhatsky@gmail.com

Another solution would be to make printk() to ignore locks
when Oops is in progress. It was somewhere suggested by Peter
Zijlstra. Well, it might cause some problems as well when
there are more CPUs still running and printing.

Best Regards,
Petr

Re: [PATCH] printk: Fix spinlock deadlock in printk reenty

[Peter Zijlstra]

On Wed, Nov 30, 2016 at 11:56:53AM +0100, Petr Mladek wrote:
> On Wed 2016-11-30 15:15:19, linyongting@huawei.com wrote:
> > In arm, arm64, x86 or other architecture, spinlock variable

x86 no longer uses ticket locks.

> > The solution is that In function zap_locks(), replace
> > raw_spin_lock_init(&logbuf_lock) with raw_spin_unlock(&logbuf_lock),

That's broken too. Imagine the CPU that actually holds the lock then
_also_ doing an unlock. At that point the tail is ahead of the head and
you're also up some creek without no paddle.

Note that I ran into all these scenarios many years ago..

> Another solution would be to make printk() to ignore locks
> when Oops is in progress. It was somewhere suggested by Peter
> Zijlstra. Well, it might cause some problems as well when
> there are more CPUs still running and printing.

Ignoring is the only option. There is no way to fudge the lock state and
live to tell about it.

Re: [PATCH] printk: Fix spinlock deadlock in printk reenty

[Andrew Morton]

On Wed, 30 Nov 2016 15:15:19 +0800 <linyongting@huawei.com> wrote:

> From: Jinling Ke <kejinling@huawei.com>
> 
> when Oops in printk, printk will call zap_locks() to reinitialize
> spinlock to prevent deadlock. In arm, arm64, x86 or other
> architecture smp cpu, race condition will occur in printk spinlock
> logbuf_lock and then it will result other cpu that is waiting printk
> spinlock in deadlock(in function raw_spin_lock). Because the cpus
> deadlock, you can see the error  printk log:
> 
> "SMP: failed to stop secondary CPUs"
> 
> In arm, arm64, x86 or other architecture, spinlock variable
> is divided into 2 parts, for example they are 'owner' and 'next' in arm.
> When get a spinlock, the 'next' part will add 1 and wait 'next' being
> equal to 'owner'. However, at this moment, the 'next' part is local
> variable, but 'owner' part value is get from global variable logbuf_lock.
> However,raw_spin_lock_init(&logbuf_lock) will set 'owner' part and
> 'next' part to zero, the result is that cpu deadlock in function
> raw_spin_lock( while loop in function arch_spin_lock ).
> 
> 	struct of arm spinlock
> 	 	union {
> 			u32 slock;
> 			struct __raw_tickets {
> 				u16 owner;
> 				u16 next;
> 			} tickets;
> 		};
> 	} arch_spinlock_t;
> 	static inline void arch_spin_lock(arch_spinlock_t *lock)
> 	{...
> 		<--- At the moment, other cpu call zap_locks()->spin_lock_init(),
> 		<--- set the 'owner' part to zero, but lockval.tickets.next is a
> 	        <--- local variable
> 		while (lockval.tickets.next != lockval.tickets.owner) {
> 			lockval.tickets.owner = ACCESS_ONCE(lock->tickets.owner);
> 		}
> 	...
> 	}
> 
> The solution is that In function zap_locks(), replace
> raw_spin_lock_init(&logbuf_lock) with raw_spin_unlock(&logbuf_lock),
> to let spin_lock stay in unlocked.
> 
> ...
>
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1603,7 +1603,7 @@ static void zap_locks(void)
>  
>  	debug_locks_off();
>  	/* If a crash is occurring, make sure we can't deadlock */
> -	raw_spin_lock_init(&logbuf_lock);
> +	raw_spin_unlock(&logbuf_lock);
>  	/* And make sure that we print immediately */
>  	sema_init(&console_sem, 1);

OK, so it's a race between raw_spin_lock() and raw_spin_lock_init()?

I wonder if there's a more general way of preventing this, within
raw_spin_lock_init()?

Of course, printk is special and the situation is unlikely to occur
elsewhere.

I guess the raw_spin_unlock() is OK - lockdep would have warned about
unlock-of-unlocked-lock but we did a debug_locks_off() to prevent that.