syzbot


INFO: task hung in hci_request_cancel_all

Status: auto-closed as invalid on 2022/02/03 20:37
Reported-by: syzbot+@syzkaller.appspotmail.com
First crash: 362d, last: 362d

Sample crash report:
INFO: task kworker/0:7:7875 blocked for more than 143 seconds.
      Not tainted 5.16.0-rc2-next-20211125-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/0:7     state:D stack:23776 pid: 7875 ppid:     2 flags:0x00004000
Workqueue: events rfkill_sync_work
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:4983 [inline]
 __schedule+0xab2/0x4d90 kernel/sched/core.c:6293
 schedule+0xd2/0x260 kernel/sched/core.c:6366
 schedule_timeout+0x1db/0x2a0 kernel/time/timer.c:1857
 do_wait_for_common kernel/sched/completion.c:85 [inline]
 __wait_for_common kernel/sched/completion.c:106 [inline]
 wait_for_common kernel/sched/completion.c:117 [inline]
 wait_for_completion+0x174/0x270 kernel/sched/completion.c:138
 __flush_work+0x56c/0xb10 kernel/workqueue.c:3085
 __cancel_work_timer+0x3f9/0x570 kernel/workqueue.c:3172
 hci_request_cancel_all+0x38/0x100 net/bluetooth/hci_request.c:2709
 hci_dev_close_sync+0xa1/0x1120 net/bluetooth/hci_sync.c:3971
 hci_dev_do_close+0x32/0x70 net/bluetooth/hci_core.c:553
 hci_rfkill_set_block+0x19c/0x1d0 net/bluetooth/hci_core.c:935
 rfkill_set_block+0x1f9/0x540 net/rfkill/core.c:344
 rfkill_sync_work+0x8a/0xc0 net/rfkill/core.c:1029
 process_one_work+0x9b2/0x1690 kernel/workqueue.c:2299
 worker_thread+0x658/0x11f0 kernel/workqueue.c:2446
 kthread+0x405/0x4f0 kernel/kthread.c:345
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:295
 </TASK>
INFO: task kworker/u5:1:8077 blocked for more than 143 seconds.
      Not tainted 5.16.0-rc2-next-20211125-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/u5:1    state:D stack:27232 pid: 8077 ppid:     2 flags:0x00004000
Workqueue: hci5 scan_update_work
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:4983 [inline]
 __schedule+0xab2/0x4d90 kernel/sched/core.c:6293
 schedule+0xd2/0x260 kernel/sched/core.c:6366
 schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6425
 __mutex_lock_common kernel/locking/mutex.c:680 [inline]
 __mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:740
 hci_req_sync net/bluetooth/hci_request.c:209 [inline]
 scan_update_work+0x26/0xb0 net/bluetooth/hci_request.c:1911
 process_one_work+0x9b2/0x1690 kernel/workqueue.c:2299
 worker_thread+0x658/0x11f0 kernel/workqueue.c:2446
 kthread+0x405/0x4f0 kernel/kthread.c:345
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:295
 </TASK>
INFO: task kworker/0:6:17866 blocked for more than 143 seconds.
      Not tainted 5.16.0-rc2-next-20211125-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/0:6     state:D stack:21712 pid:17866 ppid:     2 flags:0x00004000
Workqueue: events rfkill_global_led_trigger_worker
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:4983 [inline]
 __schedule+0xab2/0x4d90 kernel/sched/core.c:6293
 schedule+0xd2/0x260 kernel/sched/core.c:6366
 schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6425
 __mutex_lock_common kernel/locking/mutex.c:680 [inline]
 __mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:740
 rfkill_global_led_trigger_worker+0x17/0x110 net/rfkill/core.c:180
 process_one_work+0x9b2/0x1690 kernel/workqueue.c:2299
 worker_thread+0x658/0x11f0 kernel/workqueue.c:2446
 kthread+0x405/0x4f0 kernel/kthread.c:345
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:295
 </TASK>
INFO: task systemd-rfkill:31993 blocked for more than 143 seconds.
      Not tainted 5.16.0-rc2-next-20211125-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:systemd-rfkill  state:D stack:26008 pid:31993 ppid:     1 flags:0x00000000
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:4983 [inline]
 __schedule+0xab2/0x4d90 kernel/sched/core.c:6293
 schedule+0xd2/0x260 kernel/sched/core.c:6366
 schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6425
 __mutex_lock_common kernel/locking/mutex.c:680 [inline]
 __mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:740
 rfkill_fop_write+0xff/0x500 net/rfkill/core.c:1260
 vfs_write+0x28e/0xae0 fs/read_write.c:588
 ksys_write+0x1ee/0x250 fs/read_write.c:643
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7f8683feb1b0
RSP: 002b:00007ffd3fab2438 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
RAX: ffffffffffffffda RBX: 0000562f1b05b040 RCX: 00007f8683feb1b0
RDX: 0000000000000008 RSI: 00007ffd3fab2480 RDI: 0000000000000003
RBP: 00007ffd3fab2478 R08: 0000000000000003 R09: 0000000000001010
R10: 0000000000080000 R11: 0000000000000246 R12: 0000000000000001
R13: 00007ffd3fab2470 R14: 0000000000000000 R15: 0000000000000003
 </TASK>
INFO: task syz-executor.3:32106 blocked for more than 144 seconds.
      Not tainted 5.16.0-rc2-next-20211125-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor.3  state:D stack:23816 pid:32106 ppid:     1 flags:0x00000004
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:4983 [inline]
 __schedule+0xab2/0x4d90 kernel/sched/core.c:6293
 schedule+0xd2/0x260 kernel/sched/core.c:6366
 schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6425
 __mutex_lock_common kernel/locking/mutex.c:680 [inline]
 __mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:740
 rfkill_fop_open+0x10d/0x720 net/rfkill/core.c:1148
 misc_open+0x372/0x4a0 drivers/char/misc.c:141
 chrdev_open+0x266/0x770 fs/char_dev.c:414
 do_dentry_open+0x4c8/0x1250 fs/open.c:822
 do_open fs/namei.c:3426 [inline]
 path_openat+0x1cad/0x2750 fs/namei.c:3559
 do_filp_open+0x1aa/0x400 fs/namei.c:3586
 do_sys_openat2+0x16d/0x4d0 fs/open.c:1212
 do_sys_open fs/open.c:1228 [inline]
 __do_sys_openat fs/open.c:1244 [inline]
 __se_sys_openat fs/open.c:1239 [inline]
 __x64_sys_openat+0x13f/0x1f0 fs/open.c:1239
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7fb68746da04
RSP: 002b:00007ffc495c0e10 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 00007ffc495c1558 RCX: 00007fb68746da04
RDX: 0000000000000002 RSI: 00007fb6875142f4 RDI: 00000000ffffff9c
RBP: 00007fb6875142f4 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000002
R13: 00007ffc495c0ff0 R14: 0000000000000000 R15: 00007ffc495c1000
 </TASK>

Showing all locks held in the system:
1 lock held by khungtaskd/27:
 #0: ffffffff8bb83220 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x53/0x260 kernel/locking/lockdep.c:6458
1 lock held by in:imklog/6220:
 #0: ffff88807ba340f0 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0xe9/0x100 fs/file.c:990
4 locks held by kworker/0:7/7875:
 #0: ffff888010c64d38 ((wq_completion)events){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
 #0: ffff888010c64d38 ((wq_completion)events){+.+.}-{0:0}, at: arch_atomic_long_set include/linux/atomic/atomic-long.h:41 [inline]
 #0: ffff888010c64d38 ((wq_completion)events){+.+.}-{0:0}, at: atomic_long_set include/linux/atomic/atomic-instrumented.h:1198 [inline]
 #0: ffff888010c64d38 ((wq_completion)events){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:635 [inline]
 #0: ffff888010c64d38 ((wq_completion)events){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:662 [inline]
 #0: ffff888010c64d38 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x896/0x1690 kernel/workqueue.c:2270
 #1: ffffc9000da57db0 ((work_completion)(&rfkill->sync_work)){+.+.}-{0:0}, at: process_one_work+0x8ca/0x1690 kernel/workqueue.c:2274
 #2: ffffffff8d6fa6e8 (rfkill_global_mutex){+.+.}-{3:3}, at: rfkill_sync_work+0x18/0xc0 net/rfkill/core.c:1027
 #3: ffff888031119000 (&hdev->req_lock){+.+.}-{3:3}, at: hci_dev_do_close+0x2a/0x70 net/bluetooth/hci_core.c:551
3 locks held by kworker/u4:5/7975:
3 locks held by kworker/u5:1/8077:
 #0: ffff888034ed0938 ((wq_completion)hci5){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
 #0: ffff888034ed0938 ((wq_completion)hci5){+.+.}-{0:0}, at: arch_atomic_long_set include/linux/atomic/atomic-long.h:41 [inline]
 #0: ffff888034ed0938 ((wq_completion)hci5){+.+.}-{0:0}, at: atomic_long_set include/linux/atomic/atomic-instrumented.h:1198 [inline]
 #0: ffff888034ed0938 ((wq_completion)hci5){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:635 [inline]
 #0: ffff888034ed0938 ((wq_completion)hci5){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:662 [inline]
 #0: ffff888034ed0938 ((wq_completion)hci5){+.+.}-{0:0}, at: process_one_work+0x896/0x1690 kernel/workqueue.c:2270
 #1: ffffc90003297db0 ((work_completion)(&hdev->scan_update)){+.+.}-{0:0}, at: process_one_work+0x8ca/0x1690 kernel/workqueue.c:2274
 #2: ffff888031119000 (&hdev->req_lock){+.+.}-{3:3}, at: hci_req_sync net/bluetooth/hci_request.c:209 [inline]
 #2: ffff888031119000 (&hdev->req_lock){+.+.}-{3:3}, at: scan_update_work+0x26/0xb0 net/bluetooth/hci_request.c:1911
3 locks held by kworker/0:6/17866:
 #0: ffff888010c64d38 ((wq_completion)events){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
 #0: ffff888010c64d38 ((wq_completion)events){+.+.}-{0:0}, at: arch_atomic_long_set include/linux/atomic/atomic-long.h:41 [inline]
 #0: ffff888010c64d38 ((wq_completion)events){+.+.}-{0:0}, at: atomic_long_set include/linux/atomic/atomic-instrumented.h:1198 [inline]
 #0: ffff888010c64d38 ((wq_completion)events){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:635 [inline]
 #0: ffff888010c64d38 ((wq_completion)events){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:662 [inline]
 #0: ffff888010c64d38 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x896/0x1690 kernel/workqueue.c:2270
 #1: ffffc90003527db0 ((work_completion)(&rfkill_global_led_trigger_work)){+.+.}-{0:0}, at: process_one_work+0x8ca/0x1690 kernel/workqueue.c:2274
 #2: ffffffff8d6fa6e8 (rfkill_global_mutex){+.+.}-{3:3}, at: rfkill_global_led_trigger_worker+0x17/0x110 net/rfkill/core.c:180
1 lock held by systemd-rfkill/31993:
 #0: ffffffff8d6fa6e8 (rfkill_global_mutex){+.+.}-{3:3}, at: rfkill_fop_write+0xff/0x500 net/rfkill/core.c:1260
2 locks held by syz-executor.3/32106:
 #0: ffffffff8c5df5e8 (misc_mtx){+.+.}-{3:3}, at: misc_open+0x55/0x4a0 drivers/char/misc.c:107
 #1: ffffffff8d6fa6e8 (rfkill_global_mutex){+.+.}-{3:3}, at: rfkill_fop_open+0x10d/0x720 net/rfkill/core.c:1148

=============================================

NMI backtrace for cpu 0
CPU: 0 PID: 27 Comm: khungtaskd Not tainted 5.16.0-rc2-next-20211125-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 <TASK>
 __dump_stack lib/dump_stack.c:88 [inline]
 dump_stack_lvl+0xcd/0x134 lib/dump_stack.c:106
 nmi_cpu_backtrace.cold+0x47/0x144 lib/nmi_backtrace.c:111
 nmi_trigger_cpumask_backtrace+0x1b3/0x230 lib/nmi_backtrace.c:62
 trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:256 [inline]
 watchdog+0xcb7/0xed0 kernel/hung_task.c:413
 kthread+0x405/0x4f0 kernel/kthread.c:345
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:295
 </TASK>
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 7975 Comm: kworker/u4:5 Not tainted 5.16.0-rc2-next-20211125-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Workqueue: events_unbound toggle_allocation_gate
RIP: 0010:__sanitizer_cov_trace_const_cmp4+0x6b/0x70 kernel/kcov.c:289
Code: 00 00 00 48 39 fe 72 22 44 89 c6 48 83 c2 01 48 89 4c 38 f0 48 c7 44 38 e0 05 00 00 00 48 89 74 38 e8 4e 89 54 c8 20 48 89 10 <c3> 0f 1f 40 00 49 89 f8 bf 03 00 00 00 4c 8b 14 24 48 89 f1 65 48
RSP: 0018:ffffc900029ff978 EFLAGS: 00000046
RAX: 0000000000000000 RBX: ffff8881400b0000 RCX: 0000000000000001
RDX: 0000000000000000 RSI: ffff8880355b3a80 RDI: 0000000000000003
RBP: ffff8880b9d394c0 R08: 0000000000000007 R09: 0000000000151cd4
R10: ffffffff8405e526 R11: 000000000000003f R12: 0000000000000001
R13: ffff8881400b0668 R14: 0000000000000000 R15: 0000000000000001
FS:  0000000000000000(0000) GS:ffff8880b9d00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f276ad90000 CR3: 000000000b88e000 CR4: 00000000003506e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 00000000b8fecd19 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Call Trace:
 <TASK>
 cpu_max_bits_warn include/linux/cpumask.h:108 [inline]
 cpumask_check include/linux/cpumask.h:115 [inline]
 cpumask_any_but+0x26/0x1a0 lib/cpumask.c:57
 flush_tlb_mm_range+0xb5/0x230 arch/x86/mm/tlb.c:1012
 __text_poke+0x593/0x8c0 arch/x86/kernel/alternative.c:1048
 text_poke_bp_batch+0x3d7/0x560 arch/x86/kernel/alternative.c:1361
 text_poke_flush arch/x86/kernel/alternative.c:1451 [inline]
 text_poke_flush arch/x86/kernel/alternative.c:1448 [inline]
 text_poke_finish+0x16/0x30 arch/x86/kernel/alternative.c:1458
 arch_jump_label_transform_apply+0x13/0x20 arch/x86/kernel/jump_label.c:146
 jump_label_update+0x1d5/0x430 kernel/jump_label.c:830
 static_key_enable_cpuslocked+0x1b1/0x260 kernel/jump_label.c:177
 static_key_enable+0x16/0x20 kernel/jump_label.c:190
 toggle_allocation_gate mm/kfence/core.c:732 [inline]
 toggle_allocation_gate+0x100/0x390 mm/kfence/core.c:724
 process_one_work+0x9b2/0x1690 kernel/workqueue.c:2299
 worker_thread+0x658/0x11f0 kernel/workqueue.c:2446
 kthread+0x405/0x4f0 kernel/kthread.c:345
 ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:295
 </TASK>
----------------
Code disassembly (best guess), 1 bytes skipped:
   0:	00 00                	add    %al,(%rax)
   2:	48 39 fe             	cmp    %rdi,%rsi
   5:	72 22                	jb     0x29
   7:	44 89 c6             	mov    %r8d,%esi
   a:	48 83 c2 01          	add    $0x1,%rdx
   e:	48 89 4c 38 f0       	mov    %rcx,-0x10(%rax,%rdi,1)
  13:	48 c7 44 38 e0 05 00 	movq   $0x5,-0x20(%rax,%rdi,1)
  1a:	00 00
  1c:	48 89 74 38 e8       	mov    %rsi,-0x18(%rax,%rdi,1)
  21:	4e 89 54 c8 20       	mov    %r10,0x20(%rax,%r9,8)
  26:	48 89 10             	mov    %rdx,(%rax)
* 29:	c3                   	retq <-- trapping instruction
  2a:	0f 1f 40 00          	nopl   0x0(%rax)
  2e:	49 89 f8             	mov    %rdi,%r8
  31:	bf 03 00 00 00       	mov    $0x3,%edi
  36:	4c 8b 14 24          	mov    (%rsp),%r10
  3a:	48 89 f1             	mov    %rsi,%rcx
  3d:	65                   	gs
  3e:	48                   	rex.W

Crashes (1):
Manager Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Title
ci-upstream-linux-next-kasan-gce-root 2021/12/05 20:34 linux-next f81e94e91878 a617004c .config log report info INFO: task hung in hci_request_cancel_all
* Struck through repros no longer work on HEAD.