syzbot

 sign-in | mailing list | source | docs
🐞 Open [717] 🐞 Fixed [181] 🐞 Invalid [640] 📈 Kernel Health 📈 Bug Lifetimes 📈 Fuzzing 📈 Crashes 💬 Send us feedback

possible deadlock in hci_dev_do_close

Status: auto-closed as invalid on 2021/08/21 08:03
Reported-by: syzbot+e73e6633d2b34f0bcffe@syzkaller.appspotmail.com
First crash: 1344d, last: 1106d
▶ ▼ Similar bugs (5)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream possible deadlock in hci_dev_do_close (2) bluetooth C done 10 1d18h 6d23h 0/26 upstream: reported C repro on 2024/04/26 13:39
upstream possible deadlock in hci_dev_do_close bluetooth C done done 6476 133d 221d 0/26 closed as dup on 2024/02/02 20:04
linux-4.14 possible deadlock in hci_dev_do_close (3) 1 547d 547d 0/1 auto-obsoleted due to no activity on 2023/03/03 05:50
linux-4.14 possible deadlock in hci_dev_do_close (2) 1 841d 841d 0/1 auto-closed as invalid on 2022/05/12 19:44
linux-5.15 possible deadlock in hci_dev_do_close origin:upstream missing-backport C inconclusive 3538 4h40m 191d 0/3 upstream: reported C repro on 2023/10/25 12:10

Sample crash report:
======================================================
WARNING: possible circular locking dependency detected
4.14.231-syzkaller #0 Not tainted
audit: type=1804 audit(1619164964.952:13): pid=10290 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="ToMToU" comm="syz-executor.5" name="/root/syzkaller-testdir470597845/syzkaller.BRpKU0/18/file0/file0" dev="sda1" ino=14014 res=1
------------------------------------------------------
syz-executor.4/10335 is trying to acquire lock:
 ("%s"hdev->name#2){+.+.}, at: [<ffffffff81366797>] start_flush_work kernel/workqueue.c:2860 [inline]
 ("%s"hdev->name#2){+.+.}, at: [<ffffffff81366797>] flush_work+0x387/0x770 kernel/workqueue.c:2892

but task is already holding lock:
 (&hdev->lock){+.+.}, at: [<ffffffff866011ec>] hci_dev_do_close+0x21c/0xca0 net/bluetooth/hci_core.c:1609

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:
audit: type=1804 audit(1619164964.962:14): pid=10290 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="open_writers" comm="syz-executor.5" name="/root/syzkaller-testdir470597845/syzkaller.BRpKU0/18/file0/file0" dev="sda1" ino=14014 res=1

-> #2 (&hdev->lock){+.+.}:
       __mutex_lock_common kernel/locking/mutex.c:756 [inline]
       __mutex_lock+0xc4/0x1310 kernel/locking/mutex.c:893
       hci_cc_write_scan_enable net/bluetooth/hci_event.c:375 [inline]
       hci_cmd_complete_evt+0x4d34/0xb490 net/bluetooth/hci_event.c:2831
audit: type=1804 audit(1619164964.962:15): pid=10305 uid=0 auid=4294967295 ses=4294967295 op="invalid_pcr" cause="ToMToU" comm="syz-executor.5" name="/root/syzkaller-testdir470597845/syzkaller.BRpKU0/18/file0/file0" dev="sda1" ino=14014 res=1
       hci_event_packet+0x21ce/0x7510 net/bluetooth/hci_event.c:5330
       hci_rx_work+0x427/0xb40 net/bluetooth/hci_core.c:4246
       process_one_work+0x793/0x14a0 kernel/workqueue.c:2116
audit: type=1800 audit(1619164965.272:16): pid=10365 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.0" name="bus" dev="sda1" ino=13884 res=0
       worker_thread+0x5cc/0xff0 kernel/workqueue.c:2250
       kthread+0x30d/0x420 kernel/kthread.c:232
       ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404
audit: type=1800 audit(1619164965.272:17): pid=10365 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.0" name="bus" dev="sda1" ino=13884 res=0

-> #1 ((&hdev->rx_work)){+.+.}:
       process_one_work+0x736/0x14a0 kernel/workqueue.c:2092
       worker_thread+0x5cc/0xff0 kernel/workqueue.c:2250
       kthread+0x30d/0x420 kernel/kthread.c:232
       ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404

-> #0 ("%s"hdev->name#2){+.+.}:
       lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
       start_flush_work kernel/workqueue.c:2861 [inline]
       flush_work+0x3ac/0x770 kernel/workqueue.c:2892
       __cancel_work_timer+0x321/0x460 kernel/workqueue.c:2964
       hci_conn_del+0x52/0x6f0 net/bluetooth/hci_conn.c:575
       hci_conn_hash_flush+0x19c/0x260 net/bluetooth/hci_conn.c:1394
       hci_dev_do_close+0x535/0xca0 net/bluetooth/hci_core.c:1622
       hci_rfkill_set_block+0xaf/0x120 net/bluetooth/hci_core.c:2052
       rfkill_set_block+0x1b2/0x4a0 net/rfkill/core.c:337
       rfkill_fop_write+0x1b6/0x3c0 net/rfkill/core.c:1233
       do_loop_readv_writev fs/read_write.c:698 [inline]
       do_loop_readv_writev fs/read_write.c:682 [inline]
       do_iter_write+0x3da/0x550 fs/read_write.c:956
       vfs_writev+0x125/0x290 fs/read_write.c:999
       do_writev+0xfc/0x2c0 fs/read_write.c:1034
       do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
       entry_SYSCALL_64_after_hwframe+0x46/0xbb

other info that might help us debug this:

Chain exists of:
  "%s"hdev->name#2 --> (&hdev->rx_work) --> &hdev->lock

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&hdev->lock);
                               lock((&hdev->rx_work));
                               lock(&hdev->lock);
  lock("%s"hdev->name#2);

 *** DEADLOCK ***

3 locks held by syz-executor.4/10335:
 #0:  (rfkill_global_mutex){+.+.}, at: [<ffffffff86d4e17f>] rfkill_fop_write+0xbf/0x3c0 net/rfkill/core.c:1225
 #1:  (&hdev->req_lock){+.+.}, at: [<ffffffff866010d9>] hci_dev_do_close+0x109/0xca0 net/bluetooth/hci_core.c:1578
 #2:  (&hdev->lock){+.+.}, at: [<ffffffff866011ec>] hci_dev_do_close+0x21c/0xca0 net/bluetooth/hci_core.c:1609

stack backtrace:
CPU: 1 PID: 10335 Comm: syz-executor.4 Not tainted 4.14.231-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 __dump_stack lib/dump_stack.c:17 [inline]
 dump_stack+0x1b2/0x281 lib/dump_stack.c:58
 print_circular_bug.constprop.0.cold+0x2d7/0x41e kernel/locking/lockdep.c:1258
 check_prev_add kernel/locking/lockdep.c:1905 [inline]
 check_prevs_add kernel/locking/lockdep.c:2022 [inline]
 validate_chain kernel/locking/lockdep.c:2464 [inline]
 __lock_acquire+0x2e0e/0x3f20 kernel/locking/lockdep.c:3491
 lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
 start_flush_work kernel/workqueue.c:2861 [inline]
 flush_work+0x3ac/0x770 kernel/workqueue.c:2892
 __cancel_work_timer+0x321/0x460 kernel/workqueue.c:2964
 hci_conn_del+0x52/0x6f0 net/bluetooth/hci_conn.c:575
 hci_conn_hash_flush+0x19c/0x260 net/bluetooth/hci_conn.c:1394
 hci_dev_do_close+0x535/0xca0 net/bluetooth/hci_core.c:1622
 hci_rfkill_set_block+0xaf/0x120 net/bluetooth/hci_core.c:2052
 rfkill_set_block+0x1b2/0x4a0 net/rfkill/core.c:337
 rfkill_fop_write+0x1b6/0x3c0 net/rfkill/core.c:1233
 do_loop_readv_writev fs/read_write.c:698 [inline]
 do_loop_readv_writev fs/read_write.c:682 [inline]
 do_iter_write+0x3da/0x550 fs/read_write.c:956
 vfs_writev+0x125/0x290 fs/read_write.c:999
 do_writev+0xfc/0x2c0 fs/read_write.c:1034
 do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
 entry_SYSCALL_64_after_hwframe+0x46/0xbb
RIP: 0033:0x4665f9
RSP: 002b:00007f94473ac188 EFLAGS: 00000246 ORIG_RAX: 0000000000000014
RAX: ffffffffffffffda RBX: 000000000056c008 RCX: 00000000004665f9
RDX: 0000000000000001 RSI: 0000000020000000 RDI: 0000000000000005
RBP: 00000000004bfbb9 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000056c008
R13: 00007ffe98e8b99f R14: 00007f94473ac300 R15: 0000000000022000
EXT4-fs (loop4): mounted filesystem without journal. Opts: resgid=0x0000000000000000,stripe=0x0000000000000003,nojournal_checksum,inode_readahead_blks=0x0000000002000000,,errors=continue
EXT4-fs (loop5): VFS: Can't find ext4 filesystem
EXT4-fs (loop5): VFS: Can't find ext4 filesystem
audit: type=1800 audit(1619164966.542:18): pid=10463 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.0" name="bus" dev="sda1" ino=14025 res=0
audit: type=1800 audit(1619164966.542:19): pid=10463 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.0" name="bus" dev="sda1" ino=14025 res=0
EXT4-fs (loop5): VFS: Can't find ext4 filesystem
EXT4-fs (loop5): VFS: Can't find ext4 filesystem
kauditd_printk_skb: 22 callbacks suppressed
audit: type=1800 audit(1619164970.452:42): pid=10805 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.0" name="bus" dev="sda1" ino=14079 res=0
audit: type=1800 audit(1619164970.452:43): pid=10805 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.0" name="bus" dev="sda1" ino=14079 res=0
audit: type=1800 audit(1619164970.622:44): pid=10832 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.0" name="bus" dev="sda1" ino=14080 res=0
audit: type=1800 audit(1619164970.632:45): pid=10832 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.0" name="bus" dev="sda1" ino=14080 res=0
audit: type=1800 audit(1619164970.742:46): pid=10839 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.0" name="bus" dev="sda1" ino=14075 res=0
audit: type=1800 audit(1619164970.762:47): pid=10839 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.0" name="bus" dev="sda1" ino=14075 res=0
audit: type=1800 audit(1619164971.292:48): pid=10851 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.0" name="bus" dev="sda1" ino=14095 res=0
audit: type=1800 audit(1619164971.302:49): pid=10851 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.0" name="bus" dev="sda1" ino=14095 res=0
audit: type=1800 audit(1619164971.562:50): pid=10898 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.0" name="bus" dev="sda1" ino=14099 res=0
audit: type=1800 audit(1619164971.602:51): pid=10898 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed(directio)" comm="syz-executor.0" name="bus" dev="sda1" ino=14099 res=0

Crashes (11):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2021/04/23 08:02 linux-4.14.y cf256fbcbe34 590921a5 .config console log report info ci2-linux-4-14 possible deadlock in hci_dev_do_close
2021/04/20 05:56 linux-4.14.y cf256fbcbe34 4285c989 .config console log report info ci2-linux-4-14 possible deadlock in hci_dev_do_close
2021/04/11 04:38 linux-4.14.y 958e517f4e16 6a81331a .config console log report info ci2-linux-4-14 possible deadlock in hci_dev_do_close
2021/02/09 09:48 linux-4.14.y 2c8a3fceddf0 2bd9619f .config console log report info ci2-linux-4-14 possible deadlock in hci_dev_do_close
2021/02/02 10:01 linux-4.14.y 2c8a3fceddf0 19e09687 .config console log report info ci2-linux-4-14 possible deadlock in hci_dev_do_close
2021/01/17 14:08 linux-4.14.y 2762b48e9611 813be542 .config console log report info ci2-linux-4-14
2020/11/15 19:07 linux-4.14.y 27ce4f2a6817 1bf9a662 .config console log report info ci2-linux-4-14
2020/10/17 13:19 linux-4.14.y cbfa1702aaf6 fea47c01 .config console log report info ci2-linux-4-14
2020/10/15 21:22 linux-4.14.y cbfa1702aaf6 6e262c73 .config console log report info ci2-linux-4-14
2020/10/01 10:39 linux-4.14.y cbfa1702aaf6 4103fce0 .config console log report info ci2-linux-4-14
2020/08/27 15:12 linux-4.14.y d7e78d08fa77 816e0689 .config console log report ci2-linux-4-14
* Struck through repros no longer work on HEAD.