syzbot


inconsistent lock state in sco_sock_timeout

Status: fixed on 2021/11/10 00:50
Reported-by: syzbot+2f6d7c28bb4bf7e82060@syzkaller.appspotmail.com
Fix commit: ba316be1b6a0 Bluetooth: schedule SCO timeouts with delayed_work
First crash: 683d, last: 337d

Cause bisection: introduced by (bisect log) :
commit 331c56ac73846fa267c04ee6aa9a00bb5fed9440
Author: Heiner Kallweit <hkallweit1@gmail.com>
Date: Mon Aug 12 21:51:27 2019 +0000

  net: phy: add phy_speed_down_core and phy_resolve_min_speed

Crash: general protection fault in batadv_iv_ogm_queue_add (log)
Repro: C syz .config
duplicates (1):
Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
inconsistent lock state in sco_conn_del C done 110 303d 687d 0/22 closed as dup on 2021/06/28 04:28
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 8d18h 690d 0/1 upstream: reported C repro on 2020/08/08 22:36
linux-4.19 inconsistent lock state in sco_sock_timeout C done 19 290d 681d 1/1 fixed on 2021/10/12 13:38
Patch testing requests:
Created Duration User Patch Repo Result
2021/08/04 03:19 18m desmondcheongzx@gmail.com patch git://git.kernel.org/pub/scm/linux/kernel/git/bluetooth/bluetooth-next.git master OK
2021/08/03 16:54 18m desmondcheongzx@gmail.com patch git://git.kernel.org/pub/scm/linux/kernel/git/bluetooth/bluetooth-next.git master report log
2021/08/03 11:41 18m desmondcheongzx@gmail.com patch upstream OK
2021/08/03 10:26 17m desmondcheongzx@gmail.com patch upstream report log
2021/08/03 09:41 13m desmondcheongzx@gmail.com patch upstream report log
2021/08/03 08:45 18m desmondcheongzx@gmail.com patch upstream report log
2021/08/03 08:29 0m desmondcheongzx@gmail.com patch upstream error
2021/08/03 04:38 18m desmondcheongzx@gmail.com patch upstream report log
2021/08/02 17:03 18m desmondcheongzx@gmail.com patch upstream report log
2021/08/02 15:57 16m desmondcheongzx@gmail.com patch upstream report log
2021/08/02 15:02 18m desmondcheongzx@gmail.com patch upstream report log
2021/08/02 13:23 15m desmondcheongzx@gmail.com patch upstream report log
2021/08/02 08:46 11m desmondcheongzx@gmail.com patch upstream report log
2021/08/02 05:06 18m desmondcheongzx@gmail.com patch upstream report log
2021/08/01 06:15 18m desmondcheongzx@gmail.com patch upstream report log
2021/08/01 04:13 18m desmondcheongzx@gmail.com patch upstream report log
2021/07/30 16:05 18m desmondcheongzx@gmail.com patch upstream report log
2021/07/30 08:38 0m desmondcheongzx@gmail.com patch upstream error
2021/07/29 12:14 23m desmondcheongzx@gmail.com patch upstream OK
2021/07/29 10:25 18m desmondcheongzx@gmail.com patch upstream report log
2021/07/28 03:44 19m desmondcheongzx@gmail.com patch upstream report log
2021/07/27 13:44 22m desmondcheongzx@gmail.com patch upstream OK
2021/07/21 03:24 21m desmondcheongzx@gmail.com patch upstream OK
2021/07/20 13:55 0m desmondcheongzx@gmail.com patch upstream error
2021/07/19 13:20 18m desmondcheongzx@gmail.com patch upstream report log
2021/07/19 11:08 19m desmondcheongzx@gmail.com patch upstream report log
2021/07/13 12:35 19m desmondcheongzx@gmail.com patch upstream OK
2021/07/13 09:35 18m desmondcheongzx@gmail.com patch upstream OK
2021/06/28 07:22 18m desmondcheongzx@gmail.com patch upstream OK
2021/06/28 06:37 18m desmondcheongzx@gmail.com patch upstream report log
2021/06/28 04:21 18m desmondcheongzx@gmail.com patch upstream OK

Sample crash report:
================================
WARNING: inconsistent lock state
5.13.0-rc7-syzkaller #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
syz-executor907/19672 [HC0[0]:SC1[1]:HE1:SE0] takes:
ffff88802ae750a0 (slock-AF_BLUETOOTH-BTPROTO_SCO){+.?.}-{2:2}, at: spin_lock include/linux/spinlock.h:354 [inline]
ffff88802ae750a0 (slock-AF_BLUETOOTH-BTPROTO_SCO){+.?.}-{2:2}, at: sco_sock_timeout+0x33/0x1b0 net/bluetooth/sco.c:83
{SOFTIRQ-ON-W} state was registered at:
  lock_acquire kernel/locking/lockdep.c:5514 [inline]
  lock_acquire+0x1ab/0x510 kernel/locking/lockdep.c:5479
  __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]
  sco_conn_del+0x134/0x2b0 net/bluetooth/sco.c:176
  sco_disconn_cfm+0x74/0xb0 net/bluetooth/sco.c:1189
  hci_disconn_cfm include/net/bluetooth/hci_core.h:1499 [inline]
  hci_conn_hash_flush+0x127/0x260 net/bluetooth/hci_conn.c:1608
  hci_dev_do_close+0x569/0x1110 net/bluetooth/hci_core.c:1785
  hci_unregister_dev+0x263/0x1130 net/bluetooth/hci_core.c:3999
  vhci_release+0x70/0xe0 drivers/bluetooth/hci_vhci.c:340
  __fput+0x288/0x920 fs/file_table.c:280
  task_work_run+0xdd/0x1a0 kernel/task_work.c:164
  exit_task_work include/linux/task_work.h:32 [inline]
  do_exit+0xbfc/0x2a60 kernel/exit.c:826
  do_group_exit+0x125/0x310 kernel/exit.c:923
  get_signal+0x47f/0x2150 kernel/signal.c:2850
  arch_do_signal_or_restart+0x2a8/0x1eb0 arch/x86/kernel/signal.c:789
  handle_signal_work kernel/entry/common.c:148 [inline]
  exit_to_user_mode_loop kernel/entry/common.c:172 [inline]
  exit_to_user_mode_prepare+0x180/0x290 kernel/entry/common.c:209
  __syscall_exit_to_user_mode_work kernel/entry/common.c:291 [inline]
  syscall_exit_to_user_mode+0x19/0x60 kernel/entry/common.c:302
  do_syscall_64+0x47/0xb0 arch/x86/entry/common.c:57
  entry_SYSCALL_64_after_hwframe+0x44/0xae
irq event stamp: 330
hardirqs last  enabled at (330): [<ffffffff8919982f>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
hardirqs last  enabled at (330): [<ffffffff8919982f>] _raw_spin_unlock_irq+0x1f/0x40 kernel/locking/spinlock.c:199
hardirqs last disabled at (329): [<ffffffff89199601>] __raw_spin_lock_irq include/linux/spinlock_api_smp.h:126 [inline]
hardirqs last disabled at (329): [<ffffffff89199601>] _raw_spin_lock_irq+0x41/0x50 kernel/locking/spinlock.c:167
softirqs last  enabled at (0): [<ffffffff8143a667>] copy_process+0x1d77/0x7120 kernel/fork.c:2062
softirqs last disabled at (323): [<ffffffff8145d326>] invoke_softirq kernel/softirq.c:433 [inline]
softirqs last disabled at (323): [<ffffffff8145d326>] __irq_exit_rcu+0x136/0x200 kernel/softirq.c:637

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 ***

2 locks held by syz-executor907/19672:
 #0: ffffffff8bf79860 (rcu_read_lock){....}-{1:2}, at: __do_sys_setpgid+0x85/0x770 kernel/sys.c:1037
 #1: ffffc90000dc0d70 ((&sk->sk_timer)){+.-.}-{0:0}, at: lockdep_copy_map include/linux/lockdep.h:35 [inline]
 #1: ffffc90000dc0d70 ((&sk->sk_timer)){+.-.}-{0:0}, at: call_timer_fn+0xd5/0x6b0 kernel/time/timer.c:1421

stack backtrace:
CPU: 1 PID: 19672 Comm: syz-executor907 Not tainted 5.13.0-rc7-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+0x141/0x1d7 lib/dump_stack.c:120
 print_usage_bug kernel/locking/lockdep.c:203 [inline]
 valid_state kernel/locking/lockdep.c:3822 [inline]
 mark_lock_irq kernel/locking/lockdep.c:4025 [inline]
 mark_lock.cold+0x61/0x8e kernel/locking/lockdep.c:4482
 mark_usage kernel/locking/lockdep.c:4377 [inline]
 __lock_acquire+0x11aa/0x5230 kernel/locking/lockdep.c:4858
 lock_acquire kernel/locking/lockdep.c:5514 [inline]
 lock_acquire+0x1ab/0x510 kernel/locking/lockdep.c:5479
 __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]
 sco_sock_timeout+0x33/0x1b0 net/bluetooth/sco.c:83
 call_timer_fn+0x1a5/0x6b0 kernel/time/timer.c:1431
 expire_timers kernel/time/timer.c:1476 [inline]
 __run_timers.part.0+0x67c/0xa50 kernel/time/timer.c:1745
 __run_timers kernel/time/timer.c:1726 [inline]
 run_timer_softirq+0xb3/0x1d0 kernel/time/timer.c:1758
 __do_softirq+0x29b/0x9f6 kernel/softirq.c:559
 invoke_softirq kernel/softirq.c:433 [inline]
 __irq_exit_rcu+0x136/0x200 kernel/softirq.c:637
 irq_exit_rcu+0x5/0x20 kernel/softirq.c:649
 sysvec_apic_timer_interrupt+0x93/0xc0 arch/x86/kernel/apic/apic.c:1100
 </IRQ>
 asm_sysvec_apic_timer_interrupt+0x12/0x20 arch/x86/include/asm/idtentry.h:647
RIP: 0010:__raw_write_unlock_irq include/linux/rwlock_api_smp.h:268 [inline]
RIP: 0010:_raw_write_unlock_irq+0x25/0x40 kernel/locking/spinlock.c:343
Code: 0f 1f 44 00 00 55 48 8b 74 24 08 48 89 fd 48 83 c7 18 e8 7e e2 40 f8 48 89 ef e8 56 5f 41 f8 e8 81 4a 61 f8 fb bf 01 00 00 00 <e8> 56 4f 35 f8 65 8b 05 2f 51 e8 76 85 c0 74 02 5d c3 e8 eb a6 e6
RSP: 0018:ffffc9002107fee8 EFLAGS: 00000206
RAX: 0000000000000141 RBX: ffff888029aa5a00 RCX: 1ffffffff1b927b9
RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000000001
RBP: ffffffff8bc0a080 R08: 0000000000000001 R09: 0000000000000001
R10: ffffffff817ae938 R11: 0000000000000000 R12: ffff88814cc81c40
R13: 0000000000000000 R14: ffff88814cc81c40 R15: ffff88814cc82460
 __do_sys_setpgid+0x1fd/0x770 kernel/sys.c:1092
 do_syscall_64+0x3a/0xb0 arch/x86/entry/common.c:47
 entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x470fc7
Code: 00 00 00 b8 68 00 00 00 0f 05 c3 0f 1f 84 00 00 00 00 00 b8 6c 00 00 00 0f 05 c3 0f 1f 84 00 00 00 00 00 b8 6d 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 c7 c1 b8 ff ff ff f7 d8 64 89 01 48
RSP: 002b:00007ffc2ff3e7b8 EFLAGS: 00000246 ORIG_RAX: 000000000000006d
RAX: ffffffffffffffda RBX: 00007ffc2ff3e990 RCX: 0000000000470fc7
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
RBP: 0000000000000000 R08: 0000000000000000 R09: 00000000004c9130
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000000f4240
R13: 00007ffc2ff3e7f0 R14: 00007ffc2ff3e990 R15: 00007ffc2ff3e870

Fix bisection attempts:
Manager Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Title
ci-upstream-kasan-gce-root 2021/07/28 01:13 upstream 7d549995d4e0 9d2ab5df .config log report syz C
ci-upstream-kasan-gce-root 2021/05/02 07:19 upstream 17ae69aba89d 94b45706 .config log report syz C
ci-upstream-kasan-gce-root 2020/12/28 10:46 upstream 5c8fe583cce5 94b45706 .config log report syz C
ci-upstream-kasan-gce-root 2020/11/28 10:19 upstream c84e1efae022 94b45706 .config log report syz C
ci-upstream-kasan-gce-root 2020/10/29 09:54 upstream 23859ae44402 94b45706 .config log report syz C
ci-upstream-kasan-gce-root 2020/09/19 00:15 upstream 92ab97adeefc 94b45706 .config log report syz C
Crashes (16):
Manager Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Title
ci-upstream-kasan-gce-root 2021/06/27 06:23 upstream 625acffd7ae2 9d2ab5df .config log report syz C inconsistent lock state in sco_sock_timeout
ci-upstream-kasan-gce-root 2021/06/23 08:24 upstream 0c18f29aae7c aba2b2fb .config log report syz C inconsistent lock state in sco_sock_timeout
ci-upstream-kasan-gce-root 2020/08/19 23:47 upstream 18445bf405cb 94b45706 .config log report syz C
ci-upstream-kasan-gce-smack-root 2020/08/17 07:58 upstream 2cc3c4b3c2e9 424dd8e7 .config log report syz C
ci-upstream-kasan-gce-smack-root 2021/06/14 01:58 upstream e4e453434a19 1ba81399 .config log report info inconsistent lock state in sco_sock_timeout
ci-upstream-kasan-gce-root 2021/05/25 14:12 upstream a050a6d2b7e8 3c7fef33 .config log report info inconsistent lock state in sco_sock_timeout
ci-upstream-kasan-gce-smack-root 2021/04/02 00:34 upstream ffd9fb546d49 6a81331a .config log report info inconsistent lock state in sco_sock_timeout
ci-upstream-kasan-gce-root 2021/03/10 19:02 upstream 05a59d79793d 764067f3 .config log report info inconsistent lock state in sco_sock_timeout
ci-upstream-kasan-gce-root 2021/02/04 13:30 upstream 61556703b610 42b90a7c .config log report info inconsistent lock state in sco_sock_timeout
ci-upstream-kasan-gce-root 2021/01/30 17:32 upstream 0e9bcda5d286 fc9fd31e .config log report info inconsistent lock state in sco_sock_timeout
ci-upstream-kasan-gce-smack-root 2021/01/22 04:04 upstream 9f29bd8b2e71 d4f4eca5 .config log report info inconsistent lock state in sco_sock_timeout
ci-qemu2-arm64-compat 2021/02/17 06:09 upstream f40ddce88593 98682e5e .config log report info inconsistent lock state in sco_sock_timeout
ci-upstream-kasan-gce-selinux-root 2020/09/29 09:28 upstream fb0155a09b02 1b88c6d5 .config log report info
ci-upstream-kasan-gce-selinux-root 2020/09/27 23:09 upstream a1bffa48745a 5dd8aee8 .config log report info
ci-upstream-kasan-gce-smack-root 2020/08/17 03:04 upstream 2cc3c4b3c2e9 424dd8e7 .config log report
ci-upstream-kasan-gce-root 2020/08/16 03:00 upstream c9c9735c46f5 424dd8e7 .config log report