[syzbot] INFO: task hung in hub_port_init (2)

14 views

Skip to first unread message

syzbot

unread,

Nov 15, 2021, 9:47:23 PM11/15/21

to gre...@linuxfoundation.org, jo...@kernel.org, linux-...@vger.kernel.org, linu...@vger.kernel.org, st...@rowland.harvard.edu, syzkall...@googlegroups.com

Hello,

syzbot found the following issue on:

HEAD commit: 8ab774587903 Merge tag 'trace-v5.16-5' of git://git.kernel..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=12a6b6d1b00000
kernel config: https://syzkaller.appspot.com/x/.config?x=6c3ab72998e7f1a4
dashboard link: https://syzkaller.appspot.com/bug?extid=76629376e06e2c2ad626
compiler: Debian clang version 11.0.1-2, GNU ld (GNU Binutils for Debian) 2.35.2

Unfortunately, I don't have any reproducer for this issue yet.

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+766293...@syzkaller.appspotmail.com

INFO: task kworker/1:4:7960 blocked for more than 143 seconds.
Not tainted 5.16.0-rc1-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:4 state:D stack:23576 pid: 7960 ppid: 2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
context_switch kernel/sched/core.c:4972 [inline]
__schedule+0xb72/0x1460 kernel/sched/core.c:6253
schedule+0x12b/0x1f0 kernel/sched/core.c:6326
usb_kill_urb+0x1d5/0x310 drivers/usb/core/urb.c:720
usb_start_wait_urb+0x265/0x530 drivers/usb/core/message.c:64
usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
usb_control_msg+0x2a5/0x4b0 drivers/usb/core/message.c:153
hub_port_init+0x9f1/0x2df0 drivers/usb/core/hub.c:4829
hub_port_connect+0xcf8/0x27d0 drivers/usb/core/hub.c:5280
hub_port_connect_change+0x5f9/0xc20 drivers/usb/core/hub.c:5488
port_event+0xb67/0x1220 drivers/usb/core/hub.c:5634
hub_event+0x4ed/0xe40 drivers/usb/core/hub.c:5716
process_one_work+0x853/0x1140 kernel/workqueue.c:2298
worker_thread+0xac1/0x1320 kernel/workqueue.c:2445
kthread+0x468/0x490 kernel/kthread.c:327
ret_from_fork+0x1f/0x30
</TASK>

Showing all locks held in the system:
3 locks held by kworker/u4:0/8:
1 lock held by khungtaskd/27:
#0: ffffffff8cd1da80 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x0/0x30
1 lock held by in:imklog/6200:
#0: ffff8880715914f0 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0x24e/0x2f0 fs/file.c:990
2 locks held by agetty/6229:
#0: ffff888024550098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x21/0x70 drivers/tty/tty_ldisc.c:252
#1: ffffc900028dc2e8 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x6c5/0x1c60 drivers/tty/n_tty.c:2113
5 locks held by kworker/1:4/7960:
#0: ffff888016717538 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x7ca/0x1140
#1: ffffc9000c1bfd20 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x808/0x1140 kernel/workqueue.c:2273
#2: ffff888147758220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:760 [inline]
#2: ffff888147758220 (&dev->mutex){....}-{3:3}, at: hub_event+0x1b2/0xe40 drivers/usb/core/hub.c:5662
#3: ffff88814775c5c0 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3086 [inline]
#3: ffff88814775c5c0 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect+0xce1/0x27d0 drivers/usb/core/hub.c:5279
#4: ffff888147701168 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_init+0x1ef/0x2df0 drivers/usb/core/hub.c:4703
1 lock held by syz-executor.0/16819:
2 locks held by syz-executor.4/16820:
1 lock held by syz-executor.1/16824:

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

NMI backtrace for cpu 1
CPU: 1 PID: 27 Comm: khungtaskd Not tainted 5.16.0-rc1-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+0x1dc/0x2d8 lib/dump_stack.c:106
nmi_cpu_backtrace+0x45f/0x490 lib/nmi_backtrace.c:105
nmi_trigger_cpumask_backtrace+0x16a/0x280 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:210 [inline]
watchdog+0xc82/0xcd0 kernel/hung_task.c:295
kthread+0x468/0x490 kernel/kthread.c:327
ret_from_fork+0x1f/0x30
</TASK>
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 16715 Comm: kworker/u4:4 Not tainted 5.16.0-rc1-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Workqueue: phy8 ieee80211_iface_work
RIP: 0010:unwind_done arch/x86/include/asm/unwind.h:50 [inline]
RIP: 0010:__unwind_start+0x61a/0x750 arch/x86/kernel/unwind_orc.c:709
Code: e8 5b 79 95 00 48 8b 44 24 10 48 39 03 0f 83 d4 fa ff ff 4c 89 f7 e8 35 da ff ff 48 b8 00 00 00 00 00 fc ff df 0f b6 44 05 00 <84> c0 75 2d 41 83 3e 00 0f 85 38 ff ff ff e9 aa fa ff ff 44 89 f1
RSP: 0018:ffffc90001b3f3b8 EFLAGS: 00000292
RAX: 0000000000000000 RBX: ffffc90001b3f458 RCX: 0000000080000000
RDX: ffffc90001b3f3b8 RSI: 0000000000000001 RDI: 0000000000000001
RBP: 1ffff92000367e84 R08: dffffc0000000000 R09: ffffc90001b3f470
R10: fffff52000367e90 R11: 0000000000000000 R12: 1ffff92000367e86
R13: ffffc90001b38000 R14: ffffc90001b3f420 R15: ffffc90001b3f428
FS: 0000000000000000(0000) GS:ffff8880b9a00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fd4386b03a4 CR3: 000000003a2bd000 CR4: 00000000003506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
Call Trace:
<TASK>
unwind_start arch/x86/include/asm/unwind.h:64 [inline]
arch_stack_walk+0xdc/0x140 arch/x86/kernel/stacktrace.c:24
stack_trace_save+0x11b/0x1e0 kernel/stacktrace.c:122
kasan_save_stack mm/kasan/common.c:38 [inline]
kasan_set_track mm/kasan/common.c:46 [inline]
set_alloc_info mm/kasan/common.c:434 [inline]
____kasan_kmalloc+0xdc/0x110 mm/kasan/common.c:513
kasan_kmalloc include/linux/kasan.h:269 [inline]
kmem_cache_alloc_trace+0x9d/0x330 mm/slub.c:3261
kmalloc include/linux/slab.h:590 [inline]
kzalloc include/linux/slab.h:724 [inline]
ieee802_11_parse_elems_crc+0xc7/0x1040 net/mac80211/util.c:1471
ieee802_11_parse_elems net/mac80211/ieee80211_i.h:2208 [inline]
ieee80211_rx_mgmt_probe_beacon net/mac80211/ibss.c:1605 [inline]
ieee80211_ibss_rx_queued_mgmt+0x389/0x2b30 net/mac80211/ibss.c:1639
ieee80211_iface_process_skb net/mac80211/iface.c:1466 [inline]
ieee80211_iface_work+0x709/0xc90 net/mac80211/iface.c:1520
process_one_work+0x853/0x1140 kernel/workqueue.c:2298
worker_thread+0xac1/0x1320 kernel/workqueue.c:2445
kthread+0x468/0x490 kernel/kthread.c:327
ret_from_fork+0x1f/0x30
</TASK>
----------------
Code disassembly (best guess):
0: e8 5b 79 95 00 callq 0x957960
5: 48 8b 44 24 10 mov 0x10(%rsp),%rax
a: 48 39 03 cmp %rax,(%rbx)
d: 0f 83 d4 fa ff ff jae 0xfffffae7
13: 4c 89 f7 mov %r14,%rdi
16: e8 35 da ff ff callq 0xffffda50
1b: 48 b8 00 00 00 00 00 movabs $0xdffffc0000000000,%rax
22: fc ff df
25: 0f b6 44 05 00 movzbl 0x0(%rbp,%rax,1),%eax
* 2a: 84 c0 test %al,%al <-- trapping instruction
2c: 75 2d jne 0x5b
2e: 41 83 3e 00 cmpl $0x0,(%r14)
32: 0f 85 38 ff ff ff jne 0xffffff70
38: e9 aa fa ff ff jmpq 0xfffffae7
3d: 44 89 f1 mov %r14d,%ecx

---
This report is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzk...@googlegroups.com.

syzbot will keep track of this issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

syzbot

unread,

Jan 19, 2022, 3:16:27 PM1/19/22

to gre...@linuxfoundation.org, jo...@kernel.org, linux-...@vger.kernel.org, linu...@vger.kernel.org, st...@rowland.harvard.edu, syzkall...@googlegroups.com

syzbot has found a reproducer for the following issue on:

HEAD commit: 6f59bc242877 Add linux-next specific files for 20220118
git tree: linux-next
console output: https://syzkaller.appspot.com/x/log.txt?x=173526ffb00000
kernel config: https://syzkaller.appspot.com/x/.config?x=94e8da4df9ab6319
dashboard link: https://syzkaller.appspot.com/bug?extid=76629376e06e2c2ad626
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=13070f40700000

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+766293...@syzkaller.appspotmail.com

INFO: task kworker/1:6:3709 blocked for more than 143 seconds.
Not tainted 5.16.0-next-20220118-syzkaller #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:kworker/1:6 state:D stack:26416 pid: 3709 ppid: 2 flags:0x00004000

Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>

context_switch kernel/sched/core.c:4986 [inline]
__schedule+0xab2/0x4e90 kernel/sched/core.c:6296
schedule+0xd2/0x260 kernel/sched/core.c:6369
usb_kill_urb.part.0+0x19a/0x220 drivers/usb/core/urb.c:720
usb_kill_urb+0x7f/0xa0 drivers/usb/core/urb.c:715
usb_start_wait_urb+0x24a/0x4c0 drivers/usb/core/message.c:64
usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
usb_control_msg+0x31c/0x4a0 drivers/usb/core/message.c:153
hub_port_init+0x7bd/0x2e80 drivers/usb/core/hub.c:4832
hub_port_connect drivers/usb/core/hub.c:5287 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5502 [inline]
port_event drivers/usb/core/hub.c:5660 [inline]
hub_event+0x238a/0x44d0 drivers/usb/core/hub.c:5742
process_one_work+0x996/0x1610 kernel/workqueue.c:2289
worker_thread+0x665/0x1080 kernel/workqueue.c:2436
kthread+0x2e9/0x3a0 kernel/kthread.c:377
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:295
</TASK>
INFO: task syz-executor.0:3767 can't die for more than 143 seconds.
task:syz-executor.0 state:D stack:28000 pid: 3767 ppid: 3655 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:4986 [inline]
__schedule+0xab2/0x4e90 kernel/sched/core.c:6296
schedule+0xd2/0x260 kernel/sched/core.c:6369
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6428
__mutex_lock_common kernel/locking/mutex.c:673 [inline]
__mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:733
device_lock include/linux/device.h:767 [inline]
usbdev_release+0x83/0x4b0 drivers/usb/core/devio.c:1075
__fput+0x286/0x9f0 fs/file_table.c:311
task_work_run+0xdd/0x1a0 kernel/task_work.c:164
tracehook_notify_resume include/linux/tracehook.h:188 [inline]
exit_to_user_mode_loop kernel/entry/common.c:175 [inline]
exit_to_user_mode_prepare+0x27e/0x290 kernel/entry/common.c:207
__syscall_exit_to_user_mode_work kernel/entry/common.c:289 [inline]
syscall_exit_to_user_mode+0x19/0x60 kernel/entry/common.c:300
do_syscall_64+0x42/0xb0 arch/x86/entry/common.c:86
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7ff21c603c2b
RSP: 002b:00007ffe6d368d40 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000004 RCX: 00007ff21c603c2b
RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000000003
RBP: 00007ff21c765960 R08: 0000000000000000 R09: 00007ff21c7680d0
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000079a2e
R13: 00007ffe6d368e40 R14: 00007ffe6d368e60 R15: 0000000000000032
</TASK>
INFO: task syz-executor.0:3767 blocked for more than 143 seconds.
Not tainted 5.16.0-next-20220118-syzkaller #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:syz-executor.0 state:D stack:28000 pid: 3767 ppid: 3655 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:4986 [inline]
__schedule+0xab2/0x4e90 kernel/sched/core.c:6296
schedule+0xd2/0x260 kernel/sched/core.c:6369
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6428
__mutex_lock_common kernel/locking/mutex.c:673 [inline]
__mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:733
device_lock include/linux/device.h:767 [inline]
usbdev_release+0x83/0x4b0 drivers/usb/core/devio.c:1075
__fput+0x286/0x9f0 fs/file_table.c:311
task_work_run+0xdd/0x1a0 kernel/task_work.c:164
tracehook_notify_resume include/linux/tracehook.h:188 [inline]
exit_to_user_mode_loop kernel/entry/common.c:175 [inline]
exit_to_user_mode_prepare+0x27e/0x290 kernel/entry/common.c:207
__syscall_exit_to_user_mode_work kernel/entry/common.c:289 [inline]
syscall_exit_to_user_mode+0x19/0x60 kernel/entry/common.c:300
do_syscall_64+0x42/0xb0 arch/x86/entry/common.c:86
entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7ff21c603c2b
RSP: 002b:00007ffe6d368d40 EFLAGS: 00000293 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000004 RCX: 00007ff21c603c2b
RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000000003
RBP: 00007ff21c765960 R08: 0000000000000000 R09: 00007ff21c7680d0
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000079a2e
R13: 00007ffe6d368e40 R14: 00007ffe6d368e60 R15: 0000000000000032
</TASK>
INFO: task syz-executor.2:3773 can't die for more than 144 seconds.
task:syz-executor.2 state:D stack:28504 pid: 3773 ppid: 3657 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:4986 [inline]
__schedule+0xab2/0x4e90 kernel/sched/core.c:6296
schedule+0xd2/0x260 kernel/sched/core.c:6369
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6428
__mutex_lock_common kernel/locking/mutex.c:673 [inline]
__mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:733
device_lock include/linux/device.h:767 [inline]
usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030
chrdev_open+0x266/0x770 fs/char_dev.c:414
do_dentry_open+0x4b9/0x1240 fs/open.c:824
do_open fs/namei.c:3476 [inline]
path_openat+0x1c9e/0x2940 fs/namei.c:3609
do_filp_open+0x1aa/0x400 fs/namei.c:3636
do_sys_openat2+0x16d/0x4d0 fs/open.c:1214
do_sys_open fs/open.c:1230 [inline]
__do_sys_openat fs/open.c:1246 [inline]
__se_sys_openat fs/open.c:1241 [inline]
__x64_sys_openat+0x13f/0x1f0 fs/open.c:1241
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:0x7f3be7549f04
RSP: 002b:00007f3be6d0bca0 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 6666666666666667 RCX: 00007f3be7549f04
RDX: 0000000000028101 RSI: 00007f3be6d0bd40 RDI: 00000000ffffff9c
RBP: 00007f3be6d0bd40 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000028101
R13: 00007ffcf9aa18df R14: 00007f3be6d0c300 R15: 0000000000022000
</TASK>
INFO: task syz-executor.2:3773 blocked for more than 144 seconds.
Not tainted 5.16.0-next-20220118-syzkaller #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:syz-executor.2 state:D stack:28504 pid: 3773 ppid: 3657 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:4986 [inline]
__schedule+0xab2/0x4e90 kernel/sched/core.c:6296
schedule+0xd2/0x260 kernel/sched/core.c:6369
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6428
__mutex_lock_common kernel/locking/mutex.c:673 [inline]
__mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:733
device_lock include/linux/device.h:767 [inline]
usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030
chrdev_open+0x266/0x770 fs/char_dev.c:414
do_dentry_open+0x4b9/0x1240 fs/open.c:824
do_open fs/namei.c:3476 [inline]
path_openat+0x1c9e/0x2940 fs/namei.c:3609
do_filp_open+0x1aa/0x400 fs/namei.c:3636
do_sys_openat2+0x16d/0x4d0 fs/open.c:1214
do_sys_open fs/open.c:1230 [inline]
__do_sys_openat fs/open.c:1246 [inline]
__se_sys_openat fs/open.c:1241 [inline]
__x64_sys_openat+0x13f/0x1f0 fs/open.c:1241
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:0x7f3be7549f04
RSP: 002b:00007f3be6d0bca0 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 6666666666666667 RCX: 00007f3be7549f04
RDX: 0000000000028101 RSI: 00007f3be6d0bd40 RDI: 00000000ffffff9c
RBP: 00007f3be6d0bd40 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000028101
R13: 00007ffcf9aa18df R14: 00007f3be6d0c300 R15: 0000000000022000
</TASK>
INFO: task syz-executor.3:3778 can't die for more than 144 seconds.
task:syz-executor.3 state:D stack:28504 pid: 3778 ppid: 3654 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:4986 [inline]
__schedule+0xab2/0x4e90 kernel/sched/core.c:6296
schedule+0xd2/0x260 kernel/sched/core.c:6369
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6428
__mutex_lock_common kernel/locking/mutex.c:673 [inline]
__mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:733
device_lock include/linux/device.h:767 [inline]
usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030
chrdev_open+0x266/0x770 fs/char_dev.c:414
do_dentry_open+0x4b9/0x1240 fs/open.c:824
do_open fs/namei.c:3476 [inline]
path_openat+0x1c9e/0x2940 fs/namei.c:3609
do_filp_open+0x1aa/0x400 fs/namei.c:3636
do_sys_openat2+0x16d/0x4d0 fs/open.c:1214
do_sys_open fs/open.c:1230 [inline]
__do_sys_openat fs/open.c:1246 [inline]
__se_sys_openat fs/open.c:1241 [inline]
__x64_sys_openat+0x13f/0x1f0 fs/open.c:1241
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:0x7f1ccb53ef04
RSP: 002b:00007f1ccad00ca0 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 6666666666666667 RCX: 00007f1ccb53ef04
RDX: 0000000000028101 RSI: 00007f1ccad00d40 RDI: 00000000ffffff9c
RBP: 00007f1ccad00d40 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000028101
R13: 00007ffee90aa8cf R14: 00007f1ccad01300 R15: 0000000000022000
</TASK>
INFO: task syz-executor.3:3778 blocked for more than 145 seconds.
Not tainted 5.16.0-next-20220118-syzkaller #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:syz-executor.3 state:D stack:28504 pid: 3778 ppid: 3654 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:4986 [inline]
__schedule+0xab2/0x4e90 kernel/sched/core.c:6296
schedule+0xd2/0x260 kernel/sched/core.c:6369
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6428
__mutex_lock_common kernel/locking/mutex.c:673 [inline]
__mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:733
device_lock include/linux/device.h:767 [inline]
usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030
chrdev_open+0x266/0x770 fs/char_dev.c:414
do_dentry_open+0x4b9/0x1240 fs/open.c:824
do_open fs/namei.c:3476 [inline]
path_openat+0x1c9e/0x2940 fs/namei.c:3609
do_filp_open+0x1aa/0x400 fs/namei.c:3636
do_sys_openat2+0x16d/0x4d0 fs/open.c:1214
do_sys_open fs/open.c:1230 [inline]
__do_sys_openat fs/open.c:1246 [inline]
__se_sys_openat fs/open.c:1241 [inline]
__x64_sys_openat+0x13f/0x1f0 fs/open.c:1241
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:0x7f1ccb53ef04
RSP: 002b:00007f1ccad00ca0 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 6666666666666667 RCX: 00007f1ccb53ef04
RDX: 0000000000028101 RSI: 00007f1ccad00d40 RDI: 00000000ffffff9c
RBP: 00007f1ccad00d40 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000028101
R13: 00007ffee90aa8cf R14: 00007f1ccad01300 R15: 0000000000022000
</TASK>
INFO: task syz-executor.5:3783 can't die for more than 145 seconds.
task:syz-executor.5 state:D stack:28152 pid: 3783 ppid: 3656 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:4986 [inline]
__schedule+0xab2/0x4e90 kernel/sched/core.c:6296
schedule+0xd2/0x260 kernel/sched/core.c:6369
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6428
__mutex_lock_common kernel/locking/mutex.c:673 [inline]
__mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:733
device_lock include/linux/device.h:767 [inline]
usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030
chrdev_open+0x266/0x770 fs/char_dev.c:414
do_dentry_open+0x4b9/0x1240 fs/open.c:824
do_open fs/namei.c:3476 [inline]
path_openat+0x1c9e/0x2940 fs/namei.c:3609
do_filp_open+0x1aa/0x400 fs/namei.c:3636
do_sys_openat2+0x16d/0x4d0 fs/open.c:1214
do_sys_open fs/open.c:1230 [inline]
__do_sys_openat fs/open.c:1246 [inline]
__se_sys_openat fs/open.c:1241 [inline]
__x64_sys_openat+0x13f/0x1f0 fs/open.c:1241
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:0x7ffbef1d2f04
RSP: 002b:00007ffbee994ca0 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 6666666666666667 RCX: 00007ffbef1d2f04
RDX: 0000000000028101 RSI: 00007ffbee994d40 RDI: 00000000ffffff9c
RBP: 00007ffbee994d40 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000028101
R13: 00007ffedefc73bf R14: 00007ffbee995300 R15: 0000000000022000
</TASK>
INFO: task syz-executor.5:3783 blocked for more than 145 seconds.
Not tainted 5.16.0-next-20220118-syzkaller #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:syz-executor.5 state:D stack:28152 pid: 3783 ppid: 3656 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:4986 [inline]
__schedule+0xab2/0x4e90 kernel/sched/core.c:6296
schedule+0xd2/0x260 kernel/sched/core.c:6369
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6428
__mutex_lock_common kernel/locking/mutex.c:673 [inline]
__mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:733
device_lock include/linux/device.h:767 [inline]
usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030
chrdev_open+0x266/0x770 fs/char_dev.c:414
do_dentry_open+0x4b9/0x1240 fs/open.c:824
do_open fs/namei.c:3476 [inline]
path_openat+0x1c9e/0x2940 fs/namei.c:3609
do_filp_open+0x1aa/0x400 fs/namei.c:3636
do_sys_openat2+0x16d/0x4d0 fs/open.c:1214
do_sys_open fs/open.c:1230 [inline]
__do_sys_openat fs/open.c:1246 [inline]
__se_sys_openat fs/open.c:1241 [inline]
__x64_sys_openat+0x13f/0x1f0 fs/open.c:1241
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:0x7ffbef1d2f04
RSP: 002b:00007ffbee994ca0 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 6666666666666667 RCX: 00007ffbef1d2f04
RDX: 0000000000028101 RSI: 00007ffbee994d40 RDI: 00000000ffffff9c
RBP: 00007ffbee994d40 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000028101
R13: 00007ffedefc73bf R14: 00007ffbee995300 R15: 0000000000022000
</TASK>
INFO: task syz-executor.1:3790 can't die for more than 145 seconds.
task:syz-executor.1 state:D stack:28504 pid: 3790 ppid: 3659 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:4986 [inline]
__schedule+0xab2/0x4e90 kernel/sched/core.c:6296
schedule+0xd2/0x260 kernel/sched/core.c:6369
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6428
__mutex_lock_common kernel/locking/mutex.c:673 [inline]
__mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:733
device_lock include/linux/device.h:767 [inline]
usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030
chrdev_open+0x266/0x770 fs/char_dev.c:414
do_dentry_open+0x4b9/0x1240 fs/open.c:824
do_open fs/namei.c:3476 [inline]
path_openat+0x1c9e/0x2940 fs/namei.c:3609
do_filp_open+0x1aa/0x400 fs/namei.c:3636
do_sys_openat2+0x16d/0x4d0 fs/open.c:1214
do_sys_open fs/open.c:1230 [inline]
__do_sys_openat fs/open.c:1246 [inline]
__se_sys_openat fs/open.c:1241 [inline]
__x64_sys_openat+0x13f/0x1f0 fs/open.c:1241
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:0x7fb7dbbeaf04
RSP: 002b:00007fb7db3acca0 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 6666666666666667 RCX: 00007fb7dbbeaf04
RDX: 0000000000028101 RSI: 00007fb7db3acd40 RDI: 00000000ffffff9c
RBP: 00007fb7db3acd40 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000028101
R13: 00007ffdd38c69ef R14: 00007fb7db3ad300 R15: 0000000000022000
</TASK>
INFO: task syz-executor.1:3790 blocked for more than 146 seconds.
Not tainted 5.16.0-next-20220118-syzkaller #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:syz-executor.1 state:D stack:28504 pid: 3790 ppid: 3659 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:4986 [inline]
__schedule+0xab2/0x4e90 kernel/sched/core.c:6296
schedule+0xd2/0x260 kernel/sched/core.c:6369
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6428
__mutex_lock_common kernel/locking/mutex.c:673 [inline]
__mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:733
device_lock include/linux/device.h:767 [inline]
usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030
chrdev_open+0x266/0x770 fs/char_dev.c:414
do_dentry_open+0x4b9/0x1240 fs/open.c:824
do_open fs/namei.c:3476 [inline]
path_openat+0x1c9e/0x2940 fs/namei.c:3609
do_filp_open+0x1aa/0x400 fs/namei.c:3636
do_sys_openat2+0x16d/0x4d0 fs/open.c:1214
do_sys_open fs/open.c:1230 [inline]
__do_sys_openat fs/open.c:1246 [inline]
__se_sys_openat fs/open.c:1241 [inline]
__x64_sys_openat+0x13f/0x1f0 fs/open.c:1241
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:0x7fb7dbbeaf04
RSP: 002b:00007fb7db3acca0 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 6666666666666667 RCX: 00007fb7dbbeaf04
RDX: 0000000000028101 RSI: 00007fb7db3acd40 RDI: 00000000ffffff9c
RBP: 00007fb7db3acd40 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000028101
R13: 00007ffdd38c69ef R14: 00007fb7db3ad300 R15: 0000000000022000
</TASK>
INFO: task syz-executor.4:3792 can't die for more than 146 seconds.
task:syz-executor.4 state:D stack:28504 pid: 3792 ppid: 3658 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:4986 [inline]
__schedule+0xab2/0x4e90 kernel/sched/core.c:6296
schedule+0xd2/0x260 kernel/sched/core.c:6369
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6428
__mutex_lock_common kernel/locking/mutex.c:673 [inline]
__mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:733
device_lock include/linux/device.h:767 [inline]
usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030
chrdev_open+0x266/0x770 fs/char_dev.c:414
do_dentry_open+0x4b9/0x1240 fs/open.c:824
do_open fs/namei.c:3476 [inline]
path_openat+0x1c9e/0x2940 fs/namei.c:3609
do_filp_open+0x1aa/0x400 fs/namei.c:3636
do_sys_openat2+0x16d/0x4d0 fs/open.c:1214
do_sys_open fs/open.c:1230 [inline]
__do_sys_openat fs/open.c:1246 [inline]
__se_sys_openat fs/open.c:1241 [inline]
__x64_sys_openat+0x13f/0x1f0 fs/open.c:1241
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:0x7f2ad26daf04
RSP: 002b:00007f2ad1e9cca0 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 6666666666666667 RCX: 00007f2ad26daf04
RDX: 0000000000028101 RSI: 00007f2ad1e9cd40 RDI: 00000000ffffff9c
RBP: 00007f2ad1e9cd40 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000028101
R13: 00007ffd4db79f0f R14: 00007f2ad1e9d300 R15: 0000000000022000
</TASK>
INFO: task syz-executor.4:3792 blocked for more than 146 seconds.
Not tainted 5.16.0-next-20220118-syzkaller #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:syz-executor.4 state:D stack:28504 pid: 3792 ppid: 3658 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:4986 [inline]
__schedule+0xab2/0x4e90 kernel/sched/core.c:6296
schedule+0xd2/0x260 kernel/sched/core.c:6369
schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:6428
__mutex_lock_common kernel/locking/mutex.c:673 [inline]
__mutex_lock+0xa32/0x12f0 kernel/locking/mutex.c:733
device_lock include/linux/device.h:767 [inline]
usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030
chrdev_open+0x266/0x770 fs/char_dev.c:414
do_dentry_open+0x4b9/0x1240 fs/open.c:824
do_open fs/namei.c:3476 [inline]
path_openat+0x1c9e/0x2940 fs/namei.c:3609
do_filp_open+0x1aa/0x400 fs/namei.c:3636
do_sys_openat2+0x16d/0x4d0 fs/open.c:1214
do_sys_open fs/open.c:1230 [inline]
__do_sys_openat fs/open.c:1246 [inline]
__se_sys_openat fs/open.c:1241 [inline]
__x64_sys_openat+0x13f/0x1f0 fs/open.c:1241
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:0x7f2ad26daf04
RSP: 002b:00007f2ad1e9cca0 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 6666666666666667 RCX: 00007f2ad26daf04
RDX: 0000000000028101 RSI: 00007f2ad1e9cd40 RDI: 00000000ffffff9c
RBP: 00007f2ad1e9cd40 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000028101
R13: 00007ffd4db79f0f R14: 00007f2ad1e9d300 R15: 0000000000022000

</TASK>

Showing all locks held in the system:

1 lock held by khungtaskd/27:

#0: ffffffff8bb83520 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x53/0x260 kernel/locking/lockdep.c:6460
2 locks held by getty/3291:
#0: ffff88814aeb3098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x22/0x80 drivers/tty/tty_ldisc.c:244
#1: ffffc90002b632e8 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xcf0/0x1230 drivers/tty/n_tty.c:2077
5 locks held by kworker/1:6/3709:
#0: ffff888013392938 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff888013392938 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic_long_set include/linux/atomic/atomic-long.h:41 [inline]
#0: ffff888013392938 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic_long_set include/linux/atomic/atomic-instrumented.h:1280 [inline]
#0: ffff888013392938 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:636 [inline]
#0: ffff888013392938 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:663 [inline]
#0: ffff888013392938 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x87a/0x1610 kernel/workqueue.c:2260
#1: ffffc90002c7fda8 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x8ae/0x1610 kernel/workqueue.c:2264
#2: ffff88801dc51220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:767 [inline]
#2: ffff88801dc51220 (&dev->mutex){....}-{3:3}, at: hub_event+0x1c5/0x44d0 drivers/usb/core/hub.c:5688
#3: ffff88801dc55580 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3091 [inline]
#3: ffff88801dc55580 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5254 [inline]
#3: ffff88801dc55580 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5502 [inline]
#3: ffff88801dc55580 (&port_dev->status_lock){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5660 [inline]
#3: ffff88801dc55580 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_event+0x1fba/0x44d0 drivers/usb/core/hub.c:5742
#4: ffff88801d301868 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5255 [inline]
#4: ffff88801d301868 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5502 [inline]
#4: ffff88801d301868 (hcd->address0_mutex){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5660 [inline]
#4: ffff88801d301868 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_event+0x1fe3/0x44d0 drivers/usb/core/hub.c:5742
1 lock held by syz-executor.0/3767:
#0: ffff88801dc51220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:767 [inline]
#0: ffff88801dc51220 (&dev->mutex){....}-{3:3}, at: usbdev_release+0x83/0x4b0 drivers/usb/core/devio.c:1075
1 lock held by syz-executor.2/3773:
#0: ffff88801dc51220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:767 [inline]
#0: ffff88801dc51220 (&dev->mutex){....}-{3:3}, at: usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030
1 lock held by syz-executor.3/3778:
#0: ffff88801dc51220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:767 [inline]
#0: ffff88801dc51220 (&dev->mutex){....}-{3:3}, at: usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030
1 lock held by syz-executor.5/3783:
#0: ffff88801dc51220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:767 [inline]
#0: ffff88801dc51220 (&dev->mutex){....}-{3:3}, at: usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030
1 lock held by syz-executor.1/3790:
#0: ffff88801dc51220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:767 [inline]
#0: ffff88801dc51220 (&dev->mutex){....}-{3:3}, at: usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030
1 lock held by syz-executor.4/3792:
#0: ffff88801dc51220 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:767 [inline]
#0: ffff88801dc51220 (&dev->mutex){....}-{3:3}, at: usbdev_open+0x19d/0x920 drivers/usb/core/devio.c:1030

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

NMI backtrace for cpu 1

CPU: 1 PID: 27 Comm: khungtaskd Not tainted 5.16.0-next-20220118-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+0x2e9/0x3a0 kernel/kthread.c:377
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:295

</TASK>
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0

CPU: 0 PID: 3269 Comm: kworker/0:3 Not tainted 5.16.0-next-20220118-syzkaller #0

Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011

Workqueue: events nsim_dev_trap_report_work
RIP: 0010:mark_lock+0x30/0x17b0 kernel/locking/lockdep.c:4566
Code: 41 54 41 89 d4 48 ba 00 00 00 00 00 fc ff df 55 53 48 81 ec 18 01 00 00 48 8d 5c 24 38 48 89 3c 24 48 c7 44 24 38 b3 8a b5 41 <48> c1 eb 03 48 c7 44 24 40 28 3c 3a 8b 48 8d 04 13 48 c7 44 24 48
RSP: 0018:ffffc90002c9f938 EFLAGS: 00000092
RAX: 0000000000000004 RBX: ffffc90002c9f970 RCX: 1ffffffff1ffb5ee
RDX: dffffc0000000000 RSI: ffff8880206c8a90 RDI: ffff8880206c8000
RBP: 0000000000000006 R08: 0000000000000000 R09: ffffffff8ffd2957
R10: 0000000000000001 R11: 0000000000088078 R12: 0000000000000006
R13: dffffc0000000000 R14: ffff8880206c8a68 R15: ffff888077ad2000
FS: 0000000000000000(0000) GS:ffff8880b9c00000(0000) knlGS:0000000000000000

CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033

CR2: 00007fac04558600 CR3: 000000000b88e000 CR4: 00000000003506f0

DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000

DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<TASK>
mark_held_locks+0x9f/0xe0 kernel/locking/lockdep.c:4206
__trace_hardirqs_on_caller kernel/locking/lockdep.c:4232 [inline]
lockdep_hardirqs_on_prepare kernel/locking/lockdep.c:4292 [inline]
lockdep_hardirqs_on_prepare+0x28b/0x400 kernel/locking/lockdep.c:4244
trace_hardirqs_on+0x5b/0x1c0 kernel/trace/trace_preemptirq.c:49
kasan_quarantine_put+0xf5/0x210 mm/kasan/quarantine.c:231
kasan_slab_free include/linux/kasan.h:236 [inline]
slab_free_hook mm/slub.c:1728 [inline]
slab_free_freelist_hook+0x8b/0x1c0 mm/slub.c:1754
slab_free mm/slub.c:3509 [inline]
kfree+0xce/0x380 mm/slub.c:4562
skb_free_head net/core/skbuff.c:655 [inline]
skb_release_data+0x718/0x870 net/core/skbuff.c:677
skb_release_all net/core/skbuff.c:742 [inline]
__kfree_skb net/core/skbuff.c:756 [inline]
consume_skb net/core/skbuff.c:914 [inline]
consume_skb+0xc2/0x160 net/core/skbuff.c:908
nsim_dev_trap_report drivers/net/netdevsim/dev.c:818 [inline]
nsim_dev_trap_report_work+0x85d/0xbc0 drivers/net/netdevsim/dev.c:843
process_one_work+0x996/0x1610 kernel/workqueue.c:2289
worker_thread+0x665/0x1080 kernel/workqueue.c:2436
kthread+0x2e9/0x3a0 kernel/kthread.c:377
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:295

</TASK>
----------------
Code disassembly (best guess):

0: 41 54 push %r12
2: 41 89 d4 mov %edx,%r12d
5: 48 ba 00 00 00 00 00 movabs $0xdffffc0000000000,%rdx
c: fc ff df
f: 55 push %rbp
10: 53 push %rbx
11: 48 81 ec 18 01 00 00 sub $0x118,%rsp
18: 48 8d 5c 24 38 lea 0x38(%rsp),%rbx
1d: 48 89 3c 24 mov %rdi,(%rsp)
21: 48 c7 44 24 38 b3 8a movq $0x41b58ab3,0x38(%rsp)
28: b5 41
* 2a: 48 c1 eb 03 shr $0x3,%rbx <-- trapping instruction
2e: 48 c7 44 24 40 28 3c movq $0xffffffff8b3a3c28,0x40(%rsp)
35: 3a 8b
37: 48 8d 04 13 lea (%rbx,%rdx,1),%rax
3b: 48 rex.W
3c: c7 .byte 0xc7
3d: 44 24 48 rex.R and $0x48,%al

Hillf Danton

unread,

Jan 20, 2022, 3:00:39 AM1/20/22

to syzbot, gre...@linuxfoundation.org, jo...@kernel.org, linux-...@vger.kernel.org, linu...@vger.kernel.org, Pavel Skripkin, st...@rowland.harvard.edu, syzkall...@googlegroups.com

On Wed, 19 Jan 2022 12:16:25 -0800

See if it means hardware glitch to take 143 seconds for the underlying
hardware to complete IO.

Only for thoughts now.

#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git 6f59bc242877

--- x/drivers/usb/core/hcd.c
+++ y/drivers/usb/core/hcd.c
@@ -1667,6 +1667,8 @@ static void __usb_hcd_giveback_urb(struc
atomic_dec(&urb->use_count);
if (unlikely(atomic_read(&urb->reject)))
wake_up(&usb_kill_urb_queue);
+ else if (urb->debug_complete != NULL)
+ complete(urb->debug_complete);
usb_put_urb(urb);
}

--- x/drivers/usb/core/message.c
+++ y/drivers/usb/core/message.c
@@ -49,19 +49,23 @@ static void usb_api_blocking_completion(
static int usb_start_wait_urb(struct urb *urb, int timeout, int *actual_length)
{
struct api_context ctx;
+ struct completion compl;
unsigned long expire;
int retval;

init_completion(&ctx.done);
urb->context = &ctx;
urb->actual_length = 0;
+ urb->debug_complete = &compl;
+ init_completion(urb->debug_complete);
retval = usb_submit_urb(urb, GFP_NOIO);
if (unlikely(retval))
goto out;

expire = timeout ? msecs_to_jiffies(timeout) : MAX_SCHEDULE_TIMEOUT;
if (!wait_for_completion_timeout(&ctx.done, expire)) {
- usb_kill_urb(urb);
+ dev_dbg(&urb->dev->dev, "%s timeout %lu\n", __func__, expire);
+ wait_for_completion(urb->debug_complete);
retval = (ctx.status == -ENOENT ? -ETIMEDOUT : ctx.status);

dev_dbg(&urb->dev->dev,
--- x/include/linux/usb.h
+++ y/include/linux/usb.h
@@ -1560,6 +1560,7 @@ struct urb {
void *hcpriv; /* private data for host controller */
atomic_t use_count; /* concurrent submissions counter */
atomic_t reject; /* submissions will fail */
+ struct completion *debug_complete;

/* public: documented fields in the urb that can be used by drivers */
struct list_head urb_list; /* list head for use by the urb's
--

syzbot

unread,

Jan 20, 2022, 3:11:11 AM1/20/22

to gre...@linuxfoundation.org, hda...@sina.com, jo...@kernel.org, linux-...@vger.kernel.org, linu...@vger.kernel.org, paskr...@gmail.com, st...@rowland.harvard.edu, syzkall...@googlegroups.com

Hello,

syzbot has tested the proposed patch and the reproducer did not trigger any issue:

Reported-and-tested-by: syzbot+766293...@syzkaller.appspotmail.com

Tested on:

commit: 6f59bc24 Add linux-next specific files for 20220118
git tree: git://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git

kernel config: https://syzkaller.appspot.com/x/.config?x=94e8da4df9ab6319
dashboard link: https://syzkaller.appspot.com/bug?extid=76629376e06e2c2ad626
compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2

patch: https://syzkaller.appspot.com/x/patch.diff?x=101ba7efb00000

Note: testing is done by a robot and is best-effort only.

Hillf Danton

unread,

Jan 20, 2022, 6:03:08 AM1/20/22

to syzbot, gre...@linuxfoundation.org, hda...@sina.com, jo...@kernel.org, linux-...@vger.kernel.org, linu...@vger.kernel.org, paskr...@gmail.com, st...@rowland.harvard.edu, syzkall...@googlegroups.com

On Thu, 20 Jan 2022 00:11:10 -0800

The tested debug patch below was prepared based on the race supposed to be
between the kill and giveback pathes.

usb_kill_urb giveback_urb

if (unlikely(atomic_read(&urb->reject)))
wake_up(&usb_kill_urb_queue);

atomic_inc(&urb->reject);
wait_event(usb_kill_urb_queue,
atomic_read(&urb->use_count) == 0);
atomic_dec(&urb->reject);

And if either the ckeck for urb->reject runs before it is incremented or
wakeup runs before waiter gets themselves on the waitqueue or there are
multi waiters, the race can be triggered.

Light on how to fix the race if the chance for it is not zero is welcome.

Hillf

Alan Stern

unread,

Jan 20, 2022, 12:28:43 PM1/20/22

to syzbot, gre...@linuxfoundation.org, hda...@sina.com, jo...@kernel.org, linux-...@vger.kernel.org, linu...@vger.kernel.org, paskr...@gmail.com, syzkall...@googlegroups.com

Attempted fix.

Alan Stern

#syz test: https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git/ 6f59bc24

Index: usb-devel/drivers/usb/core/hcd.c
===================================================================
--- usb-devel.orig/drivers/usb/core/hcd.c
+++ usb-devel/drivers/usb/core/hcd.c
@@ -1563,6 +1563,12 @@ int usb_hcd_submit_urb (struct urb *urb,
urb->hcpriv = NULL;
INIT_LIST_HEAD(&urb->urb_list);
atomic_dec(&urb->use_count);
+ /*
+ * Order the write of urb->use_count above against the read of
+ * urb->reject below. Pairs with the memory barriers in
+ * usb_kill_urb() and usb_poison_urb().
+ */
+ smp_mb__after_atomic();
atomic_dec(&urb->dev->urbnum);
if (atomic_read(&urb->reject))
wake_up(&usb_kill_urb_queue);
@@ -1665,6 +1671,13 @@ static void __usb_hcd_giveback_urb(struc

usb_anchor_resume_wakeups(anchor);
atomic_dec(&urb->use_count);
+ /*
+ * Order the write of urb->use_count above against the read of
+ * urb->reject below. Pairs with the memory barriers in
+ * usb_kill_urb() and usb_poison_urb().
+ */
+ smp_mb__after_atomic();
+
if (unlikely(atomic_read(&urb->reject)))
wake_up(&usb_kill_urb_queue);
usb_put_urb(urb);
Index: usb-devel/drivers/usb/core/urb.c
===================================================================
--- usb-devel.orig/drivers/usb/core/urb.c
+++ usb-devel/drivers/usb/core/urb.c
@@ -715,6 +715,12 @@ void usb_kill_urb(struct urb *urb)
if (!(urb && urb->dev && urb->ep))
return;
atomic_inc(&urb->reject);
+ /*
+ * Order the write of urb->reject above against the read of
+ * urb->use_count below. Pairs with the barriers in
+ * __usb_hcd_giveback_urb() and usb_hcd_submit_urb().
+ */
+ smp_mb__after_atomic();

usb_hcd_unlink_urb(urb, -ENOENT);

wait_event(usb_kill_urb_queue, atomic_read(&urb->use_count) == 0);

@@ -756,6 +762,12 @@ void usb_poison_urb(struct urb *urb)
if (!urb)
return;
atomic_inc(&urb->reject);
+ /*
+ * Order the write of urb->reject above against the read of
+ * urb->use_count below. Pairs with the barriers in
+ * __usb_hcd_giveback_urb() and usb_hcd_submit_urb().
+ */
+ smp_mb__after_atomic();

if (!urb->dev || !urb->ep)
return;

syzbot

unread,

Jan 20, 2022, 12:55:08 PM1/20/22

to gre...@linuxfoundation.org, hda...@sina.com, jo...@kernel.org, linux-...@vger.kernel.org, linu...@vger.kernel.org, paskr...@gmail.com, st...@rowland.harvard.edu, syzkall...@googlegroups.com

git tree: https://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git/

patch: https://syzkaller.appspot.com/x/patch.diff?x=1596bbdfb00000

Alan Stern

unread,

Jan 24, 2022, 3:23:46 PM1/24/22

to Greg KH, syzkall...@googlegroups.com, USB mailing list

The syzbot fuzzer has identified a bug in which processes hang waiting
for usb_kill_urb() to return. It turns out the issue is not unlinking
the URB; that works just fine. Rather, the problem arises when the
wakeup notification that the URB has completed is not received.

The reason is memory-access ordering on SMP systems. In outline form,
usb_kill_urb() and __usb_hcd_giveback_urb() operating concurrently on
different CPUs perform the following actions:

CPU 0 CPU 1
---------------------------- ---------------------------------
usb_kill_urb(): __usb_hcd_giveback_urb():
... ...
atomic_inc(&urb->reject); atomic_dec(&urb->use_count);
... ...

wait_event(usb_kill_urb_queue,
atomic_read(&urb->use_count) == 0);

if (atomic_read(&urb->reject))
wake_up(&usb_kill_urb_queue);

Confining your attention to urb->reject and urb->use_count, you can
see that the overall pattern of accesses on CPU 0 is:

write urb->reject, then read urb->use_count;

whereas the overall pattern of accesses on CPU 1 is:

write urb->use_count, then read urb->reject.

This pattern is referred to in memory-model circles as SB (for "Store
Buffering"), and it is well known that without suitable enforcement of
the desired order of accesses -- in the form of memory barriers -- it
is entirely possible for one or both CPUs to execute their reads ahead
of their writes. The end result will be that sometimes CPU 0 sees the
old un-decremented value of urb->use_count while CPU 1 sees the old
un-incremented value of urb->reject. Consequently CPU 0 ends up on
the wait queue and never gets woken up, leading to the observed hang
in usb_kill_urb().

The same pattern of accesses occurs in usb_poison_urb() and the
failure pathway of usb_hcd_submit_urb().

The problem is fixed by adding suitable memory barriers. To provide
proper memory-access ordering in the SB pattern, a full barrier is
required on both CPUs. The atomic_inc() and atomic_dec() accesses
themselves don't provide any memory ordering, but since they are
present, we can use the optimized smp_mb__after_atomic() memory
barrier in the various routines to obtain the desired effect.

This patch adds the necessary memory barriers.

Reported-and-tested-by: syzbot+766293...@syzkaller.appspotmail.com
Signed-off-by: Alan Stern <st...@rowland.harvard.edu>
CC: <sta...@vger.kernel.org>

---

[as1969]

drivers/usb/core/hcd.c | 14 ++++++++++++++
drivers/usb/core/urb.c | 12 ++++++++++++
2 files changed, 26 insertions(+)

Index: usb-devel/drivers/usb/core/hcd.c
===================================================================
--- usb-devel.orig/drivers/usb/core/hcd.c
+++ usb-devel/drivers/usb/core/hcd.c

@@ -1563,6 +1563,13 @@ int usb_hcd_submit_urb (struct urb *urb,

urb->hcpriv = NULL;
INIT_LIST_HEAD(&urb->urb_list);
atomic_dec(&urb->use_count);
+ /*

+ * Order the write of urb->use_count above before the read
+ * of urb->reject below. Pairs with the memory barriers in

+ * usb_kill_urb() and usb_poison_urb().
+ */
+ smp_mb__after_atomic();
+

atomic_dec(&urb->dev->urbnum);
if (atomic_read(&urb->reject))
wake_up(&usb_kill_urb_queue);

@@ -1665,6 +1672,13 @@ static void __usb_hcd_giveback_urb(struc

usb_anchor_resume_wakeups(anchor);
atomic_dec(&urb->use_count);
+ /*

+ * Order the write of urb->use_count above before the read
+ * of urb->reject below. Pairs with the memory barriers in

+ * usb_kill_urb() and usb_poison_urb().
+ */
+ smp_mb__after_atomic();
+
if (unlikely(atomic_read(&urb->reject)))
wake_up(&usb_kill_urb_queue);
usb_put_urb(urb);
Index: usb-devel/drivers/usb/core/urb.c
===================================================================
--- usb-devel.orig/drivers/usb/core/urb.c
+++ usb-devel/drivers/usb/core/urb.c
@@ -715,6 +715,12 @@ void usb_kill_urb(struct urb *urb)
if (!(urb && urb->dev && urb->ep))
return;
atomic_inc(&urb->reject);
+ /*

+ * Order the write of urb->reject above before the read
+ * of urb->use_count below. Pairs with the barriers in

+ * __usb_hcd_giveback_urb() and usb_hcd_submit_urb().
+ */
+ smp_mb__after_atomic();

usb_hcd_unlink_urb(urb, -ENOENT);
wait_event(usb_kill_urb_queue, atomic_read(&urb->use_count) == 0);
@@ -756,6 +762,12 @@ void usb_poison_urb(struct urb *urb)
if (!urb)
return;
atomic_inc(&urb->reject);
+ /*

+ * Order the write of urb->reject above before the read
+ * of urb->use_count below. Pairs with the barriers in

syzbot

unread,

Sep 18, 2022, 9:54:31 PM9/18/22

to admi...@boc.com, bra...@kernel.org, bro...@kernel.org, catalin...@arm.com, ebie...@xmission.com, gre...@linuxfoundation.org, hda...@sina.com, jo...@kernel.org, linux-ar...@lists.infradead.org, linux-...@vger.kernel.org, linu...@vger.kernel.org, madv...@linux.microsoft.com, mark.r...@arm.com, paskr...@gmail.com, qiaz...@amazon.co.jp, sc...@os.amperecomputing.com, sta...@vger.kernel.org, st...@rowland.harvard.edu, sup...@tokocrypto.com, syzkall...@googlegroups.com, wi...@kernel.org

syzbot has found a reproducer for the following issue on:

HEAD commit: a6b443748715 Merge branch 'for-next/core', remote-tracking..
git tree: git://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux.git for-kernelci
console output: https://syzkaller.appspot.com/x/log.txt?x=16b7e0f8880000
kernel config: https://syzkaller.appspot.com/x/.config?x=14bf9ec0df433b27
dashboard link: https://syzkaller.appspot.com/bug?extid=76629376e06e2c2ad626
compiler: Debian clang version 13.0.1-++20220126092033+75e33f71c2da-1~exp1~20220126212112.63, GNU ld (GNU Binutils for Debian) 2.35.2
userspace arch: arm64
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=111ff2d5080000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=11667887080000

Downloadable assets:
disk image: https://storage.googleapis.com/81b491dd5861/disk-a6b44374.raw.xz
vmlinux: https://storage.googleapis.com/69c979cdc99a/vmlinux-a6b44374.xz

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+766293...@syzkaller.appspotmail.com

INFO: task kworker/0:0:6 blocked for more than 143 seconds.
Not tainted 6.0.0-rc4-syzkaller-17255-ga6b443748715 #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:kworker/0:0 state:D stack: 0 pid: 6 ppid: 2 flags:0x00000008
Workqueue: usb_hub_wq hub_event
Call trace:
__switch_to+0x180/0x28c arch/arm64/kernel/process.c:557
context_switch kernel/sched/core.c:5182 [inline]
__schedule+0x414/0x5a0 kernel/sched/core.c:6494
schedule+0x64/0xa4 kernel/sched/core.c:6570
usb_kill_urb+0xe0/0x1c8 drivers/usb/core/urb.c:726
usb_start_wait_urb+0xf8/0x1ec drivers/usb/core/message.c:64
usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
usb_control_msg+0xd8/0x17c drivers/usb/core/message.c:153
hub_port_init+0x534/0x1064 drivers/usb/core/hub.c:4825
hub_port_connect+0x528/0xe30 drivers/usb/core/hub.c:5282
hub_port_connect_change+0x3d8/0x70c drivers/usb/core/hub.c:5497
port_event+0x780/0x930 drivers/usb/core/hub.c:5653
hub_event+0x2f0/0x658 drivers/usb/core/hub.c:5735
process_one_work+0x2d8/0x504 kernel/workqueue.c:2289
worker_thread+0x340/0x610 kernel/workqueue.c:2436
kthread+0x12c/0x158 kernel/kthread.c:376
ret_from_fork+0x10/0x20
INFO: task kworker/1:0:20 blocked for more than 143 seconds.
Not tainted 6.0.0-rc4-syzkaller-17255-ga6b443748715 #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:kworker/1:0 state:D stack: 0 pid: 20 ppid: 2 flags:0x00000008
Workqueue: usb_hub_wq hub_event
Call trace:
__switch_to+0x180/0x28c arch/arm64/kernel/process.c:557
context_switch kernel/sched/core.c:5182 [inline]
__schedule+0x414/0x5a0 kernel/sched/core.c:6494
schedule+0x64/0xa4 kernel/sched/core.c:6570
usb_kill_urb+0xe0/0x1c8 drivers/usb/core/urb.c:726
usb_start_wait_urb+0xf8/0x1ec drivers/usb/core/message.c:64
usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
usb_control_msg+0xd8/0x17c drivers/usb/core/message.c:153
hub_port_init+0x534/0x1064 drivers/usb/core/hub.c:4825
hub_port_connect+0x528/0xe30 drivers/usb/core/hub.c:5282
hub_port_connect_change+0x3d8/0x70c drivers/usb/core/hub.c:5497
port_event+0x780/0x930 drivers/usb/core/hub.c:5653
hub_event+0x2f0/0x658 drivers/usb/core/hub.c:5735
process_one_work+0x2d8/0x504 kernel/workqueue.c:2289
worker_thread+0x340/0x610 kernel/workqueue.c:2436
kthread+0x12c/0x158 kernel/kthread.c:376
ret_from_fork+0x10/0x20
INFO: task kworker/1:2:109 blocked for more than 143 seconds.
Not tainted 6.0.0-rc4-syzkaller-17255-ga6b443748715 #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:kworker/1:2 state:D stack: 0 pid: 109 ppid: 2 flags:0x00000008
Workqueue: usb_hub_wq hub_event
Call trace:
__switch_to+0x180/0x28c arch/arm64/kernel/process.c:557
context_switch kernel/sched/core.c:5182 [inline]
__schedule+0x414/0x5a0 kernel/sched/core.c:6494
schedule+0x64/0xa4 kernel/sched/core.c:6570
usb_kill_urb+0xe0/0x1c8 drivers/usb/core/urb.c:726
usb_start_wait_urb+0xf8/0x1ec drivers/usb/core/message.c:64
usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
usb_control_msg+0xd8/0x17c drivers/usb/core/message.c:153
hub_port_init+0x534/0x1064 drivers/usb/core/hub.c:4825
hub_port_connect+0x528/0xe30 drivers/usb/core/hub.c:5282
hub_port_connect_change+0x3d8/0x70c drivers/usb/core/hub.c:5497
port_event+0x780/0x930 drivers/usb/core/hub.c:5653
hub_event+0x2f0/0x658 drivers/usb/core/hub.c:5735
process_one_work+0x2d8/0x504 kernel/workqueue.c:2289
worker_thread+0x340/0x610 kernel/workqueue.c:2436
kthread+0x12c/0x158 kernel/kthread.c:376
ret_from_fork+0x10/0x20
INFO: task syz-executor535:3088 blocked for more than 143 seconds.
Not tainted 6.0.0-rc4-syzkaller-17255-ga6b443748715 #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:syz-executor535 state:D stack: 0 pid: 3088 ppid: 3083 flags:0x00000001
Call trace:
__switch_to+0x180/0x28c arch/arm64/kernel/process.c:557
context_switch kernel/sched/core.c:5182 [inline]
__schedule+0x414/0x5a0 kernel/sched/core.c:6494
schedule+0x64/0xa4 kernel/sched/core.c:6570
schedule_preempt_disabled+0x18/0x2c kernel/sched/core.c:6629
__mutex_lock_common+0x788/0xca8 kernel/locking/mutex.c:679
__mutex_lock kernel/locking/mutex.c:747 [inline]
mutex_lock_nested+0x38/0x44 kernel/locking/mutex.c:799
device_lock include/linux/device.h:835 [inline]
usbdev_release+0x40/0x3b8 drivers/usb/core/devio.c:1087
__fput+0x198/0x3dc fs/file_table.c:320
____fput+0x20/0x30 fs/file_table.c:353
task_work_run+0xc4/0x14c kernel/task_work.c:177
resume_user_mode_work include/linux/resume_user_mode.h:49 [inline]
do_notify_resume+0x174/0x1f0 arch/arm64/kernel/signal.c:1127
prepare_exit_to_user_mode arch/arm64/kernel/entry-common.c:137 [inline]
exit_to_user_mode arch/arm64/kernel/entry-common.c:142 [inline]
el0_svc+0x9c/0x150 arch/arm64/kernel/entry-common.c:625
el0t_64_sync_handler+0x84/0xf0 arch/arm64/kernel/entry-common.c:642
el0t_64_sync+0x18c/0x190
INFO: task kworker/0:1:3090 blocked for more than 143 seconds.
Not tainted 6.0.0-rc4-syzkaller-17255-ga6b443748715 #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:kworker/0:1 state:D stack: 0 pid: 3090 ppid: 2 flags:0x00000008
Workqueue: usb_hub_wq hub_event
Call trace:
__switch_to+0x180/0x28c arch/arm64/kernel/process.c:557
context_switch kernel/sched/core.c:5182 [inline]
__schedule+0x414/0x5a0 kernel/sched/core.c:6494
schedule+0x64/0xa4 kernel/sched/core.c:6570
usb_kill_urb+0xe0/0x1c8 drivers/usb/core/urb.c:726
usb_start_wait_urb+0xf8/0x1ec drivers/usb/core/message.c:64
usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
usb_control_msg+0xd8/0x17c drivers/usb/core/message.c:153
hub_port_init+0x534/0x1064 drivers/usb/core/hub.c:4825
hub_port_connect+0x528/0xe30 drivers/usb/core/hub.c:5282
hub_port_connect_change+0x3d8/0x70c drivers/usb/core/hub.c:5497
port_event+0x780/0x930 drivers/usb/core/hub.c:5653
hub_event+0x2f0/0x658 drivers/usb/core/hub.c:5735
process_one_work+0x2d8/0x504 kernel/workqueue.c:2289
worker_thread+0x340/0x610 kernel/workqueue.c:2436
kthread+0x12c/0x158 kernel/kthread.c:376
ret_from_fork+0x10/0x20
INFO: task syz-executor535:3091 blocked for more than 143 seconds.
Not tainted 6.0.0-rc4-syzkaller-17255-ga6b443748715 #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:syz-executor535 state:D stack: 0 pid: 3091 ppid: 3080 flags:0x00000001
Call trace:
__switch_to+0x180/0x28c arch/arm64/kernel/process.c:557
context_switch kernel/sched/core.c:5182 [inline]
__schedule+0x414/0x5a0 kernel/sched/core.c:6494
schedule+0x64/0xa4 kernel/sched/core.c:6570
schedule_preempt_disabled+0x18/0x2c kernel/sched/core.c:6629
__mutex_lock_common+0x788/0xca8 kernel/locking/mutex.c:679
__mutex_lock kernel/locking/mutex.c:747 [inline]
mutex_lock_nested+0x38/0x44 kernel/locking/mutex.c:799
device_lock include/linux/device.h:835 [inline]
usbdev_release+0x40/0x3b8 drivers/usb/core/devio.c:1087
__fput+0x198/0x3dc fs/file_table.c:320
____fput+0x20/0x30 fs/file_table.c:353
task_work_run+0xc4/0x14c kernel/task_work.c:177
resume_user_mode_work include/linux/resume_user_mode.h:49 [inline]
do_notify_resume+0x174/0x1f0 arch/arm64/kernel/signal.c:1127
prepare_exit_to_user_mode arch/arm64/kernel/entry-common.c:137 [inline]
exit_to_user_mode arch/arm64/kernel/entry-common.c:142 [inline]
el0_svc+0x9c/0x150 arch/arm64/kernel/entry-common.c:625
el0t_64_sync_handler+0x84/0xf0 arch/arm64/kernel/entry-common.c:642
el0t_64_sync+0x18c/0x190
INFO: task syz-executor535:3092 blocked for more than 143 seconds.
Not tainted 6.0.0-rc4-syzkaller-17255-ga6b443748715 #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:syz-executor535 state:D stack: 0 pid: 3092 ppid: 3082 flags:0x00000001
Call trace:
__switch_to+0x180/0x28c arch/arm64/kernel/process.c:557
context_switch kernel/sched/core.c:5182 [inline]
__schedule+0x414/0x5a0 kernel/sched/core.c:6494
schedule+0x64/0xa4 kernel/sched/core.c:6570
schedule_preempt_disabled+0x18/0x2c kernel/sched/core.c:6629
__mutex_lock_common+0x788/0xca8 kernel/locking/mutex.c:679
__mutex_lock kernel/locking/mutex.c:747 [inline]
mutex_lock_nested+0x38/0x44 kernel/locking/mutex.c:799
device_lock include/linux/device.h:835 [inline]
usbdev_release+0x40/0x3b8 drivers/usb/core/devio.c:1087
__fput+0x198/0x3dc fs/file_table.c:320
____fput+0x20/0x30 fs/file_table.c:353
task_work_run+0xc4/0x14c kernel/task_work.c:177
resume_user_mode_work include/linux/resume_user_mode.h:49 [inline]
do_notify_resume+0x174/0x1f0 arch/arm64/kernel/signal.c:1127
prepare_exit_to_user_mode arch/arm64/kernel/entry-common.c:137 [inline]
exit_to_user_mode arch/arm64/kernel/entry-common.c:142 [inline]
el0_svc+0x9c/0x150 arch/arm64/kernel/entry-common.c:625
el0t_64_sync_handler+0x84/0xf0 arch/arm64/kernel/entry-common.c:642
el0t_64_sync+0x18c/0x190
INFO: task syz-executor535:3096 blocked for more than 143 seconds.
Not tainted 6.0.0-rc4-syzkaller-17255-ga6b443748715 #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:syz-executor535 state:D stack: 0 pid: 3096 ppid: 3084 flags:0x00000001
Call trace:
__switch_to+0x180/0x28c arch/arm64/kernel/process.c:557
context_switch kernel/sched/core.c:5182 [inline]
__schedule+0x414/0x5a0 kernel/sched/core.c:6494
schedule+0x64/0xa4 kernel/sched/core.c:6570
schedule_preempt_disabled+0x18/0x2c kernel/sched/core.c:6629
__mutex_lock_common+0x788/0xca8 kernel/locking/mutex.c:679
__mutex_lock kernel/locking/mutex.c:747 [inline]
mutex_lock_nested+0x38/0x44 kernel/locking/mutex.c:799
device_lock include/linux/device.h:835 [inline]
usbdev_release+0x40/0x3b8 drivers/usb/core/devio.c:1087
__fput+0x198/0x3dc fs/file_table.c:320
____fput+0x20/0x30 fs/file_table.c:353
task_work_run+0xc4/0x14c kernel/task_work.c:177
resume_user_mode_work include/linux/resume_user_mode.h:49 [inline]
do_notify_resume+0x174/0x1f0 arch/arm64/kernel/signal.c:1127
prepare_exit_to_user_mode arch/arm64/kernel/entry-common.c:137 [inline]
exit_to_user_mode arch/arm64/kernel/entry-common.c:142 [inline]
el0_svc+0x9c/0x150 arch/arm64/kernel/entry-common.c:625
el0t_64_sync_handler+0x84/0xf0 arch/arm64/kernel/entry-common.c:642
el0t_64_sync+0x18c/0x190
INFO: task syz-executor535:3099 blocked for more than 143 seconds.
Not tainted 6.0.0-rc4-syzkaller-17255-ga6b443748715 #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:syz-executor535 state:D stack: 0 pid: 3099 ppid: 3076 flags:0x00000001
Call trace:
__switch_to+0x180/0x28c arch/arm64/kernel/process.c:557
context_switch kernel/sched/core.c:5182 [inline]
__schedule+0x414/0x5a0 kernel/sched/core.c:6494
schedule+0x64/0xa4 kernel/sched/core.c:6570
schedule_preempt_disabled+0x18/0x2c kernel/sched/core.c:6629
__mutex_lock_common+0x788/0xca8 kernel/locking/mutex.c:679
__mutex_lock kernel/locking/mutex.c:747 [inline]
mutex_lock_nested+0x38/0x44 kernel/locking/mutex.c:799
device_lock include/linux/device.h:835 [inline]
usbdev_release+0x40/0x3b8 drivers/usb/core/devio.c:1087
__fput+0x198/0x3dc fs/file_table.c:320
____fput+0x20/0x30 fs/file_table.c:353
task_work_run+0xc4/0x14c kernel/task_work.c:177
resume_user_mode_work include/linux/resume_user_mode.h:49 [inline]
do_notify_resume+0x174/0x1f0 arch/arm64/kernel/signal.c:1127
prepare_exit_to_user_mode arch/arm64/kernel/entry-common.c:137 [inline]
exit_to_user_mode arch/arm64/kernel/entry-common.c:142 [inline]
el0_svc+0x9c/0x150 arch/arm64/kernel/entry-common.c:625
el0t_64_sync_handler+0x84/0xf0 arch/arm64/kernel/entry-common.c:642
el0t_64_sync+0x18c/0x190
INFO: task kworker/1:1:3101 blocked for more than 143 seconds.
Not tainted 6.0.0-rc4-syzkaller-17255-ga6b443748715 #0

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

task:kworker/1:1 state:D stack: 0 pid: 3101 ppid: 2 flags:0x00000008
Workqueue: usb_hub_wq hub_event
Call trace:
__switch_to+0x180/0x28c arch/arm64/kernel/process.c:557
context_switch kernel/sched/core.c:5182 [inline]
__schedule+0x414/0x5a0 kernel/sched/core.c:6494
schedule+0x64/0xa4 kernel/sched/core.c:6570
usb_kill_urb+0xe0/0x1c8 drivers/usb/core/urb.c:726
usb_start_wait_urb+0xf8/0x1ec drivers/usb/core/message.c:64
usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
usb_control_msg+0xd8/0x17c drivers/usb/core/message.c:153
hub_port_init+0x534/0x1064 drivers/usb/core/hub.c:4825
hub_port_connect+0x528/0xe30 drivers/usb/core/hub.c:5282
hub_port_connect_change+0x3d8/0x70c drivers/usb/core/hub.c:5497
port_event+0x780/0x930 drivers/usb/core/hub.c:5653
hub_event+0x2f0/0x658 drivers/usb/core/hub.c:5735
process_one_work+0x2d8/0x504 kernel/workqueue.c:2289
worker_thread+0x340/0x610 kernel/workqueue.c:2436
kthread+0x12c/0x158 kernel/kthread.c:376
ret_from_fork+0x10/0x20

Showing all locks held in the system:

5 locks held by kworker/0:0/6:
#0: ffff0000c0c12138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x270/0x504 kernel/workqueue.c:2262
#1: ffff80000f21bd80 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x29c/0x504 kernel/workqueue.c:2264
#2: ffff0000c4a87990 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:835 [inline]
#2: ffff0000c4a87990 (&dev->mutex){....}-{3:3}, at: hub_event+0x8c/0x658 drivers/usb/core/hub.c:5681
#3: ffff0000c6299508 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3103 [inline]
#3: ffff0000c6299508 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect+0x33c/0xe30 drivers/usb/core/hub.c:5249
#4: ffff0000c66b8468 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect+0x348/0xe30 drivers/usb/core/hub.c:5250
1 lock held by rcu_tasks_kthre/10:
#0: ffff80000d4634e8 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x3c/0x450 kernel/rcu/tasks.h:507
1 lock held by rcu_tasks_trace/11:
#0: ffff80000d463b38 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x3c/0x450 kernel/rcu/tasks.h:507
5 locks held by kworker/1:0/20:
#0: ffff0000c0c12138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x270/0x504 kernel/workqueue.c:2262
#1: ffff80000f293d80 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x29c/0x504 kernel/workqueue.c:2264
#2: ffff0000c622f990 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:835 [inline]
#2: ffff0000c622f990 (&dev->mutex){....}-{3:3}, at: hub_event+0x8c/0x658 drivers/usb/core/hub.c:5681
#3: ffff0000c4bf1508 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3103 [inline]
#3: ffff0000c4bf1508 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect+0x33c/0xe30 drivers/usb/core/hub.c:5249
#4: ffff0000c64c9168 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect+0x348/0xe30 drivers/usb/core/hub.c:5250
1 lock held by khungtaskd/26:
#0: ffff80000d4633c0 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x4/0x48 include/linux/rcupdate.h:279
5 locks held by kworker/1:2/109:
#0: ffff0000c0c12138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x270/0x504 kernel/workqueue.c:2262
#1: ffff8000126ebd80 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x29c/0x504 kernel/workqueue.c:2264
#2: ffff0000c5283990 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:835 [inline]
#2: ffff0000c5283990 (&dev->mutex){....}-{3:3}, at: hub_event+0x8c/0x658 drivers/usb/core/hub.c:5681
#3: ffff0000c5285508 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3103 [inline]
#3: ffff0000c5285508 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect+0x33c/0xe30 drivers/usb/core/hub.c:5249
#4: ffff0000c64d2368 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect+0x348/0xe30 drivers/usb/core/hub.c:5250
2 locks held by getty/2728:
#0: ffff0000c6f4d898 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x28/0x58 drivers/tty/tty_ldisc.c:244
#1: ffff80000f63e2f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x19c/0x89c drivers/tty/n_tty.c:2177
1 lock held by syz-executor535/3088:
#0: ffff0000c5283990 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:835 [inline]
#0: ffff0000c5283990 (&dev->mutex){....}-{3:3}, at: usbdev_release+0x40/0x3b8 drivers/usb/core/devio.c:1087
5 locks held by kworker/0:1/3090:
#0: ffff0000c0c12138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x270/0x504 kernel/workqueue.c:2262
#1: ffff8000127a3d80 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x29c/0x504 kernel/workqueue.c:2264
#2: ffff0000c6289990 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:835 [inline]
#2: ffff0000c6289990 (&dev->mutex){....}-{3:3}, at: hub_event+0x8c/0x658 drivers/usb/core/hub.c:5681
#3: ffff0000c628b508 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3103 [inline]
#3: ffff0000c628b508 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect+0x33c/0xe30 drivers/usb/core/hub.c:5249
#4: ffff0000c66b8f68 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect+0x348/0xe30 drivers/usb/core/hub.c:5250
1 lock held by syz-executor535/3091:
#0: ffff0000c5283990 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:835 [inline]
#0: ffff0000c5283990 (&dev->mutex){....}-{3:3}, at: usbdev_release+0x40/0x3b8 drivers/usb/core/devio.c:1087
1 lock held by syz-executor535/3092:
#0: ffff0000c5283990 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:835 [inline]
#0: ffff0000c5283990 (&dev->mutex){....}-{3:3}, at: usbdev_release+0x40/0x3b8 drivers/usb/core/devio.c:1087
1 lock held by syz-executor535/3096:
#0: ffff0000c5283990 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:835 [inline]
#0: ffff0000c5283990 (&dev->mutex){....}-{3:3}, at: usbdev_release+0x40/0x3b8 drivers/usb/core/devio.c:1087
1 lock held by syz-executor535/3099:
#0: ffff0000c5283990 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:835 [inline]
#0: ffff0000c5283990 (&dev->mutex){....}-{3:3}, at: usbdev_release+0x40/0x3b8 drivers/usb/core/devio.c:1087
5 locks held by kworker/1:1/3101:
#0: ffff0000c0c12138 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x270/0x504 kernel/workqueue.c:2262
#1: ffff800012863d80 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x29c/0x504 kernel/workqueue.c:2264
#2: ffff0000c62c9190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:835 [inline]
#2: ffff0000c62c9190 (&dev->mutex){....}-{3:3}, at: hub_event+0x8c/0x658 drivers/usb/core/hub.c:5681
#3: ffff0000c62cb508 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3103 [inline]
#3: ffff0000c62cb508 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect+0x33c/0xe30 drivers/usb/core/hub.c:5249
#4: ffff0000c64d2d68 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect+0x348/0xe30 drivers/usb/core/hub.c:5250
1 lock held by syz-executor535/3102:
#0: ffff0000c5283990 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:835 [inline]
#0: ffff0000c5283990 (&dev->mutex){....}-{3:3}, at: usbdev_open+0xb0/0x370 drivers/usb/core/devio.c:1042

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

Hillf Danton

unread,

Sep 19, 2022, 7:10:49 AM9/19/22

to syzbot, linux-...@vger.kernel.org, syzkall...@googlegroups.com

On 18 Sep 2022 18:54:31 -0700

>
> syzbot has found a reproducer for the following issue on:
>
> HEAD commit: a6b443748715 Merge branch 'for-next/core', remote-tracking..
> git tree: git://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux.git for-kernelci
> console output: https://syzkaller.appspot.com/x/log.txt?x=16b7e0f8880000
> kernel config: https://syzkaller.appspot.com/x/.config?x=14bf9ec0df433b27
> dashboard link: https://syzkaller.appspot.com/bug?extid=76629376e06e2c2ad626
> compiler: Debian clang version 13.0.1-++20220126092033+75e33f71c2da-1~exp1~20220126212112.63, GNU ld (GNU Binutils for Debian) 2.35.2
> userspace arch: arm64
> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=111ff2d5080000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=11667887080000

> INFO: task kworker/0:0:6 blocked for more than 143 seconds.

See how many seconds it would take to kill a urb.

If it will take more than 143s to do the job then this report is bogus.

#syz test https://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux.git a6b443748715

--- x/drivers/usb/core/urb.c
+++ u/drivers/usb/core/urb.c
@@ -711,6 +711,7 @@ EXPORT_SYMBOL_GPL(usb_unlink_urb);
*/
void usb_kill_urb(struct urb *urb)
{
+ int i;
might_sleep();

if (!(urb && urb->dev && urb->ep))
return;

@@ -723,7 +724,15 @@ void usb_kill_urb(struct urb *urb)
smp_mb__after_atomic();

usb_hcd_unlink_urb(urb, -ENOENT);
- wait_event(usb_kill_urb_queue, atomic_read(&urb->use_count) == 0);
+
+ for (i = 1;; i++) {
+ if (!wait_event_timeout(usb_kill_urb_queue,
+ atomic_read(&urb->use_count) == 0, 5*HZ))
+ continue;
+ WARN_ONCE(i > 27, "It took more than %d seconds to kill a urb\n",
+ (i - 1) *5);
+ break;
+ }

atomic_dec(&urb->reject);
}
--

syzbot

unread,

Sep 19, 2022, 7:37:27 AM9/19/22

to hda...@sina.com, linux-...@vger.kernel.org, syzkall...@googlegroups.com

Hello,

syzbot has tested the proposed patch but the reproducer is still triggering an issue:
INFO: rcu detected stall in corrupted

rcu: INFO: rcu_preempt detected expedited stalls on CPUs/tasks: { P3497 } 2645 jiffies s: 2025 root: 0x0/T
rcu: blocking rcu_node structures (internal RCU debug):

Tested on:

commit: a6b44374 Merge branch 'for-next/core', remote-tracking..
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux.git
console output: https://syzkaller.appspot.com/x/log.txt?x=120d7937080000

kernel config: https://syzkaller.appspot.com/x/.config?x=14bf9ec0df433b27
dashboard link: https://syzkaller.appspot.com/bug?extid=76629376e06e2c2ad626
compiler: Debian clang version 13.0.1-++20220126092033+75e33f71c2da-1~exp1~20220126212112.63, GNU ld (GNU Binutils for Debian) 2.35.2
userspace arch: arm64

patch: https://syzkaller.appspot.com/x/patch.diff?x=11a15337080000

Reply all

Reply to author

Forward

0 new messages