syzbot


inconsistent lock state in sco_sock_timeout

Status: fixed on 2021/10/12 13:38
Reported-by: syzbot+3257b5a27d60dc9d951d@syzkaller.appspotmail.com
Fix commit: 48669c81a656 Bluetooth: schedule SCO timeouts with delayed_work
First crash: 1345d, last: 954d
Fix bisection: fixed by (bisect log) :
commit 48669c81a65628ef234cbdd91b9395952c7c27fe
Author: Desmond Cheong Zhi Xi <desmondcheongzx@gmail.com>
Date: Tue Aug 10 04:14:05 2021 +0000

  Bluetooth: schedule SCO timeouts with delayed_work

  
Similar bugs (2)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
linux-4.14 inconsistent lock state in sco_sock_timeout C 14 429d 1353d 0/1 upstream: reported C repro on 2020/08/08 22:36
upstream inconsistent lock state in sco_sock_timeout bluetooth C done 16 1000d 1345d 20/26 fixed on 2021/11/10 00:50
Fix bisection attempts (9)
Created Duration User Patch Repo Result
2021/10/12 07:40 5h22m bisect fix linux-4.19.y job log (1)
2021/08/24 14:53 38m bisect fix linux-4.19.y job log (0) log
2021/07/19 04:57 39m bisect fix linux-4.19.y job log (0) log
2021/06/10 04:40 32m bisect fix linux-4.19.y job log (0) log
2021/04/17 18:15 35m bisect fix linux-4.19.y job log (0) log
2021/02/23 17:41 35m bisect fix linux-4.19.y job log (0) log
2020/12/10 06:19 46m bisect fix linux-4.19.y job log (0) log
2020/11/05 05:27 35m bisect fix linux-4.19.y job log (0) log
2020/10/06 00:59 33m bisect fix linux-4.19.y job log (0) log

Sample crash report:
================================
WARNING: inconsistent lock state
4.19.164-syzkaller #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
swapper/0/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
0000000082a52b3a (slock-AF_BLUETOOTH-BTPROTO_SCO){+.?.}, at: spin_lock include/linux/spinlock.h:329 [inline]
0000000082a52b3a (slock-AF_BLUETOOTH-BTPROTO_SCO){+.?.}, at: sco_sock_timeout+0x31/0x210 net/bluetooth/sco.c:82
{SOFTIRQ-ON-W} state was registered at:
  __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
  _raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:144
  spin_lock include/linux/spinlock.h:329 [inline]
  sco_conn_del+0xe2/0x240 net/bluetooth/sco.c:175
  sco_disconn_cfm+0x74/0xb0 net/bluetooth/sco.c:1133
  hci_disconn_cfm include/net/bluetooth/hci_core.h:1261 [inline]
  hci_conn_hash_flush+0x127/0x260 net/bluetooth/hci_conn.c:1512
  hci_dev_do_close+0x659/0xf10 net/bluetooth/hci_core.c:1666
  hci_unregister_dev+0x18b/0x910 net/bluetooth/hci_core.c:3271
  vhci_release+0x70/0xe0 drivers/bluetooth/hci_vhci.c:354
  __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+0xbed/0x2be0 kernel/exit.c:890
  do_group_exit+0x125/0x310 kernel/exit.c:993
  get_signal+0x3f2/0x1f70 kernel/signal.c:2589
  do_signal+0x8f/0x1670 arch/x86/kernel/signal.c:821
  exit_to_usermode_loop+0x204/0x2a0 arch/x86/entry/common.c:163
  prepare_exit_to_usermode arch/x86/entry/common.c:198 [inline]
  syscall_return_slowpath arch/x86/entry/common.c:271 [inline]
  do_syscall_64+0x538/0x620 arch/x86/entry/common.c:296
  entry_SYSCALL_64_after_hwframe+0x49/0xbe
irq event stamp: 1142346
hardirqs last  enabled at (1142346): [<ffffffff81004313>] trace_hardirqs_on_thunk+0x1a/0x1c
hardirqs last disabled at (1142345): [<ffffffff8100432f>] trace_hardirqs_off_thunk+0x1a/0x1c
softirqs last  enabled at (1142334): [<ffffffff813a3acd>] irq_enter+0xbd/0xd0 kernel/softirq.c:354
softirqs last disabled at (1142335): [<ffffffff813a3cf5>] invoke_softirq kernel/softirq.c:372 [inline]
softirqs last disabled at (1142335): [<ffffffff813a3cf5>] irq_exit+0x215/0x260 kernel/softirq.c:412

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

       CPU0
       ----
  lock(slock-AF_BLUETOOTH-BTPROTO_SCO);
  <Interrupt>
    lock(slock-AF_BLUETOOTH-BTPROTO_SCO);

 *** DEADLOCK ***

1 lock held by swapper/0/0:
 #0: 00000000d9df0ada ((&sk->sk_timer)){+.-.}, at: lockdep_copy_map include/linux/lockdep.h:168 [inline]
 #0: 00000000d9df0ada ((&sk->sk_timer)){+.-.}, at: call_timer_fn+0xc9/0x700 kernel/time/timer.c:1328

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.164-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/0x2fe lib/dump_stack.c:118
 print_usage_bug.cold+0x42e/0x570 kernel/locking/lockdep.c:2544
 valid_state kernel/locking/lockdep.c:2557 [inline]
 mark_lock_irq kernel/locking/lockdep.c:2751 [inline]
 mark_lock+0xc70/0x1160 kernel/locking/lockdep.c:3131
 mark_irqflags kernel/locking/lockdep.c:3009 [inline]
 __lock_acquire+0xdc4/0x3ff0 kernel/locking/lockdep.c:3372
 lock_acquire+0x170/0x3c0 kernel/locking/lockdep.c:3907
 __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
 _raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:144
 spin_lock include/linux/spinlock.h:329 [inline]
 sco_sock_timeout+0x31/0x210 net/bluetooth/sco.c:82
 call_timer_fn+0x177/0x700 kernel/time/timer.c:1338
 expire_timers+0x243/0x4e0 kernel/time/timer.c:1375
 __run_timers kernel/time/timer.c:1696 [inline]
 run_timer_softirq+0x21c/0x670 kernel/time/timer.c:1709
 __do_softirq+0x26c/0x9a0 kernel/softirq.c:292
 invoke_softirq kernel/softirq.c:372 [inline]
 irq_exit+0x215/0x260 kernel/softirq.c:412
 exiting_irq arch/x86/include/asm/apic.h:545 [inline]
 smp_apic_timer_interrupt+0x136/0x550 arch/x86/kernel/apic/apic.c:1094
 apic_timer_interrupt+0xf/0x20 arch/x86/entry/entry_64.S:894
 </IRQ>
RIP: 0010:native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:61
Code: 48 89 df e8 44 1f 85 f9 e9 2e ff ff ff 48 89 df e8 37 1f 85 f9 eb 82 90 90 90 90 90 e9 07 00 00 00 0f 00 2d 14 aa 51 00 fb f4 <c3> 90 e9 07 00 00 00 0f 00 2d 04 aa 51 00 f4 c3 90 90 41 56 41 55
RSP: 0018:ffffffff89e07d40 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
RAX: 1ffffffff13e3034 RBX: dffffc0000000000 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffffffff89e78904
RBP: 0000000000000000 R08: 0000000000000001 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff89f18190
R13: 1ffffffff13c0fb2 R14: 0000000000000000 R15: 0000000000000000
 arch_safe_halt arch/x86/include/asm/paravirt.h:94 [inline]
 default_idle+0x49/0x310 arch/x86/kernel/process.c:557
 cpuidle_idle_call kernel/sched/idle.c:153 [inline]
 do_idle+0x2ec/0x4b0 kernel/sched/idle.c:263
 cpu_startup_entry+0xc5/0xe0 kernel/sched/idle.c:369
 start_kernel+0x8d6/0x911 init/main.c:736
 secondary_startup_64+0xa4/0xb0 arch/x86/kernel/head_64.S:243

Crashes (19):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2021/01/03 14:48 linux-4.19.y 3207316b3bee 79264ae3 .config console log report syz C ci2-linux-4-19
2020/09/06 00:59 linux-4.19.y c37da90efff5 abf9ba4f .config console log report syz C ci2-linux-4-19
2021/09/12 07:39 linux-4.19.y b172b44fcb17 3ce60af8 .config console log report syz ci2-linux-4-19 inconsistent lock state in sco_sock_timeout
2020/08/17 18:32 linux-4.19.y c14d30dc9987 5ce13532 .config console log report syz ci2-linux-4-19
2021/09/08 21:25 linux-4.19.y b172b44fcb17 e2776ee4 .config console log report info ci2-linux-4-19 inconsistent lock state in sco_sock_timeout
2021/07/25 14:12 linux-4.19.y 4938296e03bd 4d1b57d4 .config console log report info ci2-linux-4-19 inconsistent lock state in sco_sock_timeout
2021/06/19 04:57 linux-4.19.y eb575cd5d7f6 aba2b2fb .config console log report info ci2-linux-4-19 inconsistent lock state in sco_sock_timeout
2021/06/18 14:37 linux-4.19.y eb575cd5d7f6 aba2b2fb .config console log report info ci2-linux-4-19 inconsistent lock state in sco_sock_timeout
2021/06/16 06:43 linux-4.19.y 9a2dc0e6c531 990d3cbe .config console log report info ci2-linux-4-19 inconsistent lock state in sco_sock_timeout
2021/06/12 17:32 linux-4.19.y 9a2dc0e6c531 1ba81399 .config console log report info ci2-linux-4-19 inconsistent lock state in sco_sock_timeout
2021/05/11 04:40 linux-4.19.y 3c8c23092588 ca873091 .config console log report info ci2-linux-4-19 inconsistent lock state in sco_sock_timeout
2021/03/18 18:15 linux-4.19.y ac3af4beac43 7216542e .config console log report info ci2-linux-4-19 inconsistent lock state in sco_sock_timeout
2021/02/27 08:59 linux-4.19.y 2d19be4653f5 4c37c133 .config console log report info ci2-linux-4-19 inconsistent lock state in sco_sock_timeout
2021/01/21 17:11 linux-4.19.y 43d555d83c3f d4f4eca5 .config console log report info ci2-linux-4-19 inconsistent lock state in sco_sock_timeout
2021/01/12 01:09 linux-4.19.y 610bdbf6a174 2c1f2513 .config console log report info ci2-linux-4-19
2021/01/03 20:31 linux-4.19.y 3207316b3bee 79264ae3 .config console log report info ci2-linux-4-19
2020/12/15 10:50 linux-4.19.y 13d2ce42de8c 97183ed7 .config console log report info ci2-linux-4-19
2020/12/12 07:36 linux-4.19.y 13d2ce42de8c bca53db9 .config console log report info ci2-linux-4-19
2020/11/10 06:19 linux-4.19.y b94de4d19498 cba33199 .config console log report info ci2-linux-4-19
* Struck through repros no longer work on HEAD.