linux-kernel - Re: Deadlock?: console_waiter/serial8250_ports/low_water

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite for Android: free password hash cracker in your pocket
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <ZyAJD5IPWRoXhd_B@Boquns-Mac-mini.local>
Date: Mon, 28 Oct 2024 14:58:39 -0700
From: Boqun Feng <boqun.feng@...il.com>
To: John Stultz <jstultz@...gle.com>
Cc: John Ogness <john.ogness@...utronix.de>, Petr Mladek <pmladek@...e.com>,
	Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
	jirislaby@...nel.org, LKML <linux-kernel@...r.kernel.org>,
	kernel-team@...roid.com
Subject: Re: Deadlock?: console_waiter/serial8250_ports/low_water_lock with
 6.12-rc

On Mon, Oct 28, 2024 at 12:54:35PM -0700, John Stultz wrote:
> On Mon, Oct 28, 2024 at 12:30 PM John Stultz <jstultz@...gle.com> wrote:
> > * One thread is in virt_spin_lock (lock=lock@...ry=0xffffffff843d19a0
> > <serial8250_ports>) at ./arch/x86/include/asm/qspinlock.h:106.  The
> > backtrace there, is similarly going through
> > do_exit()->check_stack_usage()->printk (I suspect blocking all the
> > other cpus), where it hits: serial8250_console_write
> > (up=0xffffffff843d19a0 <serial8250_ports>, s=0xffffffff8434f7e0
> > <printk_shared_pbufs> "[   69.857641] \n", count=<optimized out>) at
> > drivers/tty/serial/8250/8250_port.c:3352,  then into the spinlock
> > code.
> >
> 
> I got a question on IRC about the backtrace for this cpu, so I wanted
> to also share it here as well.
> 

I think the cause of the issue is:

	CPU X					CPU Y
	=====					=====
	uart_write():				console_unlock(): // console lock is held by Y.
	  uart_port_lock();			  __console_flush_and_unlock():
	  __uart_start():			    __console_flush_all():
	    pm_runtime_get():			      console_emit_next_record():
	      __pm_runtime_resume():		        con->write(); <- serial8250_console_write() // will try to acquire uart_port_lock();
	        spin_lock_irqsave(&dev->power.lock, flags):
		  <this triggers the lockdep splats, probably because
		   PM has done some print under "&dev->power.lock">
		  lock_acquire():
		    printk():
		      vprintk_emit():
		        // Because NBCON_PRIO_EMERGENCY is used, and 
		        console_trylock_spinning();

So CPU X has the uart_port_lock() but need the console lock, and CPU Y
has the console lock but need the uart_port_lock().

Regards,
Boqun

> #0  virt_spin_lock (lock=lock@...ry=0xffffffff843d19a0
> <serial8250_ports>) at ./arch/x86/include/asm/qspinlock.h:106
> #1  queued_spin_lock_slowpath (lock=lock@...ry=0xffffffff843d19a0
> <serial8250_ports>, val=1) at kernel/locking/qspinlock.c:324
> #2  0xffffffff8112954e in queued_spin_lock (lock=0xffffffff843d19a0
> <serial8250_ports>) at ./include/asm-generic/qspinlock.h:114
> #3  do_raw_spin_lock (lock=lock@...ry=0xffffffff843d19a0
> <serial8250_ports>) at kernel/locking/spinlock_debug.c:116
> #4  0xffffffff82177e67 in __raw_spin_lock_irqsave
> (lock=0xffffffff843d19a0 <serial8250_ports>) at
> ./include/linux/spinlock_api_smp.h:111
> #5  _raw_spin_lock_irqsave (lock=lock@...ry=0xffffffff843d19a0
> <serial8250_ports>) at kernel/locking/spinlock.c:162
> #6  0xffffffff817723d0 in uart_port_lock_irqsave (flags=<synthetic
> pointer>, up=0xffffffff843d19a0 <serial8250_ports>) at
> ./include/linux/serial_core.h:711
> #7  serial8250_console_write (up=0xffffffff843d19a0
> <serial8250_ports>, s=0xffffffff8434f7e0 <printk_shared_pbufs> "[
> 69.857641] \n", count=<optimized out>)
>     at drivers/tty/serial/8250/8250_port.c:3352
> #8  0xffffffff8113ef11 in console_emit_next_record (cookie=<optimized
> out>, handover=<optimized out>, con=0xffffffff82e11e40
> <univ8250_console>)
>     at kernel/printk/printk.c:3092
> #9  console_flush_all (do_cond_resched=do_cond_resched@...ry=false,
> next_seq=next_seq@...ry=0xffffc9000274fdb8,
> handover=handover@...ry=0xffffc9000274fdb3)
>     at kernel/printk/printk.c:3180
> #10 0xffffffff8113f1a3 in __console_flush_and_unlock () at
> kernel/printk/printk.c:3239
> #11 console_unlock () at kernel/printk/printk.c:3279
> #12 0xffffffff8113f745 in vprintk_emit (facility=0, level=<optimized
> out>, dev_info=0x0 <fixed_percpu_data>,
>     fmt=0xffffffff8297cc28 "\0016%s (%d) used greatest stack depth:
> %lu bytes left\n", args=0xffffc9000274fe30) at
> kernel/printk/printk.c:2407
> #13 0xffffffff8113b9d4 in _printk (fmt=fmt@...ry=0xffffffff8297cc28
> "\0016%s (%d) used greatest stack depth: %lu bytes left\n") at
> kernel/printk/printk.c:2432
> #14 0xffffffff810994d0 in check_stack_usage () at ./include/linux/pid.h:232
> #15 do_exit (code=code@...ry=0) at kernel/exit.c:982
> #16 0xffffffff81099876 in do_group_exit (exit_code=0) at kernel/exit.c:1088
> #17 0xffffffff81099908 in __do_sys_exit_group (error_code=<optimized
> out>) at kernel/exit.c:1099
> #18 __se_sys_exit_group (error_code=<optimized out>) at kernel/exit.c:1097
> #19 __x64_sys_exit_group (regs=<optimized out>) at kernel/exit.c:1097
> #20 0xffffffff81003ab3 in x64_sys_call (regs=<optimized out>,
> nr=<optimized out>) at
> ./arch/x86/include/generated/asm/syscalls_64.h:232
> #21 0xffffffff8216267b in do_syscall_x64 (nr=231,
> regs=0xffffc9000274ff58) at arch/x86/entry/common.c:52
> #22 do_syscall_64 (regs=0xffffc9000274ff58, nr=231) at
> arch/x86/entry/common.c:83
> #23 0xffffffff82200130 in entry_SYSCALL_64 () at arch/x86/entry/entry_64.S:121
> #24 0x0000000000000000 in ?? ()
> 
> 
> thanks
> -john