Nested calls to spin_lock_irq with different locks

Nested calls to spin_lock_irq with different locks

[Guenter Roeck]

Hi,

recently I have seen various syzbot reports reporting inconsistent lock
states. One example is

================================
WARNING: inconsistent lock state
5.16.0-syzkaller #0 Not tainted
--------------------------------
inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
syz-executor.2/18360 [HC0[0]:SC0[0]:HE0:SE1] takes:
ffffffff8c712cf8 (sync_timeline_list_lock){?...}-{2:2}, at: spin_lock_irq include/linux/spinlock.h:374 [inline]
ffffffff8c712cf8 (sync_timeline_list_lock){?...}-{2:2}, at: sync_info_debugfs_show+0x2d/0x200 drivers/dma-buf/sync_debug.c:147
{IN-HARDIRQ-W} state was registered at:
  lock_acquire kernel/locking/lockdep.c:5639 [inline]
  lock_acquire+0x1ab/0x510 kernel/locking/lockdep.c:5604
  __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
  _raw_spin_lock_irqsave+0x39/0x50 kernel/locking/spinlock.c:162
  sync_timeline_debug_remove+0x25/0x190 drivers/dma-buf/sync_debug.c:31

================================
WARNING: inconsistent lock state
5.16.0-syzkaller #0 Not tainted
--------------------------------
inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
syz-executor.2/18360 [HC0[0]:SC0[0]:HE0:SE1] takes:
ffffffff8c712cf8 (sync_timeline_list_lock){?...}-{2:2}, at: spin_lock_irq include/linux/spinlock.h:374 [inline]
ffffffff8c712cf8 (sync_timeline_list_lock){?...}-{2:2}, at: sync_info_debugfs_show+0x2d/0x200 drivers/dma-buf/sync_debug.c:147

The log is from
https://lore.kernel.org/lkml/000000000000d5b3af05edc9d445@google.com/T/.

sync_info_debugfs_show() calls spin_lock_irq(&sync_timeline_list_lock).
With the lock active, it calls sync_print_obj(), which calls
spin_lock_irq(&obj->lock) and spin_unlock_irq(&obj->lock).

spin_unlock_irq(), via __raw_spin_unlock_irq(), calls local_irq_enable(),
presumably enabling hardware interrupts. If such a hardware interrupt
calls sync_timeline_debug_remove(), the problem would be seen.

Can this happen in practice ? In other words, does that mean that nested
calls to spin_lock_irq() (with different locks) are not supported ?
If that is indeed the case, is there a suggested remedy ?

Thanks,
Guenter

Re: Nested calls to spin_lock_irq with different locks

[Waiman Long]

On 11/19/22 10:17, Guenter Roeck wrote:
> Hi,
>
> recently I have seen various syzbot reports reporting inconsistent lock
> states. One example is
>
> ================================
> WARNING: inconsistent lock state
> 5.16.0-syzkaller #0 Not tainted
> --------------------------------
> inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
> syz-executor.2/18360 [HC0[0]:SC0[0]:HE0:SE1] takes:
> ffffffff8c712cf8 (sync_timeline_list_lock){?...}-{2:2}, at: spin_lock_irq include/linux/spinlock.h:374 [inline]
> ffffffff8c712cf8 (sync_timeline_list_lock){?...}-{2:2}, at: sync_info_debugfs_show+0x2d/0x200 drivers/dma-buf/sync_debug.c:147
> {IN-HARDIRQ-W} state was registered at:
>    lock_acquire kernel/locking/lockdep.c:5639 [inline]
>    lock_acquire+0x1ab/0x510 kernel/locking/lockdep.c:5604
>    __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
>    _raw_spin_lock_irqsave+0x39/0x50 kernel/locking/spinlock.c:162
>    sync_timeline_debug_remove+0x25/0x190 drivers/dma-buf/sync_debug.c:31
>
> ================================
> WARNING: inconsistent lock state
> 5.16.0-syzkaller #0 Not tainted
> --------------------------------
> inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
> syz-executor.2/18360 [HC0[0]:SC0[0]:HE0:SE1] takes:
> ffffffff8c712cf8 (sync_timeline_list_lock){?...}-{2:2}, at: spin_lock_irq include/linux/spinlock.h:374 [inline]
> ffffffff8c712cf8 (sync_timeline_list_lock){?...}-{2:2}, at: sync_info_debugfs_show+0x2d/0x200 drivers/dma-buf/sync_debug.c:147
>
> The log is from
> https://lore.kernel.org/lkml/000000000000d5b3af05edc9d445@google.com/T/.
>
> sync_info_debugfs_show() calls spin_lock_irq(&sync_timeline_list_lock).
> With the lock active, it calls sync_print_obj(), which calls
> spin_lock_irq(&obj->lock) and spin_unlock_irq(&obj->lock).
>
> spin_unlock_irq(), via __raw_spin_unlock_irq(), calls local_irq_enable(),
> presumably enabling hardware interrupts. If such a hardware interrupt
> calls sync_timeline_debug_remove(), the problem would be seen.
>
> Can this happen in practice ? In other words, does that mean that nested
> calls to spin_lock_irq() (with different locks) are not supported ?
> If that is indeed the case, is there a suggested remedy ?

That is what spin_lock_irqsave() and spin_unlock_irqrestore() are for. 
If you are not certain if a function will be called with interrupt 
enabled or disabled, you should always use the irqsave/irqrestore 
variant to make sure the function will work in both cases.

Cheers,
Longman