inconsistent lock state in sync_timeline_debug_remove

15 views
Skip to first unread message

syzbot

unread,
Feb 17, 2022, 7:33:29 PM2/17/22
to syzkaller...@googlegroups.com
Hello,

syzbot found the following issue on:

HEAD commit: 3f8a27f9e27b Linux 4.19.211
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=1347dbbc700000
kernel config: https://syzkaller.appspot.com/x/.config?x=9b9277b418617afe
dashboard link: https://syzkaller.appspot.com/bug?extid=92c90d4a84afd30c2cf4
compiler: gcc version 10.2.1 20210110 (Debian 10.2.1-6)
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=15cb5a5a700000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=117d6936700000

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+92c90d...@syzkaller.appspotmail.com

================================
WARNING: inconsistent lock state
4.19.211-syzkaller #0 Not tainted
--------------------------------
inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage.
syz-executor529/8102 [HC1[1]:SC0[0]:HE0:SE1] takes:
000000003fbca257 (sync_timeline_list_lock){?.+.}, at: sync_timeline_debug_remove+0x25/0x190 drivers/dma-buf/sync_debug.c:40
{HARDIRQ-ON-W} state was registered at:
__raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
_raw_spin_unlock_irq+0x24/0x80 kernel/locking/spinlock.c:192
spin_unlock_irq include/linux/spinlock.h:379 [inline]
sync_print_obj drivers/dma-buf/sync_debug.c:127 [inline]
sync_debugfs_show+0xeb/0x200 drivers/dma-buf/sync_debug.c:162
seq_read+0x4e0/0x11c0 fs/seq_file.c:232
__vfs_read+0xf7/0x750 fs/read_write.c:416
vfs_read+0x194/0x3c0 fs/read_write.c:452
ksys_read+0x12b/0x2a0 fs/read_write.c:579
do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe
irq event stamp: 9160
hardirqs last enabled at (9159): [<ffffffff88195174>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
hardirqs last enabled at (9159): [<ffffffff88195174>] _raw_spin_unlock_irq+0x24/0x80 kernel/locking/spinlock.c:192
hardirqs last disabled at (9160): [<ffffffff81003d00>] trace_hardirqs_off_thunk+0x1a/0x1c
softirqs last enabled at (9062): [<ffffffff88400678>] __do_softirq+0x678/0x980 kernel/softirq.c:318
softirqs last disabled at (9047): [<ffffffff813927d5>] invoke_softirq kernel/softirq.c:372 [inline]
softirqs last disabled at (9047): [<ffffffff813927d5>] irq_exit+0x215/0x260 kernel/softirq.c:412

other info that might help us debug this:
Possible unsafe locking scenario:

CPU0
----
lock(sync_timeline_list_lock);
<Interrupt>
lock(sync_timeline_list_lock);

*** DEADLOCK ***

no locks held by syz-executor529/8102.

stack backtrace:
CPU: 1 PID: 8102 Comm: syz-executor529 Not tainted 4.19.211-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x1fc/0x2ef lib/dump_stack.c:118
print_usage_bug.cold+0x42e/0x570 kernel/locking/lockdep.c:2545
valid_state kernel/locking/lockdep.c:2558 [inline]
mark_lock_irq kernel/locking/lockdep.c:2752 [inline]
mark_lock+0xc70/0x1160 kernel/locking/lockdep.c:3132
mark_irqflags kernel/locking/lockdep.c:3007 [inline]
__lock_acquire+0x1077/0x3ff0 kernel/locking/lockdep.c:3373
lock_acquire+0x170/0x3c0 kernel/locking/lockdep.c:3908
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x8c/0xc0 kernel/locking/spinlock.c:152
sync_timeline_debug_remove+0x25/0x190 drivers/dma-buf/sync_debug.c:40
sync_timeline_free drivers/dma-buf/sw_sync.c:113 [inline]
kref_put include/linux/kref.h:70 [inline]
sync_timeline_put+0x31/0x40 drivers/dma-buf/sw_sync.c:125
timeline_fence_release+0x1fe/0x2f0 drivers/dma-buf/sw_sync.c:153
dma_fence_release+0xeb/0x330 drivers/dma-buf/dma-fence.c:228
kref_put include/linux/kref.h:70 [inline]
dma_fence_put include/linux/dma-fence.h:259 [inline]
dma_fence_array_release+0x192/0x230 drivers/dma-buf/dma-fence-array.c:96
dma_fence_release+0xeb/0x330 drivers/dma-buf/dma-fence.c:228
kref_put include/linux/kref.h:70 [inline]
dma_fence_put include/linux/dma-fence.h:259 [inline]
irq_dma_fence_array_work+0x54/0x60 drivers/dma-buf/dma-fence-array.c:39
irq_work_run_list+0x140/0x1c0 kernel/irq_work.c:164
irq_work_run+0x4e/0xb0 kernel/irq_work.c:179
smp_irq_work_interrupt+0x98/0x440 arch/x86/kernel/irq_work.c:21
irq_work_interrupt+0xf/0x20 arch/x86/entry/entry_64.S:925
</IRQ>
RIP: 0010:__raw_spin_unlock_irq include/linux/spinlock_api_smp.h:169 [inline]
RIP: 0010:_raw_spin_unlock_irq+0x50/0x80 kernel/locking/spinlock.c:192
Code: c0 98 82 f1 89 48 ba 00 00 00 00 00 fc ff df 48 c1 e8 03 80 3c 10 00 75 31 48 83 3d 01 31 d8 01 00 74 25 fb 66 0f 1f 44 00 00 <bf> 01 00 00 00 e8 26 1b 28 f9 65 8b 05 9f 8d e8 77 85 c0 74 02 5d
RSP: 0018:ffff888095e47ca8 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff09
RAX: 1ffffffff13e3053 RBX: ffff8880b45dbde0 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffff8880b2596d84
RBP: ffff8880b45dbe50 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: dffffc0000000000
R13: ffff8880b45dbe40 R14: ffff8880b45dbe00 R15: 0000000000000000
spin_unlock_irq include/linux/spinlock.h:379 [inline]
sw_sync_debugfs_release+0x14a/0x1b0 drivers/dma-buf/sw_sync.c:330
__fput+0x2ce/0x890 fs/file_table.c:278
task_work_run+0x148/0x1c0 kernel/task_work.c:113
exit_task_work include/linux/task_work.h:22 [inline]
do_exit+0xbf3/0x2be0 kernel/exit.c:870
do_group_exit+0x125/0x310 kernel/exit.c:967
__do_sys_exit_group kernel/exit.c:978 [inline]
__se_sys_exit_group kernel/exit.c:976 [inline]
__x64_sys_exit_group+0x3a/0x50 kernel/exit.c:976
do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7f9365a68ed9

----------------
Code disassembly (best guess), 5 bytes skipped:
0: 48 ba 00 00 00 00 00 movabs $0xdffffc0000000000,%rdx
7: fc ff df
a: 48 c1 e8 03 shr $0x3,%rax
e: 80 3c 10 00 cmpb $0x0,(%rax,%rdx,1)
12: 75 31 jne 0x45
14: 48 83 3d 01 31 d8 01 cmpq $0x0,0x1d83101(%rip) # 0x1d8311d
1b: 00
1c: 74 25 je 0x43
1e: fb sti
1f: 66 0f 1f 44 00 00 nopw 0x0(%rax,%rax,1)
* 25: bf 01 00 00 00 mov $0x1,%edi <-- trapping instruction
2a: e8 26 1b 28 f9 callq 0xf9281b55
2f: 65 8b 05 9f 8d e8 77 mov %gs:0x77e88d9f(%rip),%eax # 0x77e88dd5
36: 85 c0 test %eax,%eax
38: 74 02 je 0x3c
3a: 5d pop %rbp


---
This report is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzk...@googlegroups.com.

syzbot will keep track of this issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
syzbot can test patches for this issue, for details see:
https://goo.gl/tpsmEJ#testing-patches

syzbot

unread,
Feb 22, 2022, 12:04:20 PM2/22/22
to syzkaller...@googlegroups.com
Hello,

syzbot found the following issue on:

HEAD commit: a35d65bedfbc Linux 4.14.267
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=11f6b08e700000
kernel config: https://syzkaller.appspot.com/x/.config?x=8535d773e783c59a
dashboard link: https://syzkaller.appspot.com/bug?extid=5f940166cd8f78936b86
compiler: gcc version 10.2.1 20210110 (Debian 10.2.1-6)
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=105cfdee700000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=141d1a96700000

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+5f9401...@syzkaller.appspotmail.com

================================
WARNING: inconsistent lock state
4.14.267-syzkaller #0 Not tainted
--------------------------------
inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage.
syz-executor152/7972 [HC1[1]:SC0[0]:HE0:SE1] takes:
(sync_timeline_list_lock){?.+.}, at: [<ffffffff8399e885>] sync_timeline_debug_remove+0x25/0x190 drivers/dma-buf/sync_debug.c:40
{HARDIRQ-ON-W} state was registered at:
__trace_hardirqs_on_caller kernel/locking/lockdep.c:2875 [inline]
trace_hardirqs_on_caller+0x288/0x580 kernel/locking/lockdep.c:2930
__raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
_raw_spin_unlock_irq+0x24/0x80 kernel/locking/spinlock.c:200
spin_unlock_irq include/linux/spinlock.h:367 [inline]
sync_print_obj drivers/dma-buf/sync_debug.c:127 [inline]
sync_debugfs_show+0xeb/0x200 drivers/dma-buf/sync_debug.c:162
seq_read+0x4e4/0x1180 fs/seq_file.c:240
__vfs_read+0xe4/0x620 fs/read_write.c:411
vfs_read+0x139/0x340 fs/read_write.c:447
SYSC_read fs/read_write.c:574 [inline]
SyS_read+0xf2/0x210 fs/read_write.c:567
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x46/0xbb
irq event stamp: 9166
hardirqs last enabled at (9165): [<ffffffff87242b74>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
hardirqs last enabled at (9165): [<ffffffff87242b74>] _raw_spin_unlock_irq+0x24/0x80 kernel/locking/spinlock.c:200
hardirqs last disabled at (9166): [<ffffffff87401eee>] irq_work_interrupt+0x8e/0xa0 arch/x86/entry/entry_64.S:824
softirqs last enabled at (4510): [<ffffffff8760068b>] __do_softirq+0x68b/0x9ff kernel/softirq.c:314
softirqs last disabled at (4489): [<ffffffff81321d13>] invoke_softirq kernel/softirq.c:368 [inline]
softirqs last disabled at (4489): [<ffffffff81321d13>] irq_exit+0x193/0x240 kernel/softirq.c:409

other info that might help us debug this:
Possible unsafe locking scenario:

CPU0
----
lock(sync_timeline_list_lock);
<Interrupt>
lock(sync_timeline_list_lock);

*** DEADLOCK ***

no locks held by syz-executor152/7972.

stack backtrace:
CPU: 0 PID: 7972 Comm: syz-executor152 Not tainted 4.14.267-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
<IRQ>
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0x1b2/0x281 lib/dump_stack.c:58
print_usage_bug.cold+0x42e/0x570 kernel/locking/lockdep.c:2589
valid_state kernel/locking/lockdep.c:2602 [inline]
mark_lock_irq kernel/locking/lockdep.c:2796 [inline]
mark_lock+0xb4d/0x1050 kernel/locking/lockdep.c:3194
mark_irqflags kernel/locking/lockdep.c:3069 [inline]
__lock_acquire+0xfb2/0x3f20 kernel/locking/lockdep.c:3448
lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x8c/0xc0 kernel/locking/spinlock.c:160
sync_timeline_debug_remove+0x25/0x190 drivers/dma-buf/sync_debug.c:40
sync_timeline_free drivers/dma-buf/sw_sync.c:113 [inline]
kref_put include/linux/kref.h:70 [inline]
sync_timeline_put+0x22/0x30 drivers/dma-buf/sw_sync.c:125
timeline_fence_release+0x1ec/0x2d0 drivers/dma-buf/sw_sync.c:153
dma_fence_release+0xd1/0x320 drivers/dma-buf/dma-fence.c:178
kref_put include/linux/kref.h:70 [inline]
dma_fence_put include/linux/dma-fence.h:197 [inline]
dma_fence_array_release+0x162/0x1f0 drivers/dma-buf/dma-fence-array.c:96
dma_fence_release+0xd1/0x320 drivers/dma-buf/dma-fence.c:178
kref_put include/linux/kref.h:70 [inline]
dma_fence_put include/linux/dma-fence.h:197 [inline]
irq_dma_fence_array_work+0x46/0x50 drivers/dma-buf/dma-fence-array.c:39
irq_work_run_list+0xf0/0x160 kernel/irq_work.c:156
irq_work_run+0x4e/0xc0 kernel/irq_work.c:171
smp_irq_work_interrupt+0xa3/0x4e0 arch/x86/kernel/irq_work.c:21
irq_work_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:824
</IRQ>
RIP: 0010:__raw_spin_unlock_irq include/linux/spinlock_api_smp.h:169 [inline]
RIP: 0010:_raw_spin_unlock_irq+0x50/0x80 kernel/locking/spinlock.c:200
RSP: 0018:ffff888091557ca0 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff09
RAX: 1ffffffff11e127b RBX: ffff8880ab91efe0 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffff8880b4952b84
RBP: ffff8880ab91f050 R08: ffff88823fff7018 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: dffffc0000000000
R13: ffff8880ab91f040 R14: ffff8880ab91f000 R15: ffff8880ab91f050
spin_unlock_irq include/linux/spinlock.h:367 [inline]
sw_sync_debugfs_release+0x12c/0x1a0 drivers/dma-buf/sw_sync.c:331
__fput+0x25f/0x7a0 fs/file_table.c:210
task_work_run+0x11f/0x190 kernel/task_work.c:113
exit_task_work include/linux/task_work.h:22 [inline]
do_exit+0xa44/0x2850 kernel/exit.c:868
do_group_exit+0x100/0x2e0 kernel/exit.c:965
SYSC_exit_group kernel/exit.c:976 [inline]
SyS_exit_group+0x19/0x20 kernel/exit.c:974
do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x46/0xbb
RIP: 0033:0x7f87f8bd5ed9
RSP: 002b:00007ffce1e6bef8 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
RAX: ffffffffffffffda RBX: 00007f87f8c4a2b0 RCX: 00007f87f8bd5ed9
RDX: 000000000000003c RSI: 00000000000000e7 RDI: 0000000000000000
RBP: 000000000
Reply all
Reply to author
Forward
0 new messages