Re: Recursive/circular locking in serial8250_console_write/serial8250_do_startup

[Guenter Roeck <linux@roeck-us.net>]

On 8/13/20 8:33 AM, Guenter Roeck wrote:
> On 8/13/20 7:20 AM, Andy Shevchenko wrote:
>> On Thu, Aug 13, 2020 at 01:59:48PM +0200, Greg KH wrote:
>>> On Wed, Aug 12, 2020 at 10:06:29PM -0700, Guenter Roeck wrote:
>>>> On Wed, Aug 12, 2020 at 08:48:13AM -0700, Guenter Roeck wrote:
>>>>> Hi,
>>>>>
>>>>> crbug.com/1114800 reports a hard lockup due to circular locking in the
>>>>> 8250 console driver. This is seen if CONFIG_PROVE_LOCKING is enabled.
>>>>>
>>>>> Problem is as follows:
>>>>> - serial8250_do_startup() locks the serial (console) port.
>>>>> - serial8250_do_startup() then disables interrupts if interrupts are
>>>>>   shared, by calling disable_irq_nosync().
>>>>> - disable_irq_nosync() calls __irq_get_desc_lock() to lock the interrupt
>>>>>   descriptor.
>>>>> - __irq_get_desc_lock() calls lock_acquire()
>>>>> - If CONFIG_PROVE_LOCKING is enabled, validate_chain() and check_noncircular()
>>>>>   are called and identify a potential locking error.
>>>>> - This locking error is reported via printk, which ultimately calls
>>>>>   serial8250_console_write().
>>>>> - serial8250_console_write() tries to lock the serial console port.
>>>>>   Since it is already locked, the system hangs and ultimately reports
>>>>>   a hard lockup.
>>>>>
>>>>> I understand we'll need to figure out and fix what lockdep complains about,
>>>>> and I am working on that. However, even if that is fixed, we'll need a
>>>>> solution for the recursive lock: Fixing the lockdep problem doesn't
>>>>> guarantee that a similar problem (or some other log message) won't be
>>>>> detected and reported sometime in the future while serial8250_do_startup()
>>>>> holds the console port lock.
>>>>>
>>>>> Ideas, anyone ? Everything I came up with so far seems clumsy and hackish.
>>>>>
>>>>
>>>> Turns out the situation is a bit worse than I thought. disable_irq_nosync(),
>>>> when called from serial8250_do_startup(), locks the interrupt descriptor.
>>>> The order of locking is
>>>> 	serial port lock
>>>> 	  interrupt descriptor lock
>>>>
>>>> At the same time, __setup_irq() locks the interrupt descriptor as well.
>>>> With the descriptor locked, it may report an error message using pr_err().
>>>> This in turn may call serial8250_console_write(), which will try to lock
>>>> the console serial port. The lock sequence is
>>>> 	interrupt descriptor lock
>>>> 	  serial port lock
>>>>
>>>> I added the lockdep splat to the bug log at crbug.com/1114800.
>>>>
>>>> Effectively, I think, this means we can't call disable_irq_nosync()
>>>> while holding a serial port lock, or at least not while holding a
>>>> serial port lock that is associated with a console.
>>>>
>>>> The problem was introduced (or, rather, exposed) with upstream commit
>>>> 7febbcbc48fc ("serial: 8250: Check UPF_IRQ_SHARED in advance").
>>>
>>> Adding Andy, who wrote the above commit :)
>>>
>>> Andy, any thoughts?
>>
>> So, we have here a problem and my commit is indeed revealed it since it's
>> basically did spread of what we used to have only in two drivers (and
>> originally reported problem was against third one, i.e. 8250_pnp) to all 8250.
>> Even if we revert that commit, we got the other problem appear, hence it's a
>> matter who to suffer until the clean solution will be provided.
>>
>> As per earlier discussion [1] (and I Cc'ed this to people from there) it
>> appears there is another issue with RT kernels which brought initially that
>> controversial disable_irq_nosync() call. Same here, if we drop this call
>> somebody will be unsatisfied.
>>
> 
> The lock chain in [1] is
> 	console_owner --> &port_lock_key --> &irq_desc_lock_class
> and in my case ([2], comment 13) it is
> 	&irq_desc_lock_class --> console_owner --> &port_lock_key
> 
> Looks like we just changed the order of locks.
> 
>> The real fix possible to go to completely lockless printk(), but on the other
>> hand it probably won't prevent other locking corner cases (dead lock?) in 8250
>> console write callback.
>> spin_lock_irqsave
>> The fix proposed in [2] perhaps not the way to go either...
>>
> 
> The code in [2] (Comment 10) was just a hack to prevent the hard lockup
> from happening and to be able see the lockdep splat. It wasn't supposed
> to fix anything (and it doesn't).
> 
> Can we change the order of spin_lock_irqsave / disable_irq_nosync ?
> 
> -               spin_lock_irqsave(&port->lock, flags);
>                 if (up->port.irqflags & IRQF_SHARED)
>                         disable_irq_nosync(port->irq);
> +               spin_lock_irqsave(&port->lock, flags);
> 
> [ plus of course the same for unlock ]
> 

I tried the above, and it solves the problem for me. It is less than perfect
(interrupts will be disabled for more time if the code has to wait for the
spinlock), but I _think_ it should work.

Should I submit a patch ? Or is there a major flaw in my thinking ?

Thanks,
Guenter

> 
>> The idea about not allowing disabling IRQ for console port may be least
>> painful as a (temporary?) mitigation.
>>
>> [1]: https://lore.kernel.org/lkml/CAHQZ30BnfX+gxjPm1DUd5psOTqbyDh4EJE=2=VAMW_VDafctkA@mail.gmail.com/T/#u
>> [2]: https://bugs.chromium.org/p/chromium/issues/detail?id=1114800
>>
>