syzbot


inconsistent lock state in io_dismantle_req

Status: fixed on 2021/04/09 19:46
Subsystems: fs io-uring
[Documentation on labels]
Reported-by: syzbot+81d17233a2b02eafba33@syzkaller.appspotmail.com
Fix commit: 9ae1f8dd372e io_uring: fix inconsistent lock state
First crash: 1372d, last: 1372d
Discussions (4)
Title Replies (including bot) Last reply
[PATCH 5.10 000/157] 5.10.26-rc1 review 167 (167) 2021/03/24 14:28
[PATCH 5.11 00/36] 5.11.6-rc1 review 45 (45) 2021/03/11 17:39
[PATCH 0/6] for-5.12 stuff 8 (8) 2021/02/01 20:11
inconsistent lock state in io_dismantle_req 1 (2) 2021/02/01 11:14
Cause bisection attempts (1)
Created Duration User Patch Repo Result
2021/02/01 08:38 0m (2) bisect linux-next error job log

Sample crash report:
================================
WARNING: inconsistent lock state
5.11.0-rc5-next-20210129-syzkaller #0 Not tainted
--------------------------------
inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage.
syz-executor217/8450 [HC1[1]:SC0[0]:HE0:SE1] takes:
ffff888023d6e620 (&fs->lock){?.+.}-{2:2}, at: spin_lock include/linux/spinlock.h:354 [inline]
ffff888023d6e620 (&fs->lock){?.+.}-{2:2}, at: io_req_clean_work fs/io_uring.c:1398 [inline]
ffff888023d6e620 (&fs->lock){?.+.}-{2:2}, at: io_dismantle_req+0x66f/0xf60 fs/io_uring.c:2029
{HARDIRQ-ON-W} state was registered at:
  lock_acquire kernel/locking/lockdep.c:5509 [inline]
  lock_acquire+0x1a8/0x720 kernel/locking/lockdep.c:5474
  __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
  _raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:151
  spin_lock include/linux/spinlock.h:354 [inline]
  set_fs_pwd+0x85/0x2a0 fs/fs_struct.c:39
  init_chdir+0xdf/0x127 fs/init.c:54
  devtmpfs_setup drivers/base/devtmpfs.c:418 [inline]
  devtmpfsd+0x76/0x333 drivers/base/devtmpfs.c:433
  kthread+0x3b1/0x4a0 kernel/kthread.c:292
  ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:296
irq event stamp: 786
hardirqs last  enabled at (785): [<ffffffff8903de4f>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
hardirqs last  enabled at (785): [<ffffffff8903de4f>] _raw_spin_unlock_irq+0x1f/0x40 kernel/locking/spinlock.c:199
hardirqs last disabled at (786): [<ffffffff8901704c>] sysvec_apic_timer_interrupt+0xc/0x100 arch/x86/kernel/apic/apic.c:1096
softirqs last  enabled at (664): [<ffffffff87abbe04>] read_pnet include/net/net_namespace.h:324 [inline]
softirqs last  enabled at (664): [<ffffffff87abbe04>] sock_net include/net/sock.h:2550 [inline]
softirqs last  enabled at (664): [<ffffffff87abbe04>] unix_create1+0x484/0x570 net/unix/af_unix.c:814
softirqs last disabled at (662): [<ffffffff87abbd81>] unix_sockets_unbound net/unix/af_unix.c:133 [inline]
softirqs last disabled at (662): [<ffffffff87abbd81>] unix_create1+0x401/0x570 net/unix/af_unix.c:808

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

       CPU0
       ----
  lock(&fs->lock);
  <Interrupt>
    lock(&fs->lock);

 *** DEADLOCK ***

1 lock held by syz-executor217/8450:
 #0: ffff88802417c3e8 (&ctx->uring_lock){+.+.}-{3:3}, at: __do_sys_io_uring_enter+0x1071/0x1f30 fs/io_uring.c:9442

stack backtrace:
CPU: 1 PID: 8450 Comm: syz-executor217 Not tainted 5.11.0-rc5-next-20210129-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:79 [inline]
 dump_stack+0x107/0x163 lib/dump_stack.c:120
 print_usage_bug kernel/locking/lockdep.c:3806 [inline]
 valid_state kernel/locking/lockdep.c:3817 [inline]
 mark_lock_irq kernel/locking/lockdep.c:4020 [inline]
 mark_lock.cold+0x61/0x8e kernel/locking/lockdep.c:4477
 mark_usage kernel/locking/lockdep.c:4369 [inline]
 __lock_acquire+0x1468/0x54c0 kernel/locking/lockdep.c:4853
 lock_acquire kernel/locking/lockdep.c:5509 [inline]
 lock_acquire+0x1a8/0x720 kernel/locking/lockdep.c:5474
 __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
 _raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:151
 spin_lock include/linux/spinlock.h:354 [inline]
 io_req_clean_work fs/io_uring.c:1398 [inline]
 io_dismantle_req+0x66f/0xf60 fs/io_uring.c:2029
 __io_free_req+0x3d/0x2e0 fs/io_uring.c:2046
 io_free_req fs/io_uring.c:2269 [inline]
 io_double_put_req fs/io_uring.c:2392 [inline]
 io_put_req+0xf9/0x570 fs/io_uring.c:2388
 io_link_timeout_fn+0x30c/0x480 fs/io_uring.c:6497
 __run_hrtimer kernel/time/hrtimer.c:1519 [inline]
 __hrtimer_run_queues+0x609/0xe40 kernel/time/hrtimer.c:1583
 hrtimer_interrupt+0x334/0x940 kernel/time/hrtimer.c:1645
 local_apic_timer_interrupt arch/x86/kernel/apic/apic.c:1085 [inline]
 __sysvec_apic_timer_interrupt+0x146/0x540 arch/x86/kernel/apic/apic.c:1102
 asm_call_irq_on_stack+0xf/0x20
 </IRQ>
 __run_sysvec_on_irqstack arch/x86/include/asm/irq_stack.h:37 [inline]
 run_sysvec_on_irqstack_cond arch/x86/include/asm/irq_stack.h:89 [inline]
 sysvec_apic_timer_interrupt+0xbd/0x100 arch/x86/kernel/apic/apic.c:1096
 asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:629
RIP: 0010:__raw_spin_unlock_irq include/linux/spinlock_api_smp.h:169 [inline]
RIP: 0010:_raw_spin_unlock_irq+0x25/0x40 kernel/locking/spinlock.c:199
Code: 0f 1f 44 00 00 55 48 8b 74 24 08 48 89 fd 48 83 c7 18 e8 de 04 55 f8 48 89 ef e8 36 ba 55 f8 e8 71 16 75 f8 fb bf 01 00 00 00 <e8> 76 b9 49 f8 65 8b 05 5f 11 fe 76 85 c0 74 02 5d c3 e8 cb 66 fc
RSP: 0018:ffffc9000166f978 EFLAGS: 00000206
RAX: 0000000000000311 RBX: ffff8881416eaa00 RCX: 1ffffffff1df7d02
RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000000001
RBP: ffff88802417c480 R08: 0000000000000001 R09: ffffffff8ef738e7
R10: 0000000000000001 R11: 0000000000000000 R12: ffff88802417c480
R13: 0000000000000000 R14: 0000000000000001 R15: 0000000000000000
 spin_unlock_irq include/linux/spinlock.h:404 [inline]
 io_queue_linked_timeout+0x194/0x1f0 fs/io_uring.c:6525
 __io_queue_sqe+0x328/0x1290 fs/io_uring.c:6594
 io_queue_sqe+0x631/0x10d0 fs/io_uring.c:6639
 io_queue_link_head fs/io_uring.c:6650 [inline]
 io_submit_sqe fs/io_uring.c:6697 [inline]
 io_submit_sqes+0x19b5/0x2720 fs/io_uring.c:6960
 __do_sys_io_uring_enter+0x107d/0x1f30 fs/io_uring.c:9443
 do_syscall_64+0x2d/0x70 arch/x86/entry/common.c:46
 entry_SYSCALL_64_after_hwframe+0x44/0xa9
RIP: 0033:0x441619
Code: e8 fc ab 02 00 48 83 c4 18 c3 0f 1f 80 00 00 00 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 0f 83 1b 09 fc ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007ffc10aa3e28 EFLAGS: 00000246 ORIG_RAX: 00000000000001aa
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 0000000000441619
RDX: 0000000000000000 RSI: 0000000000004510 RDI: 0000000000000003
RBP: 00000000006cc018 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000004023c0
R13: 0000000000402450 R14: 0000000000000000 R15: 0000000000000000

Crashes (2):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2021/02/01 06:48 linux-next b01f250d83f6 fc9fd31e .config console log report syz C ci-upstream-linux-next-kasan-gce-root inconsistent lock state in io_dismantle_req
2021/02/01 06:23 linux-next b01f250d83f6 fc9fd31e .config console log report info ci-upstream-linux-next-kasan-gce-root inconsistent lock state in io_dismantle_req
* Struck through repros no longer work on HEAD.