Re: [PATCH] printk: fix deadlock when kernel panic

[Petr Mladek]

Hi,

first, I am sorry for the late reply. I have been somehow distracted
this week.

On Mon 2021-02-01 18:26:01, Muchun Song wrote:
> We found a deadlock bug on our server when the kernel panic. It can be
> described in the following diagram.
> 
> CPU0:                                         CPU1:
> panic                                         rcu_dump_cpu_stacks
>   kdump_nmi_shootdown_cpus                      nmi_trigger_cpumask_backtrace
>     register_nmi_handler(crash_nmi_callback)      printk_safe_flush
>                                                     __printk_safe_flush
>                                                       raw_spin_lock_irqsave(&read_lock)
>     // send NMI to other processors
>     apic_send_IPI_allbutself(NMI_VECTOR)
>                                                         // NMI interrupt, dead loop
>                                                         crash_nmi_callback
>   printk_safe_flush_on_panic
>     printk_safe_flush
>       __printk_safe_flush
>         // deal lock
>         raw_spin_lock_irqsave(&read_lock)

Great catch!

>  kernel/printk/printk_safe.c | 58 ++++++++++++++++++++++++++-------------------
>  1 file changed, 34 insertions(+), 24 deletions(-)
> 
> diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
> index a0e6f746de6c..86d9fa74ac5c 100644
> --- a/kernel/printk/printk_safe.c
> +++ b/kernel/printk/printk_safe.c
> @@ -174,30 +174,13 @@ static void report_message_lost(struct printk_safe_seq_buf *s)
>  		printk_deferred("Lost %d message(s)!\n", lost);
>  }
>  
> -/*
> - * Flush data from the associated per-CPU buffer. The function
> - * can be called either via IRQ work or independently.
> - */
> -static void __printk_safe_flush(struct irq_work *work)
> +static void __printk_safe_flush_work(struct irq_work *work)
>  {
> -	static raw_spinlock_t read_lock =
> -		__RAW_SPIN_LOCK_INITIALIZER(read_lock);
>  	struct printk_safe_seq_buf *s =
>  		container_of(work, struct printk_safe_seq_buf, work);
> -	unsigned long flags;
>  	size_t len;
> -	int i;
> +	int i = 0;
>  
> -	/*
> -	 * The lock has two functions. First, one reader has to flush all
> -	 * available message to make the lockless synchronization with
> -	 * writers easier. Second, we do not want to mix messages from
> -	 * different CPUs. This is especially important when printing
> -	 * a backtrace.
> -	 */
> -	raw_spin_lock_irqsave(&read_lock, flags);
> -
> -	i = 0;
>  more:
>  	len = atomic_read(&s->len);
>  
> @@ -232,6 +215,26 @@ static void __printk_safe_flush(struct irq_work *work)
>  
>  out:
>  	report_message_lost(s);
> +}
> +
> +/*
> + * Flush data from the associated per-CPU buffer. The function
> + * can be called either via IRQ work or independently.
> + */
> +static void printk_safe_flush_work(struct irq_work *work)
> +{
> +	unsigned long flags;
> +	static DEFINE_RAW_SPINLOCK(read_lock);
> +
> +	/*
> +	 * The lock has two functions. First, one reader has to flush all
> +	 * available message to make the lockless synchronization with
> +	 * writers easier. Second, we do not want to mix messages from
> +	 * different CPUs. This is especially important when printing
> +	 * a backtrace.
> +	 */
> +	raw_spin_lock_irqsave(&read_lock, flags);
> +	__printk_safe_flush_work(work);
>  	raw_spin_unlock_irqrestore(&read_lock, flags);
>  }
>  
> @@ -248,9 +251,9 @@ void printk_safe_flush(void)
>  
>  	for_each_possible_cpu(cpu) {
>  #ifdef CONFIG_PRINTK_NMI
> -		__printk_safe_flush(&per_cpu(nmi_print_seq, cpu).work);
> +		printk_safe_flush_work(&per_cpu(nmi_print_seq, cpu).work);
>  #endif
> -		__printk_safe_flush(&per_cpu(safe_print_seq, cpu).work);
> +		printk_safe_flush_work(&per_cpu(safe_print_seq, cpu).work);
>  	}
>  }
>  
> @@ -266,6 +269,8 @@ void printk_safe_flush(void)
>   */
>  void printk_safe_flush_on_panic(void)
>  {
> +	int cpu;
> +
>  	/*
>  	 * Make sure that we could access the main ring buffer.
>  	 * Do not risk a double release when more CPUs are up.
> @@ -278,7 +283,12 @@ void printk_safe_flush_on_panic(void)
>  		raw_spin_lock_init(&logbuf_lock);
>  	}
>  
> -	printk_safe_flush();
> +	for_each_possible_cpu(cpu) {
> +#ifdef CONFIG_PRINTK_NMI
> +		__printk_safe_flush_work(&per_cpu(nmi_print_seq, cpu).work);
> +#endif
> +		__printk_safe_flush_work(&per_cpu(safe_print_seq, cpu).work);
> +	}

There might be two CPUs running this code when more CPUs are still running.
The might definitely be the case here:

	if (!_crash_kexec_post_notifiers) {
		printk_safe_flush_on_panic();
		__crash_kexec(NULL);

__printk_safe_flush_work() is relatively safe even in this case.
It accesses only data that are limited by s->len that is updated
atomically.

But it calls:

  + printk_safe_flush_on_panic()
    + __printk_safe_flush_work()
      +  printk_safe_flush_buffer()
	+ printk_safe_flush_line()
	  + printk_deferred()

where printk_deferred() used logbuf_lock() until v5.11-rc1, see
the commit b031a684bfd01d633c ("printk: remove logbuf_lock
writer-protection of ringbuffer").

We need a solution that might be backported back to v4.7-rc1
where logbuf_lock() might cause a deadlock.

Also we really want to call printk_safe_flush_on_panic()
in panic(). It is trying hard but it should not cause
deadlock.

Therefore, I suggest to handle read_lock the same way in
printk_safe_flush_on_panic() as we handle logbuf_lock there.

I mean to make it global in printk_safe.c:

static DEFINE_RAW_SPINLOCK(safe_read_lock);

and do something like this in printk_safe_flush_on_panic()

	if (raw_spin_is_locked(&safe_read_lock)) {
		if (num_online_cpus() > 1)
			return;

		debug_locks_off();
		raw_spin_lock_init(&safe_read_lock);
	}

How does that sound, please?

Best Regards,
Petr