Re: Recursive/circular locking in serial8250_console_write/serial8250_do_startup

[Andy Shevchenko]

On Thu, Aug 13, 2020 at 10:03:44AM -0700, Guenter Roeck wrote:
> 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 ?

That's basically what Sergey (IIRC) proposed in [1].
(You missed enable_irq() part in above)

I guess we may try it. Sergey, can you submit a formal patch?

> >> 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@xxxxxxxxxxxxxx/T/#u
> >> [2]: https://bugs.chromium.org/p/chromium/issues/detail?id=1114800

-- 
With Best Regards,
Andy Shevchenko