syzbot


possible deadlock in hci_dev_do_close (3)

Status: auto-obsoleted due to no activity on 2023/03/03 05:50
Reported-by: syzbot+8d00f69df9477da181ba@syzkaller.appspotmail.com
First crash: 532d, last: 532d
Similar bugs (4)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream possible deadlock in hci_dev_do_close bluetooth C done done 6476 118d 206d 0/26 closed as dup on 2024/02/02 20:04
linux-4.14 possible deadlock in hci_dev_do_close 11 1091d 1330d 0/1 auto-closed as invalid on 2021/08/21 08:03
linux-4.14 possible deadlock in hci_dev_do_close (2) 1 827d 827d 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 3205 5h32m 176d 0/3 upstream: reported C repro on 2023/10/25 12:10

Sample crash report:
EXT4-fs (loop1): VFS: Can't find ext4 filesystem
======================================================
WARNING: possible circular locking dependency detected
4.14.297-syzkaller #0 Not tainted
------------------------------------------------------
syz-executor.3/14694 is trying to acquire lock:
 ("%s"hdev->name#2){+.+.}, at: [<ffffffff81368c97>] start_flush_work kernel/workqueue.c:2861 [inline]
 ("%s"hdev->name#2){+.+.}, at: [<ffffffff81368c97>] flush_work+0x387/0x770 kernel/workqueue.c:2893

but task is already holding lock:
 (&hdev->lock){+.+.}, at: [<ffffffff8661b224>] hci_dev_do_close+0x264/0xd80 net/bluetooth/hci_core.c:1628

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #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
       hci_event_packet+0x21ce/0x7510 net/bluetooth/hci_event.c:5353
       hci_rx_work+0x427/0xb40 net/bluetooth/hci_core.c:4266
       process_one_work+0x793/0x14a0 kernel/workqueue.c:2117
       worker_thread+0x5cc/0xff0 kernel/workqueue.c:2251
       kthread+0x30d/0x420 kernel/kthread.c:232
       ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:406

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

-> #0 ("%s"hdev->name#2){+.+.}:
       lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
       start_flush_work kernel/workqueue.c:2862 [inline]
       flush_work+0x3ac/0x770 kernel/workqueue.c:2893
       __cancel_work_timer+0x321/0x460 kernel/workqueue.c:2965
       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+0x57d/0xd80 net/bluetooth/hci_core.c:1641
       hci_rfkill_set_block+0xaf/0x120 net/bluetooth/hci_core.c:2071
       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+0x5e/0xd3

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.3/14694:
 #0:  (rfkill_global_mutex){+.+.}, at: [<ffffffff86d6c3ef>] rfkill_fop_write+0xbf/0x3c0 net/rfkill/core.c:1225
 #1:  (&hdev->req_lock){+.+.}, at: [<ffffffff8661b068>] hci_dev_do_close+0xa8/0xd80 net/bluetooth/hci_core.c:1589
 #2:  (&hdev->lock){+.+.}, at: [<ffffffff8661b224>] hci_dev_do_close+0x264/0xd80 net/bluetooth/hci_core.c:1628

stack backtrace:
CPU: 0 PID: 14694 Comm: syz-executor.3 Not tainted 4.14.297-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/11/2022
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:2862 [inline]
 flush_work+0x3ac/0x770 kernel/workqueue.c:2893
 __cancel_work_timer+0x321/0x460 kernel/workqueue.c:2965
 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+0x57d/0xd80 net/bluetooth/hci_core.c:1641
 hci_rfkill_set_block+0xaf/0x120 net/bluetooth/hci_core.c:2071
 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+0x5e/0xd3
EXT4-fs (loop2): VFS: Can't find ext4 filesystem
EXT4-fs (loop4): VFS: Can't find ext4 filesystem
EXT4-fs (loop5): VFS: Can't find ext4 filesystem
EXT4-fs (loop1): VFS: Can't find ext4 filesystem
EXT4-fs (loop5): VFS: Can't find ext4 filesystem
EXT4-fs (loop4): VFS: Can't find ext4 filesystem
EXT4-fs (loop2): VFS: Can't find ext4 filesystem
MTD: Attempt to mount non-MTD device "/dev/loop2"
romfs: Mounting image 'rom 5f663c08' through the block layer
audit: type=1800 audit(1667454585.860:67): pid=14904 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed" comm="syz-executor.2" name="file0" dev="loop2" ino=128 res=0
MTD: Attempt to mount non-MTD device "/dev/loop2"
MTD: Attempt to mount non-MTD device "/dev/loop1"
romfs: Mounting image 'rom 5f663c08' through the block layer
romfs: Mounting image 'rom 5f663c08' through the block layer
audit: type=1800 audit(1667454586.100:68): pid=14934 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed" comm="syz-executor.2" name="file0" dev="loop2" ino=128 res=0
audit: type=1800 audit(1667454586.100:69): pid=14938 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed" comm="syz-executor.1" name="file0" dev="loop1" ino=128 res=0
MTD: Attempt to mount non-MTD device "/dev/loop2"
MTD: Attempt to mount non-MTD device "/dev/loop1"
romfs: Mounting image 'rom 5f663c08' through the block layer
audit: type=1800 audit(1667454586.340:70): pid=14967 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed" comm="syz-executor.2" name="file0" dev="loop2" ino=128 res=0
romfs: Mounting image 'rom 5f663c08' through the block layer
MTD: Attempt to mount non-MTD device "/dev/loop2"
romfs: Mounting image 'rom 5f663c08' through the block layer
audit: type=1800 audit(1667454586.580:71): pid=14995 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed" comm="syz-executor.2" name="file0" dev="loop2" ino=128 res=0
MTD: Attempt to mount non-MTD device "/dev/loop1"
romfs: Mounting image 'rom 5f663c08' through the block layer
audit: type=1800 audit(1667454586.720:72): pid=15012 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed" comm="syz-executor.1" name="file0" dev="loop1" ino=128 res=0
kvm: pic: non byte read
kvm: pic: level sensitive irq not supported
kvm: pic: non byte read
kvm: pic: level sensitive irq not supported
kvm: pic: non byte read
kvm: pic: level sensitive irq not supported
kvm: pic: non byte read
kvm: pic: level sensitive irq not supported
kvm: pic: non byte read
kvm: pic: level sensitive irq not supported
kvm: pic: non byte read
SQUASHFS error: lzo decompression failed, data probably corrupt
SQUASHFS error: squashfs_read_data failed to read block 0x60
SQUASHFS error: Unable to read fragment cache entry [60]
kvm: pic: non byte read
SQUASHFS error: Unable to read page, block 60, size 1f
kvm: pic: level sensitive irq not supported
kvm: pic: non byte read
SQUASHFS error: Unable to read fragment cache entry [60]
kvm: pic: level sensitive irq not supported
kvm: pic: non byte read
SQUASHFS error: Unable to read page, block 60, size 1f
audit: type=1800 audit(1667454587.500:73): pid=15085 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed" comm="syz-executor.5" name="file1" dev="loop5" ino=5 res=0
kvm: pic: level sensitive irq not supported
kvm: pic: non byte read
kvm: pic: level sensitive irq not supported
kvm: pic: level sensitive irq not supported
SQUASHFS error: lzo decompression failed, data probably corrupt
SQUASHFS error: squashfs_read_data failed to read block 0x60
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read page, block 60, size 1f
audit: type=1800 audit(1667454588.330:74): pid=15150 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed" comm="syz-executor.5" name="file1" dev="loop5" ino=5 res=0
SQUASHFS error: lzo decompression failed, data probably corrupt
SQUASHFS error: squashfs_read_data failed to read block 0x60
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: lzo decompression failed, data probably corrupt
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: squashfs_read_data failed to read block 0x60
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read page, block 60, size 1f
audit: type=1800 audit(1667454588.420:75): pid=15164 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed" comm="syz-executor.2" name="file1" dev="loop2" ino=5 res=0
audit: type=1800 audit(1667454588.440:76): pid=15158 uid=0 auid=4294967295 ses=4294967295 op="collect_data" cause="failed" comm="syz-executor.4" name="file1" dev="loop4" ino=5 res=0
SQUASHFS error: lzo decompression failed, data probably corrupt
SQUASHFS error: squashfs_read_data failed to read block 0x60
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: lzo decompression failed, data probably corrupt
SQUASHFS error: lzo decompression failed, data probably corrupt
SQUASHFS error: squashfs_read_data failed to read block 0x60
SQUASHFS error: squashfs_read_data failed to read block 0x60
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: lzo decompression failed, data probably corrupt
SQUASHFS error: squashfs_read_data failed to read block 0x60
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: lzo decompression failed, data probably corrupt
SQUASHFS error: squashfs_read_data failed to read block 0x60
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: lzo decompression failed, data probably corrupt
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: squashfs_read_data failed to read block 0x60
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: Unable to read fragment cache entry [60]
SQUASHFS error: Unable to read page, block 60, size 1f
SQUASHFS error: Unable to read page, block 60, size 1f
input: syz0 as /devices/virtual/input/input5
9p: Uknown uid 18446744073709551615
9p: Uknown uid 18446744073709551615
9p: Uknown uid 18446744073709551615
9p: Uknown uid 18446744073709551615
input: syz0 as /devices/virtual/input/input6
input: syz0 as /devices/virtual/input/input7
input: syz0 as /devices/virtual/input/input8
input: syz0 as /devices/virtual/input/input9
input: syz0 as /devices/virtual/input/input10
input: syz0 as /devices/virtual/input/input11

Crashes (1):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2022/11/03 05:49 linux-4.14.y a85772d7ba90 7a2ebf95 .config console log report info [disk image] [vmlinux] [kernel image] ci2-linux-4-14 possible deadlock in hci_dev_do_close
* Struck through repros no longer work on HEAD.