Re: UART/TTY console deadlock

From: Petr Mladek
Date: Tue Jun 30 2020 - 06:21:50 EST


On Tue 2020-06-30 12:58:16, Sergey Senozhatsky wrote:
> Cc-ing more people
>
> https://lore.kernel.org/lkml/CAHp75Vd8nTzmZdnhpTDChdc11zyCaSfeigbxaCpOWZ1Lv9ZBMw@xxxxxxxxxxxxxx
>
> On (20/06/22 20:37), Andy Shevchenko wrote:
> > > [ 279.759811] -> #2 (&irq_desc_lock_class){-.-.}:
> > > [ 279.759813] _raw_spin_lock_irqsave+0x61/0x8d
> > > [ 279.759813] __irq_get_desc_lock+0x65/0x89
> > > [ 279.759814] __disable_irq_nosync+0x3b/0x93
> > > [ 279.759814] serial8250_do_startup+0x451/0x75c
> > > [ 279.759815] uart_startup+0x1b4/0x2ff
> > > [ 279.759815] uart_port_activate+0x73/0xa0
> > > [ 279.759815] tty_port_open+0xae/0x10a
> > > [ 279.759816] uart_open+0x1b/0x26
> > > [ 279.759816] tty_open+0x24d/0x3a0
> > > [ 279.759817] chrdev_open+0xd5/0x1cc
> > > [ 279.759817] do_dentry_open+0x299/0x3c8
> > > [ 279.759817] path_openat+0x434/0x1100
> > > [ 279.759818] do_filp_open+0x9b/0x10a
> > > [ 279.759818] do_sys_open+0x15f/0x3d7
> > > [ 279.759819] kernel_init_freeable+0x157/0x1dd
> > > [ 279.759819] kernel_init+0xe/0x105
> > > [ 279.759819] ret_from_fork+0x27/0x50
> > > [ 279.759820]
> > > [ 279.759820] -> #1 (&port_lock_key){-.-.}:
> > > [ 279.759822] _raw_spin_lock_irqsave+0x61/0x8d
> > > [ 279.759822] serial8250_console_write+0xa7/0x2a0
> > > [ 279.759823] console_unlock+0x3b7/0x528
> > > [ 279.759823] vprintk_emit+0x111/0x17f
> > > [ 279.759823] printk+0x59/0x73
> > > [ 279.759824] register_console+0x336/0x3a4
> > > [ 279.759824] uart_add_one_port+0x51b/0x5be
> > > [ 279.759825] serial8250_register_8250_port+0x454/0x55e
> > > [ 279.759825] dw8250_probe+0x4dc/0x5b9
> > > [ 279.759825] platform_drv_probe+0x67/0x8b
> > > [ 279.759826] really_probe+0x14a/0x422
> > > [ 279.759826] driver_probe_device+0x66/0x130
> > > [ 279.759827] device_driver_attach+0x42/0x5b
> > > [ 279.759827] __driver_attach+0xca/0x139
> > > [ 279.759827] bus_for_each_dev+0x97/0xc9
> > > [ 279.759828] bus_add_driver+0x12b/0x228
> > > [ 279.759828] driver_register+0x64/0xed
> > > [ 279.759829] do_one_initcall+0x20c/0x4a6
> > > [ 279.759829] do_initcall_level+0xb5/0xc5
> > > [ 279.759829] do_basic_setup+0x4c/0x58
> > > [ 279.759830] kernel_init_freeable+0x13f/0x1dd
> > > [ 279.759830] kernel_init+0xe/0x105
> > > [ 279.759831] ret_from_fork+0x27/0x50
> > > [ 279.759831]
> > > [ 279.759831] -> #0 (console_owner){-...}:
> > > [ 279.759833] __lock_acquire+0x118d/0x2714
> > > [ 279.759833] lock_acquire+0x203/0x258
> > > [ 279.759834] console_lock_spinning_enable+0x51/0x57
> > > [ 279.759834] console_unlock+0x25d/0x528
> > > [ 279.759834] vprintk_emit+0x111/0x17f
> > > [ 279.759835] printk+0x59/0x73
> > > [ 279.759835] __report_bad_irq+0xa3/0xba
> > > [ 279.759836] note_interrupt+0x19a/0x1d6
> > > [ 279.759836] handle_irq_event_percpu+0x57/0x79
> > > [ 279.759836] handle_irq_event+0x36/0x55
> > > [ 279.759837] handle_fasteoi_irq+0xc2/0x18a
> > > [ 279.759837] do_IRQ+0xb3/0x157
> > > [ 279.759838] ret_from_intr+0x0/0x1d
> > > [ 279.759838] cpuidle_enter_state+0x12f/0x1fd
> > > [ 279.759838] cpuidle_enter+0x2e/0x3d
> > > [ 279.759839] do_idle+0x1ce/0x2ce
> > > [ 279.759839] cpu_startup_entry+0x1d/0x1f
> > > [ 279.759840] start_kernel+0x406/0x46a
> > > [ 279.759840] secondary_startup_64+0xa4/0xb0
>
> Hmm. So this is uart->port => desc->lock vs desc->lock => uart->port
>
> chain #1:
>
> serial8250_do_startup()
> spin_lock_irqsave(&port->lock);
> disable_irq_nosync(port->irq);
> raw_spin_lock_irqsave(&desc->lock)
>
> chain #2:
>
> __report_bad_irq()
> raw_spin_lock_irqsave(&desc->lock)
> for_each_action_of_desc()
> printk()
> spin_lock_irqsave(&port->lock);
>
>
> Breaking up chain #2 is not an option, I suppose. Those are a rather
> important KERN_ERR messages, printk_deferred() will upset people badly.

Yes, we should avoid printk_deferred() unless there is another solution.


> So... Do we need to hold uart->port when we disable port->irq? What do we
> race with? Module removal? The function bumps device PM counter (albeit
> for UART_CAP_RPM ports only).

Honestly, I do not see where a PM counter gets incremented.

Anyway, __disable_irq_nosync() does nothing when
irq_get_desc_buslock() returns NULL. And irq_get_desc_buslock()
takes desc->lock when desc exist. This should be enough to
synchronize any calls.

> But, at the same time, we do a whole bunch
> of unprotected port->FOO accesses in serial8250_do_startup(). We even set
> the IRQF_SHARED up->port.irqflags without grabbing the port->lock:
>
> up->port.irqflags |= IRQF_SHARED;
> spin_lock_irqsave(&port->lock, flags);
> if (up->port.irqflags & IRQF_SHARED)
> disable_irq_nosync(port->irq);

Yup, this looks suspicious. We set a flag in port.irqflags and take the lock
only when the flag was set. Either everything needs to be done under
the lock or the lock is not needed.

Well, I might have missed something. I do not fully understand meaning
and relation of all the structures.

Anyway, I believe that this is a false positive. If I get it correctly
serial8250_do_startup() must be called before the serial port could
be registered as a console. It means that it could not be called
from inside printk().

Sigh, I do not know how to tell lockdep about these false positives.
And I am never 100% sure that we could shuffle locks in the various
the console drivers.


> IOW, can we do something like this?
>
> ---
> drivers/tty/serial/8250/8250_port.c | 11 +++++++----
> 1 file changed, 7 insertions(+), 4 deletions(-)
>
> diff --git a/drivers/tty/serial/8250/8250_port.c b/drivers/tty/serial/8250/8250_port.c
> index d64ca77d9cfa..ad30991e1b3b 100644
> --- a/drivers/tty/serial/8250/8250_port.c
> +++ b/drivers/tty/serial/8250/8250_port.c
> @@ -2275,6 +2275,11 @@ int serial8250_do_startup(struct uart_port *port)
>
> if (port->irq && !(up->port.flags & UPF_NO_THRE_TEST)) {
> unsigned char iir1;
> + bool irq_shared = up->port.irqflags & IRQF_SHARED;
> +
> + if (irq_shared)
> + disable_irq_nosync(port->irq);
> +
> /*
> * Test for UARTs that do not reassert THRE when the
> * transmitter is idle and the interrupt has already
> @@ -2284,8 +2289,6 @@ int serial8250_do_startup(struct uart_port *port)
> * allow register changes to become visible.
> */
> spin_lock_irqsave(&port->lock, flags);
> - if (up->port.irqflags & IRQF_SHARED)
> - disable_irq_nosync(port->irq);
>
> wait_for_xmitr(up, UART_LSR_THRE);
> serial_port_out_sync(port, UART_IER, UART_IER_THRI);
> @@ -2297,9 +2300,9 @@ int serial8250_do_startup(struct uart_port *port)
> iir = serial_port_in(port, UART_IIR);
> serial_port_out(port, UART_IER, 0);
>
> - if (port->irqflags & IRQF_SHARED)
> - enable_irq(port->irq);
> spin_unlock_irqrestore(&port->lock, flags);
> + if (irq_shared)
> + enable_irq(port->irq);
>
> /*
> * If the interrupt is not reasserted, or we otherwise

I think that it might be safe but I am not 100% sure, sigh.

Best Regards,
Petr