* [syzbot] [usb?] INFO: task hung in hub_port_init (3)
@ 2023-03-28 12:23 syzbot
2023-06-09 19:25 ` syzbot
0 siblings, 1 reply; 9+ messages in thread
From: syzbot @ 2023-03-28 12:23 UTC (permalink / raw)
To: gregkh, linux-kernel, linux-usb, syzkaller-bugs
Hello,
syzbot found the following issue on:
HEAD commit: fff5a5e7f528 Merge tag 'for-linus' of git://git.armlinux.o..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=1283ef16c80000
kernel config: https://syzkaller.appspot.com/x/.config?x=d40f6d44826f6cf7
dashboard link: https://syzkaller.appspot.com/bug?extid=b6f11035e572f08bc20f
compiler: Debian clang version 15.0.7, GNU ld (GNU Binutils for Debian) 2.35.2
Unfortunately, I don't have any reproducer for this issue yet.
Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/7bbf96292b2f/disk-fff5a5e7.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/65b622a8d0af/vmlinux-fff5a5e7.xz
kernel image: https://storage.googleapis.com/syzbot-assets/736865f3bb58/bzImage-fff5a5e7.xz
IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+b6f11035e572f08bc20f@syzkaller.appspotmail.com
INFO: task kworker/1:10:9980 blocked for more than 143 seconds.
Not tainted 6.3.0-rc3-syzkaller-00026-gfff5a5e7f528 #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:10 state:D stack:22992 pid:9980 ppid:2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5304 [inline]
__schedule+0x173b/0x4630 kernel/sched/core.c:6622
schedule+0xc3/0x180 kernel/sched/core.c:6698
usb_kill_urb+0x1c9/0x300 drivers/usb/core/urb.c:728
usb_start_wait_urb+0x1b0/0x520 drivers/usb/core/message.c:64
usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
usb_control_msg+0x2b1/0x4c0 drivers/usb/core/message.c:153
hub_port_init+0xa9f/0x2530 drivers/usb/core/hub.c:4874
hub_port_connect drivers/usb/core/hub.c:5336 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
port_event drivers/usb/core/hub.c:5711 [inline]
hub_event+0x2bbf/0x5460 drivers/usb/core/hub.c:5793
process_one_work+0x8a0/0x10e0 kernel/workqueue.c:2390
worker_thread+0xa63/0x1210 kernel/workqueue.c:2537
kthread+0x270/0x300 kernel/kthread.c:376
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>
INFO: task kworker/1:13:10611 blocked for more than 143 seconds.
Not tainted 6.3.0-rc3-syzkaller-00026-gfff5a5e7f528 #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:13 state:D stack:25016 pid:10611 ppid:2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5304 [inline]
__schedule+0x173b/0x4630 kernel/sched/core.c:6622
schedule+0xc3/0x180 kernel/sched/core.c:6698
usb_kill_urb+0x1c9/0x300 drivers/usb/core/urb.c:728
usb_start_wait_urb+0x1b0/0x520 drivers/usb/core/message.c:64
usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
usb_control_msg+0x2b1/0x4c0 drivers/usb/core/message.c:153
hub_port_init+0xa9f/0x2530 drivers/usb/core/hub.c:4874
hub_port_connect drivers/usb/core/hub.c:5336 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
port_event drivers/usb/core/hub.c:5711 [inline]
hub_event+0x2bbf/0x5460 drivers/usb/core/hub.c:5793
process_one_work+0x8a0/0x10e0 kernel/workqueue.c:2390
worker_thread+0xa63/0x1210 kernel/workqueue.c:2537
kthread+0x270/0x300 kernel/kthread.c:376
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>
INFO: task kworker/1:15:10757 blocked for more than 144 seconds.
Not tainted 6.3.0-rc3-syzkaller-00026-gfff5a5e7f528 #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:15 state:D stack:25112 pid:10757 ppid:2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5304 [inline]
__schedule+0x173b/0x4630 kernel/sched/core.c:6622
schedule+0xc3/0x180 kernel/sched/core.c:6698
usb_kill_urb+0x1c9/0x300 drivers/usb/core/urb.c:728
usb_start_wait_urb+0x1b0/0x520 drivers/usb/core/message.c:64
usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
usb_control_msg+0x2b1/0x4c0 drivers/usb/core/message.c:153
hub_port_init+0xa9f/0x2530 drivers/usb/core/hub.c:4874
hub_port_connect drivers/usb/core/hub.c:5336 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
port_event drivers/usb/core/hub.c:5711 [inline]
hub_event+0x2bbf/0x5460 drivers/usb/core/hub.c:5793
process_one_work+0x8a0/0x10e0 kernel/workqueue.c:2390
worker_thread+0xa63/0x1210 kernel/workqueue.c:2537
kthread+0x270/0x300 kernel/kthread.c:376
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>
Showing all locks held in the system:
1 lock held by rcu_tasks_kthre/12:
#0: ffffffff8cf255f0 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x29/0xd20 kernel/rcu/tasks.h:510
1 lock held by rcu_tasks_trace/13:
#0: ffffffff8cf25df0 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x29/0xd20 kernel/rcu/tasks.h:510
1 lock held by khungtaskd/28:
#0: ffffffff8cf25420 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire+0x0/0x30
3 locks held by kworker/u4:3/46:
#0: ffff8880b983be98 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested+0xb0/0x140 kernel/sched/core.c:547
#1: ffffc90000b77d20 ((work_completion)(&(&bat_priv->nc.work)->work)){+.+.}-{0:0}, at: process_one_work+0x7c8/0x10e0 kernel/workqueue.c:2365
#2: ffff8880b9929598 (&base->lock){-.-.}-{2:2}, at: lock_timer_base+0x120/0x260 kernel/time/timer.c:999
2 locks held by getty/4746:
#0: ffff88814a687098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x25/0x70 drivers/tty/tty_ldisc.c:244
#1: ffffc900015b02f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x6ab/0x1db0 drivers/tty/n_tty.c:2177
5 locks held by kworker/1:10/9980:
#0: ffff888017d04538 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x77e/0x10e0 kernel/workqueue.c:2363
#1: ffffc9000b06fd20 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x7c8/0x10e0 kernel/workqueue.c:2365
#2: ffff888021e2d190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:832 [inline]
#2: ffff888021e2d190 (&dev->mutex){....}-{3:3}, at: hub_event+0x20e/0x5460 drivers/usb/core/hub.c:5739
#3: ffff888021e484f8 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3147 [inline]
#3: ffff888021e484f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5303 [inline]
#3: ffff888021e484f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
#3: ffff888021e484f8 (&port_dev->status_lock){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5711 [inline]
#3: ffff888021e484f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_event+0x252f/0x5460 drivers/usb/core/hub.c:5793
#4: ffff888021db0068 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5304 [inline]
#4: ffff888021db0068 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
#4: ffff888021db0068 (hcd->address0_mutex){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5711 [inline]
#4: ffff888021db0068 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_event+0x2564/0x5460 drivers/usb/core/hub.c:5793
3 locks held by kworker/0:14/10515:
#0: ffff888012470d38 ((wq_completion)events){+.+.}-{0:0}, at: process_one_work+0x77e/0x10e0 kernel/workqueue.c:2363
#1: ffffc900162b7d20 ((work_completion)(&pwq->unbound_release_work)){+.+.}-{0:0}, at: process_one_work+0x7c8/0x10e0 kernel/workqueue.c:2365
#2: ffffffff8cf2a8f8 (rcu_state.exp_mutex){+.+.}-{3:3}, at: exp_funnel_lock kernel/rcu/tree_exp.h:325 [inline]
#2: ffffffff8cf2a8f8 (rcu_state.exp_mutex){+.+.}-{3:3}, at: synchronize_rcu_expedited+0x46c/0x890 kernel/rcu/tree_exp.h:989
5 locks held by kworker/1:13/10611:
#0: ffff888017d04538 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x77e/0x10e0 kernel/workqueue.c:2363
#1: ffffc900033cfd20 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x7c8/0x10e0 kernel/workqueue.c:2365
#2: ffff8880219ef190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:832 [inline]
#2: ffff8880219ef190 (&dev->mutex){....}-{3:3}, at: hub_event+0x20e/0x5460 drivers/usb/core/hub.c:5739
#3: ffff8881474bb4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3147 [inline]
#3: ffff8881474bb4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5303 [inline]
#3: ffff8881474bb4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
#3: ffff8881474bb4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5711 [inline]
#3: ffff8881474bb4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_event+0x252f/0x5460 drivers/usb/core/hub.c:5793
#4: ffff8880217e4968 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5304 [inline]
#4: ffff8880217e4968 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
#4: ffff8880217e4968 (hcd->address0_mutex){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5711 [inline]
#4: ffff8880217e4968 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_event+0x2564/0x5460 drivers/usb/core/hub.c:5793
5 locks held by kworker/1:15/10757:
#0: ffff888017d04538 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x77e/0x10e0 kernel/workqueue.c:2363
#1: ffffc900039afd20 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x7c8/0x10e0 kernel/workqueue.c:2365
#2: ffff888021f09190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:832 [inline]
#2: ffff888021f09190 (&dev->mutex){....}-{3:3}, at: hub_event+0x20e/0x5460 drivers/usb/core/hub.c:5739
#3: ffff888021f0c4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3147 [inline]
#3: ffff888021f0c4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5303 [inline]
#3: ffff888021f0c4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
#3: ffff888021f0c4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5711 [inline]
#3: ffff888021f0c4f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_event+0x252f/0x5460 drivers/usb/core/hub.c:5793
#4: ffff888021ebc268 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5304 [inline]
#4: ffff888021ebc268 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
#4: ffff888021ebc268 (hcd->address0_mutex){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5711 [inline]
#4: ffff888021ebc268 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_event+0x2564/0x5460 drivers/usb/core/hub.c:5793
2 locks held by kworker/1:16/10759:
#0: ffff888012472538 ((wq_completion)rcu_gp){+.+.}-{0:0}, at: process_one_work+0x77e/0x10e0 kernel/workqueue.c:2363
#1: ffffc900039efd20 ((work_completion)(&rew->rew_work)){+.+.}-{0:0}, at: process_one_work+0x7c8/0x10e0 kernel/workqueue.c:2365
1 lock held by syz-executor.3/17813:
#0: ffffffff8e08a168 (rtnl_mutex){+.+.}-{3:3}, at: ppp_release+0x8a/0x1f0 drivers/net/ppp/ppp_generic.c:405
1 lock held by syz-executor.4/17815:
#0: ffffffff8cf2a7c0 (rcu_state.barrier_mutex){+.+.}-{3:3}, at: rcu_barrier+0x4c/0x540 kernel/rcu/tree.c:3945
1 lock held by syz-executor.1/17825:
#0: ffffffff8cf2a7c0 (rcu_state.barrier_mutex){+.+.}-{3:3}, at: rcu_barrier+0x4c/0x540 kernel/rcu/tree.c:3945
1 lock held by syz-executor.0/17832:
#0: ffffffff8cf2a7c0 (rcu_state.barrier_mutex){+.+.}-{3:3}, at: rcu_barrier+0x4c/0x540 kernel/rcu/tree.c:3945
2 locks held by syz-executor.5/17841:
#0: ffffffff8e08a168 (rtnl_mutex){+.+.}-{3:3}, at: ppp_release+0x8a/0x1f0 drivers/net/ppp/ppp_generic.c:405
#1: ffffffff8cf2a8f8 (rcu_state.exp_mutex){+.+.}-{3:3}, at: exp_funnel_lock kernel/rcu/tree_exp.h:293 [inline]
#1: ffffffff8cf2a8f8 (rcu_state.exp_mutex){+.+.}-{3:3}, at: synchronize_rcu_expedited+0x3a3/0x890 kernel/rcu/tree_exp.h:989
=============================================
NMI backtrace for cpu 1
CPU: 1 PID: 28 Comm: khungtaskd Not tainted 6.3.0-rc3-syzkaller-00026-gfff5a5e7f528 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 03/02/2023
Call Trace:
<TASK>
__dump_stack lib/dump_stack.c:88 [inline]
dump_stack_lvl+0x1e7/0x2d0 lib/dump_stack.c:106
nmi_cpu_backtrace+0x498/0x4d0 lib/nmi_backtrace.c:113
nmi_trigger_cpumask_backtrace+0x187/0x300 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:148 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:222 [inline]
watchdog+0xec2/0xf00 kernel/hung_task.c:379
kthread+0x270/0x300 kernel/kthread.c:376
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 7818 Comm: kworker/u4:15 Not tainted 6.3.0-rc3-syzkaller-00026-gfff5a5e7f528 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 03/02/2023
Workqueue: bat_events batadv_nc_worker
RIP: 0010:__lock_acquire+0x121/0x1f80 kernel/locking/lockdep.c:4959
Code: e8 03 48 89 44 24 28 0f b6 04 10 84 c0 0f 85 6d 15 00 00 48 89 6c 24 18 8b 75 00 48 c7 c0 e0 70 ad 91 48 c1 e8 03 0f b6 04 10 <84> c0 48 89 74 24 40 0f 85 70 15 00 00 83 3d eb 50 43 10 00 75 09
RSP: 0018:ffffc90015d5f9a0 EFLAGS: 00000802
RAX: 0000000000000004 RBX: ffffffff8ffd6980 RCX: 0000000000000002
RDX: dffffc0000000000 RSI: 0000000000000002 RDI: ffffffff8cf25420
RBP: ffff888026842770 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: dffffc0000000001 R12: 0000000000000002
R13: ffff888026841d40 R14: ffffffff8cf25420 R15: 0000000000000000
FS: 0000000000000000(0000) GS:ffff8880b9800000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000555556f79888 CR3: 000000003ff54000 CR4: 00000000003526f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 000000000000000a DR6: 00000000ffff0ff0 DR7: 0000000000000400
Call Trace:
<TASK>
lock_acquire+0x1e1/0x520 kernel/locking/lockdep.c:5669
rcu_lock_acquire+0x2e/0x40 include/linux/rcupdate.h:327
rcu_read_lock include/linux/rcupdate.h:773 [inline]
batadv_nc_purge_orig_hash net/batman-adv/network-coding.c:408 [inline]
batadv_nc_worker+0xc5/0x5c0 net/batman-adv/network-coding.c:719
process_one_work+0x8a0/0x10e0 kernel/workqueue.c:2390
worker_thread+0xa63/0x1210 kernel/workqueue.c:2537
kthread+0x270/0x300 kernel/kthread.c:376
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>
---
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 syzkaller@googlegroups.com.
syzbot will keep track of this issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in hub_port_init (3)
2023-03-28 12:23 [syzbot] [usb?] INFO: task hung in hub_port_init (3) syzbot
@ 2023-06-09 19:25 ` syzbot
2023-11-03 14:03 ` Muhammad Usama Anjum
0 siblings, 1 reply; 9+ messages in thread
From: syzbot @ 2023-06-09 19:25 UTC (permalink / raw)
To: gregkh, linux-kernel, linux-usb, syzkaller-bugs
syzbot has found a reproducer for the following issue on:
HEAD commit: 33f2b5785a2b Merge tag 'drm-fixes-2023-06-09' of git://ano..
git tree: upstream
console+strace: https://syzkaller.appspot.com/x/log.txt?x=1206f143280000
kernel config: https://syzkaller.appspot.com/x/.config?x=3c980bfe8b399968
dashboard link: https://syzkaller.appspot.com/bug?extid=b6f11035e572f08bc20f
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=1676f51b280000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=129632fd280000
Downloadable assets:
disk image: https://storage.googleapis.com/syzbot-assets/a817d99af39d/disk-33f2b578.raw.xz
vmlinux: https://storage.googleapis.com/syzbot-assets/8916e1d053fc/vmlinux-33f2b578.xz
kernel image: https://storage.googleapis.com/syzbot-assets/e53956f3cfd4/bzImage-33f2b578.xz
IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+b6f11035e572f08bc20f@syzkaller.appspotmail.com
INFO: task kworker/0:2:901 blocked for more than 143 seconds.
Not tainted 6.4.0-rc5-syzkaller-00178-g33f2b5785a2b #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/0:2 state:D stack:26800 pid:901 ppid:2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
usb_kill_urb.part.0+0x19a/0x220 drivers/usb/core/urb.c:728
usb_kill_urb+0x83/0xa0 drivers/usb/core/urb.c:717
usb_start_wait_urb+0x24a/0x4b0 drivers/usb/core/message.c:64
usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
usb_control_msg+0x320/0x4a0 drivers/usb/core/message.c:153
hub_port_init+0x14f3/0x3900 drivers/usb/core/hub.c:4874
hub_port_connect drivers/usb/core/hub.c:5336 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
port_event drivers/usb/core/hub.c:5711 [inline]
hub_event+0x2b89/0x4e40 drivers/usb/core/hub.c:5793
process_one_work+0x99a/0x15e0 kernel/workqueue.c:2405
worker_thread+0x67d/0x10c0 kernel/workqueue.c:2552
kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>
INFO: task syz-executor104:5004 blocked for more than 143 seconds.
Not tainted 6.4.0-rc5-syzkaller-00178-g33f2b5785a2b #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz-executor104 state:D stack:26464 pid:5004 ppid:5002 flags:0x00004006
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5343 [inline]
__schedule+0xc9a/0x5880 kernel/sched/core.c:6669
schedule+0xde/0x1a0 kernel/sched/core.c:6745
schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6804
__mutex_lock_common kernel/locking/mutex.c:679 [inline]
__mutex_lock+0xa3b/0x1350 kernel/locking/mutex.c:747
device_lock include/linux/device.h:837 [inline]
usbdev_release+0x87/0x4b0 drivers/usb/core/devio.c:1094
__fput+0x27c/0xa90 fs/file_table.c:321
task_work_run+0x16f/0x270 kernel/task_work.c:179
ptrace_notify+0x118/0x140 kernel/signal.c:2371
ptrace_report_syscall include/linux/ptrace.h:411 [inline]
ptrace_report_syscall_exit include/linux/ptrace.h:473 [inline]
syscall_exit_work kernel/entry/common.c:252 [inline]
syscall_exit_to_user_mode_prepare+0x129/0x220 kernel/entry/common.c:279
__syscall_exit_to_user_mode_work kernel/entry/common.c:284 [inline]
syscall_exit_to_user_mode+0xd/0x50 kernel/entry/common.c:297
do_syscall_64+0x46/0xb0 arch/x86/entry/common.c:86
entry_SYSCALL_64_after_hwframe+0x63/0xcd
RIP: 0033:0x7f7118e08653
RSP: 002b:00007fff91a87278 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
RAX: 0000000000000000 RBX: 0000000000000004 RCX: 00007f7118e08653
RDX: 0000000000000007 RSI: 00007fff91a86da0 RDI: 0000000000000003
RBP: 00007fff91a872d0 R08: 0000000000000000 R09: 00007fff91a86cf0
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000000f4240
R13: 0000000000000000 R14: 00007fff91a872c0 R15: 00007fff91a872b0
</TASK>
Showing all locks held in the system:
1 lock held by rcu_tasks_kthre/13:
#0: ffffffff8c7984b0 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:518
1 lock held by rcu_tasks_trace/14:
#0: ffffffff8c7981b0 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:518
1 lock held by khungtaskd/28:
#0: ffffffff8c7990c0 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x55/0x340 kernel/locking/lockdep.c:6559
5 locks held by kworker/0:2/901:
#0: ffff888147275d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
#0: ffff888147275d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic_long_set include/linux/atomic/atomic-long.h:41 [inline]
#0: ffff888147275d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic_long_set include/linux/atomic/atomic-instrumented.h:1324 [inline]
#0: ffff888147275d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:643 [inline]
#0: ffff888147275d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:670 [inline]
#0: ffff888147275d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x883/0x15e0 kernel/workqueue.c:2376
#1: ffffc900056c7db0 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x8b7/0x15e0 kernel/workqueue.c:2380
#2: ffff888142f77190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:837 [inline]
#2: ffff888142f77190 (&dev->mutex){....}-{3:3}, at: hub_event+0x1c0/0x4e40 drivers/usb/core/hub.c:5739
#3: ffff8880224434f8 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3147 [inline]
#3: ffff8880224434f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5303 [inline]
#3: ffff8880224434f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
#3: ffff8880224434f8 (&port_dev->status_lock){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5711 [inline]
#3: ffff8880224434f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_event+0x278e/0x4e40 drivers/usb/core/hub.c:5793
#4: ffff888142f01468 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5304 [inline]
#4: ffff888142f01468 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
#4: ffff888142f01468 (hcd->address0_mutex){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5711 [inline]
#4: ffff888142f01468 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_event+0x27c3/0x4e40 drivers/usb/core/hub.c:5793
2 locks held by getty/4753:
#0: ffff88802c991098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x26/0x80 drivers/tty/tty_ldisc.c:243
#1: ffffc900015902f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xef4/0x13e0 drivers/tty/n_tty.c:2176
1 lock held by syz-executor104/5004:
#0: ffff888142f77190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:837 [inline]
#0: ffff888142f77190 (&dev->mutex){....}-{3:3}, at: usbdev_release+0x87/0x4b0 drivers/usb/core/devio.c:1094
=============================================
NMI backtrace for cpu 0
CPU: 0 PID: 28 Comm: khungtaskd Not tainted 6.4.0-rc5-syzkaller-00178-g33f2b5785a2b #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 05/25/2023
Call Trace:
<TASK>
__dump_stack lib/dump_stack.c:88 [inline]
dump_stack_lvl+0xd9/0x150 lib/dump_stack.c:106
nmi_cpu_backtrace+0x29c/0x350 lib/nmi_backtrace.c:113
nmi_trigger_cpumask_backtrace+0x2a4/0x300 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:148 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:222 [inline]
watchdog+0xe16/0x1090 kernel/hung_task.c:379
kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1
CPU: 1 PID: 75 Comm: kworker/u4:4 Not tainted 6.4.0-rc5-syzkaller-00178-g33f2b5785a2b #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 05/25/2023
Workqueue: events_unbound toggle_allocation_gate
RIP: 0010:__phys_addr+0xcf/0x140 arch/x86/mm/physaddr.c:32
Code: 08 e8 35 78 4a 00 4c 89 e3 44 89 e9 31 ff 48 d3 eb 48 89 de e8 62 74 4a 00 48 85 db 75 0f e8 18 78 4a 00 4c 89 e0 5b 5d 41 5c <41> 5d c3 e8 09 78 4a 00 0f 0b e8 02 78 4a 00 48 c7 c0 10 80 59 8c
RSP: 0018:ffffc900015b7968 EFLAGS: 00000093
RAX: 0000000012463000 RBX: 0000000000000001 RCX: 0000000000000000
RDX: ffff888019abd940 RSI: ffffffff8139ce28 RDI: 0000000000000007
RBP: ffff888012468000 R08: 0000000000000007 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000001 R12: ffff888019abd940
R13: 000000000000002e R14: ffffffff8c8f6940 R15: ffffffff8c8f6900
FS: 0000000000000000(0000) GS:ffff8880b9900000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00005639543b1978 CR3: 0000000012463000 CR4: 00000000003506e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<NMI>
</NMI>
<TASK>
build_cr3 arch/x86/mm/tlb.c:159 [inline]
switch_mm_irqs_off+0xc1/0xbb0 arch/x86/mm/tlb.c:529
unuse_temporary_mm arch/x86/kernel/alternative.c:1516 [inline]
__text_poke+0x3c5/0x890 arch/x86/kernel/alternative.c:1626
text_poke arch/x86/kernel/alternative.c:1669 [inline]
text_poke_bp_batch+0x3af/0x770 arch/x86/kernel/alternative.c:1992
text_poke_flush arch/x86/kernel/alternative.c:2161 [inline]
text_poke_flush arch/x86/kernel/alternative.c:2158 [inline]
text_poke_finish+0x1a/0x30 arch/x86/kernel/alternative.c:2168
arch_jump_label_transform_apply+0x17/0x30 arch/x86/kernel/jump_label.c:146
jump_label_update+0x32f/0x410 kernel/jump_label.c:829
static_key_disable_cpuslocked+0x156/0x1b0 kernel/jump_label.c:235
static_key_disable+0x1a/0x20 kernel/jump_label.c:243
toggle_allocation_gate mm/kfence/core.c:836 [inline]
toggle_allocation_gate+0x143/0x230 mm/kfence/core.c:823
process_one_work+0x99a/0x15e0 kernel/workqueue.c:2405
worker_thread+0x67d/0x10c0 kernel/workqueue.c:2552
kthread+0x344/0x440 kernel/kthread.c:379
ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
</TASK>
INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 1.090 msecs
---
If you want syzbot to run the reproducer, reply with:
#syz test: git://repo/address.git branch-or-commit-hash
If you attach or paste a git patch, syzbot will apply it before testing.
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in hub_port_init (3)
2023-06-09 19:25 ` syzbot
@ 2023-11-03 14:03 ` Muhammad Usama Anjum
2023-11-03 15:04 ` Alan Stern
0 siblings, 1 reply; 9+ messages in thread
From: Muhammad Usama Anjum @ 2023-11-03 14:03 UTC (permalink / raw)
To: syzbot, gregkh, linux-kernel, linux-usb, syzkaller-bugs
Cc: Muhammad Usama Anjum
On 6/10/23 12:25 AM, syzbot wrote:
> syzbot has found a reproducer for the following issue on:
>
> HEAD commit: 33f2b5785a2b Merge tag 'drm-fixes-2023-06-09' of git://ano..
> git tree: upstream
> console+strace: https://syzkaller.appspot.com/x/log.txt?x=1206f143280000
> kernel config: https://syzkaller.appspot.com/x/.config?x=3c980bfe8b399968
> dashboard link: https://syzkaller.appspot.com/bug?extid=b6f11035e572f08bc20f
> 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=1676f51b280000
> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=129632fd280000
>
> Downloadable assets:
> disk image: https://storage.googleapis.com/syzbot-assets/a817d99af39d/disk-33f2b578.raw.xz
> vmlinux: https://storage.googleapis.com/syzbot-assets/8916e1d053fc/vmlinux-33f2b578.xz
> kernel image: https://storage.googleapis.com/syzbot-assets/e53956f3cfd4/bzImage-33f2b578.xz
>
> IMPORTANT: if you fix the issue, please add the following tag to the commit:
> Reported-by: syzbot+b6f11035e572f08bc20f@syzkaller.appspotmail.com
>
> INFO: task kworker/0:2:901 blocked for more than 143 seconds.
> Not tainted 6.4.0-rc5-syzkaller-00178-g33f2b5785a2b #0
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:kworker/0:2 state:D stack:26800 pid:901 ppid:2 flags:0x00004000
> Workqueue: usb_hub_wq hub_event
> Call Trace:
> <TASK>
> context_switch kernel/sched/core.c:5343 [inline]
> __schedule+0xc9a/0x5880 kernel/sched/core.c:6669
> schedule+0xde/0x1a0 kernel/sched/core.c:6745
> usb_kill_urb.part.0+0x19a/0x220 drivers/usb/core/urb.c:728
> usb_kill_urb+0x83/0xa0 drivers/usb/core/urb.c:717
> usb_start_wait_urb+0x24a/0x4b0 drivers/usb/core/message.c:64
> usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
> usb_control_msg+0x320/0x4a0 drivers/usb/core/message.c:153
> hub_port_init+0x14f3/0x3900 drivers/usb/core/hub.c:4874
> hub_port_connect drivers/usb/core/hub.c:5336 [inline]
> hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
> port_event drivers/usb/core/hub.c:5711 [inline]
> hub_event+0x2b89/0x4e40 drivers/usb/core/hub.c:5793
> process_one_work+0x99a/0x15e0 kernel/workqueue.c:2405
> worker_thread+0x67d/0x10c0 kernel/workqueue.c:2552
> kthread+0x344/0x440 kernel/kthread.c:379
> ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
> </TASK>
> INFO: task syz-executor104:5004 blocked for more than 143 seconds.
This is being reproduced on linux-next. The USB IP is being fuzzed. I'd
modified the reproducer to try to understand the issue. The execution of
application creates kworkers (can be found in hub->events). One of the usb
hub kworker gets stuck because of wrong use_count. I don't know USB side of
logic. But a worker shouldn't go to sleep indefinitely.
My debug logs are as following which can help an expert USB developer to
pin point the problem:
[ 118.904272][ T9] usb_submit_urb urb->use_count: 0
[ 118.904942][ T9] usb_hcd_submit_urb urb->use_count: 1
[ 118.905715][ T9] usb_submit_urb urb->use_count: 1
[ 118.906428][ T9] usb_start_wait_urb urb->use_count: 1
[ 123.938978][ T9] usb_kill_urb use_count: 1
At this point, wait is being done on usb_kill_urb_queue as use_count isn't
zero and no event on usb_kill_urb_queue is received.
The comment for usb_kill_urb is:
> * This routine may not be used in an interrupt context (such as a bottom
> * half or a completion handler), or when holding a spinlock, or in other
> * situations where the caller can't schedule().
But several locks are held by this kworker and sleeps indefinitely.
> Not tainted 6.4.0-rc5-syzkaller-00178-g33f2b5785a2b #0
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:syz-executor104 state:D stack:26464 pid:5004 ppid:5002 flags:0x00004006
> Call Trace:
> <TASK>
> context_switch kernel/sched/core.c:5343 [inline]
> __schedule+0xc9a/0x5880 kernel/sched/core.c:6669
> schedule+0xde/0x1a0 kernel/sched/core.c:6745
> schedule_preempt_disabled+0x13/0x20 kernel/sched/core.c:6804
> __mutex_lock_common kernel/locking/mutex.c:679 [inline]
> __mutex_lock+0xa3b/0x1350 kernel/locking/mutex.c:747
> device_lock include/linux/device.h:837 [inline]
> usbdev_release+0x87/0x4b0 drivers/usb/core/devio.c:1094
> __fput+0x27c/0xa90 fs/file_table.c:321
> task_work_run+0x16f/0x270 kernel/task_work.c:179
> ptrace_notify+0x118/0x140 kernel/signal.c:2371
> ptrace_report_syscall include/linux/ptrace.h:411 [inline]
> ptrace_report_syscall_exit include/linux/ptrace.h:473 [inline]
> syscall_exit_work kernel/entry/common.c:252 [inline]
> syscall_exit_to_user_mode_prepare+0x129/0x220 kernel/entry/common.c:279
> __syscall_exit_to_user_mode_work kernel/entry/common.c:284 [inline]
> syscall_exit_to_user_mode+0xd/0x50 kernel/entry/common.c:297
> do_syscall_64+0x46/0xb0 arch/x86/entry/common.c:86
> entry_SYSCALL_64_after_hwframe+0x63/0xcd
> RIP: 0033:0x7f7118e08653
> RSP: 002b:00007fff91a87278 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
> RAX: 0000000000000000 RBX: 0000000000000004 RCX: 00007f7118e08653
> RDX: 0000000000000007 RSI: 00007fff91a86da0 RDI: 0000000000000003
> RBP: 00007fff91a872d0 R08: 0000000000000000 R09: 00007fff91a86cf0
> R10: 0000000000000000 R11: 0000000000000246 R12: 00000000000f4240
> R13: 0000000000000000 R14: 00007fff91a872c0 R15: 00007fff91a872b0
> </TASK>
>
> Showing all locks held in the system:
> 1 lock held by rcu_tasks_kthre/13:
> #0: ffffffff8c7984b0 (rcu_tasks.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:518
> 1 lock held by rcu_tasks_trace/14:
> #0: ffffffff8c7981b0 (rcu_tasks_trace.tasks_gp_mutex){+.+.}-{3:3}, at: rcu_tasks_one_gp+0x31/0xd80 kernel/rcu/tasks.h:518
> 1 lock held by khungtaskd/28:
> #0: ffffffff8c7990c0 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x55/0x340 kernel/locking/lockdep.c:6559
> 5 locks held by kworker/0:2/901:
> #0: ffff888147275d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
> #0: ffff888147275d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: arch_atomic_long_set include/linux/atomic/atomic-long.h:41 [inline]
> #0: ffff888147275d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: atomic_long_set include/linux/atomic/atomic-instrumented.h:1324 [inline]
> #0: ffff888147275d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_data kernel/workqueue.c:643 [inline]
> #0: ffff888147275d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: set_work_pool_and_clear_pending kernel/workqueue.c:670 [inline]
> #0: ffff888147275d38 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x883/0x15e0 kernel/workqueue.c:2376
> #1: ffffc900056c7db0 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x8b7/0x15e0 kernel/workqueue.c:2380
> #2: ffff888142f77190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:837 [inline]
> #2: ffff888142f77190 (&dev->mutex){....}-{3:3}, at: hub_event+0x1c0/0x4e40 drivers/usb/core/hub.c:5739
> #3: ffff8880224434f8 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3147 [inline]
> #3: ffff8880224434f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5303 [inline]
> #3: ffff8880224434f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
> #3: ffff8880224434f8 (&port_dev->status_lock){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5711 [inline]
> #3: ffff8880224434f8 (&port_dev->status_lock){+.+.}-{3:3}, at: hub_event+0x278e/0x4e40 drivers/usb/core/hub.c:5793
> #4: ffff888142f01468 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect drivers/usb/core/hub.c:5304 [inline]
> #4: ffff888142f01468 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
> #4: ffff888142f01468 (hcd->address0_mutex){+.+.}-{3:3}, at: port_event drivers/usb/core/hub.c:5711 [inline]
> #4: ffff888142f01468 (hcd->address0_mutex){+.+.}-{3:3}, at: hub_event+0x27c3/0x4e40 drivers/usb/core/hub.c:5793
> 2 locks held by getty/4753:
> #0: ffff88802c991098 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x26/0x80 drivers/tty/tty_ldisc.c:243
> #1: ffffc900015902f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xef4/0x13e0 drivers/tty/n_tty.c:2176
> 1 lock held by syz-executor104/5004:
> #0: ffff888142f77190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:837 [inline]
> #0: ffff888142f77190 (&dev->mutex){....}-{3:3}, at: usbdev_release+0x87/0x4b0 drivers/usb/core/devio.c:1094
>
> =============================================
>
> NMI backtrace for cpu 0
> CPU: 0 PID: 28 Comm: khungtaskd Not tainted 6.4.0-rc5-syzkaller-00178-g33f2b5785a2b #0
> Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 05/25/2023
> Call Trace:
> <TASK>
> __dump_stack lib/dump_stack.c:88 [inline]
> dump_stack_lvl+0xd9/0x150 lib/dump_stack.c:106
> nmi_cpu_backtrace+0x29c/0x350 lib/nmi_backtrace.c:113
> nmi_trigger_cpumask_backtrace+0x2a4/0x300 lib/nmi_backtrace.c:62
> trigger_all_cpu_backtrace include/linux/nmi.h:148 [inline]
> check_hung_uninterruptible_tasks kernel/hung_task.c:222 [inline]
> watchdog+0xe16/0x1090 kernel/hung_task.c:379
> kthread+0x344/0x440 kernel/kthread.c:379
> ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
> </TASK>
> Sending NMI from CPU 0 to CPUs 1:
> NMI backtrace for cpu 1
> CPU: 1 PID: 75 Comm: kworker/u4:4 Not tainted 6.4.0-rc5-syzkaller-00178-g33f2b5785a2b #0
> Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 05/25/2023
> Workqueue: events_unbound toggle_allocation_gate
> RIP: 0010:__phys_addr+0xcf/0x140 arch/x86/mm/physaddr.c:32
> Code: 08 e8 35 78 4a 00 4c 89 e3 44 89 e9 31 ff 48 d3 eb 48 89 de e8 62 74 4a 00 48 85 db 75 0f e8 18 78 4a 00 4c 89 e0 5b 5d 41 5c <41> 5d c3 e8 09 78 4a 00 0f 0b e8 02 78 4a 00 48 c7 c0 10 80 59 8c
> RSP: 0018:ffffc900015b7968 EFLAGS: 00000093
> RAX: 0000000012463000 RBX: 0000000000000001 RCX: 0000000000000000
> RDX: ffff888019abd940 RSI: ffffffff8139ce28 RDI: 0000000000000007
> RBP: ffff888012468000 R08: 0000000000000007 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000001 R12: ffff888019abd940
> R13: 000000000000002e R14: ffffffff8c8f6940 R15: ffffffff8c8f6900
> FS: 0000000000000000(0000) GS:ffff8880b9900000(0000) knlGS:0000000000000000
> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 00005639543b1978 CR3: 0000000012463000 CR4: 00000000003506e0
> DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> Call Trace:
> <NMI>
> </NMI>
> <TASK>
> build_cr3 arch/x86/mm/tlb.c:159 [inline]
> switch_mm_irqs_off+0xc1/0xbb0 arch/x86/mm/tlb.c:529
> unuse_temporary_mm arch/x86/kernel/alternative.c:1516 [inline]
> __text_poke+0x3c5/0x890 arch/x86/kernel/alternative.c:1626
> text_poke arch/x86/kernel/alternative.c:1669 [inline]
> text_poke_bp_batch+0x3af/0x770 arch/x86/kernel/alternative.c:1992
> text_poke_flush arch/x86/kernel/alternative.c:2161 [inline]
> text_poke_flush arch/x86/kernel/alternative.c:2158 [inline]
> text_poke_finish+0x1a/0x30 arch/x86/kernel/alternative.c:2168
> arch_jump_label_transform_apply+0x17/0x30 arch/x86/kernel/jump_label.c:146
> jump_label_update+0x32f/0x410 kernel/jump_label.c:829
> static_key_disable_cpuslocked+0x156/0x1b0 kernel/jump_label.c:235
> static_key_disable+0x1a/0x20 kernel/jump_label.c:243
> toggle_allocation_gate mm/kfence/core.c:836 [inline]
> toggle_allocation_gate+0x143/0x230 mm/kfence/core.c:823
> process_one_work+0x99a/0x15e0 kernel/workqueue.c:2405
> worker_thread+0x67d/0x10c0 kernel/workqueue.c:2552
> kthread+0x344/0x440 kernel/kthread.c:379
> ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
> </TASK>
> INFO: NMI handler (nmi_cpu_backtrace_handler) took too long to run: 1.090 msecs
>
>
> ---
> If you want syzbot to run the reproducer, reply with:
> #syz test: git://repo/address.git branch-or-commit-hash
> If you attach or paste a git patch, syzbot will apply it before testing.
>
--
BR,
Muhammad Usama Anjum
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in hub_port_init (3)
2023-11-03 14:03 ` Muhammad Usama Anjum
@ 2023-11-03 15:04 ` Alan Stern
2023-11-08 11:25 ` Muhammad Usama Anjum
0 siblings, 1 reply; 9+ messages in thread
From: Alan Stern @ 2023-11-03 15:04 UTC (permalink / raw)
To: Muhammad Usama Anjum
Cc: syzbot, gregkh, linux-kernel, linux-usb, syzkaller-bugs
On Fri, Nov 03, 2023 at 07:03:20PM +0500, Muhammad Usama Anjum wrote:
> On 6/10/23 12:25 AM, syzbot wrote:
> > syzbot has found a reproducer for the following issue on:
> >
> > HEAD commit: 33f2b5785a2b Merge tag 'drm-fixes-2023-06-09' of git://ano..
> > git tree: upstream
> > console+strace: https://syzkaller.appspot.com/x/log.txt?x=1206f143280000
> > kernel config: https://syzkaller.appspot.com/x/.config?x=3c980bfe8b399968
> > dashboard link: https://syzkaller.appspot.com/bug?extid=b6f11035e572f08bc20f
> > 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=1676f51b280000
> > C reproducer: https://syzkaller.appspot.com/x/repro.c?x=129632fd280000
> >
> > Downloadable assets:
> > disk image: https://storage.googleapis.com/syzbot-assets/a817d99af39d/disk-33f2b578.raw.xz
> > vmlinux: https://storage.googleapis.com/syzbot-assets/8916e1d053fc/vmlinux-33f2b578.xz
> > kernel image: https://storage.googleapis.com/syzbot-assets/e53956f3cfd4/bzImage-33f2b578.xz
> >
> > IMPORTANT: if you fix the issue, please add the following tag to the commit:
> > Reported-by: syzbot+b6f11035e572f08bc20f@syzkaller.appspotmail.com
> >
> > INFO: task kworker/0:2:901 blocked for more than 143 seconds.
> > Not tainted 6.4.0-rc5-syzkaller-00178-g33f2b5785a2b #0
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > task:kworker/0:2 state:D stack:26800 pid:901 ppid:2 flags:0x00004000
> > Workqueue: usb_hub_wq hub_event
> > Call Trace:
> > <TASK>
> > context_switch kernel/sched/core.c:5343 [inline]
> > __schedule+0xc9a/0x5880 kernel/sched/core.c:6669
> > schedule+0xde/0x1a0 kernel/sched/core.c:6745
> > usb_kill_urb.part.0+0x19a/0x220 drivers/usb/core/urb.c:728
> > usb_kill_urb+0x83/0xa0 drivers/usb/core/urb.c:717
> > usb_start_wait_urb+0x24a/0x4b0 drivers/usb/core/message.c:64
> > usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
> > usb_control_msg+0x320/0x4a0 drivers/usb/core/message.c:153
> > hub_port_init+0x14f3/0x3900 drivers/usb/core/hub.c:4874
> > hub_port_connect drivers/usb/core/hub.c:5336 [inline]
> > hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
> > port_event drivers/usb/core/hub.c:5711 [inline]
> > hub_event+0x2b89/0x4e40 drivers/usb/core/hub.c:5793
> > process_one_work+0x99a/0x15e0 kernel/workqueue.c:2405
> > worker_thread+0x67d/0x10c0 kernel/workqueue.c:2552
> > kthread+0x344/0x440 kernel/kthread.c:379
> > ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
> > </TASK>
> > INFO: task syz-executor104:5004 blocked for more than 143 seconds.
> This is being reproduced on linux-next. The USB IP is being fuzzed. I'd
> modified the reproducer to try to understand the issue. The execution of
> application creates kworkers (can be found in hub->events). One of the usb
> hub kworker gets stuck because of wrong use_count. I don't know USB side of
> logic. But a worker shouldn't go to sleep indefinitely.
I doubt that the problem is a wrong value for use_count. More likely
it's a bug in the usbip driver.
> My debug logs are as following which can help an expert USB developer to
> pin point the problem:
>
> [ 118.904272][ T9] usb_submit_urb urb->use_count: 0
> [ 118.904942][ T9] usb_hcd_submit_urb urb->use_count: 1
> [ 118.905715][ T9] usb_submit_urb urb->use_count: 1
> [ 118.906428][ T9] usb_start_wait_urb urb->use_count: 1
> [ 123.938978][ T9] usb_kill_urb use_count: 1
These don't mean much because they don't give the address of urb, so
we don't know if the various lines all refer to the same URB or to
different ones.
> At this point, wait is being done on usb_kill_urb_queue as use_count isn't
> zero and no event on usb_kill_urb_queue is received.
Right. The usbip driver is supposed to terminate the URB in a timely
fashion (because usb_kill_urb() calls usb_hcd_unlink_urb()), but it
isn't doing so. When the URB completes, the event will occur.
> The comment for usb_kill_urb is:
> > * This routine may not be used in an interrupt context (such as a bottom
> > * half or a completion handler), or when holding a spinlock, or in other
> > * situations where the caller can't schedule().
>
> But several locks are held by this kworker and sleeps indefinitely.
No spinlocks are held, only mutexes. The difference is that a task is
allowed to sleep while holding a mutex, but it's not allowed to sleep
while holding a spinlock.
If you want to fix this problem (and probably a bunch of other ones in
syzbot's list of pending bugs), figure out what's wrong with the
->urb_dequeue() callback routine in the usbip driver and fix it.
Alan Stern
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in hub_port_init (3)
[not found] <20231104010547.1505-1-hdanton@sina.com>
@ 2023-11-04 1:23 ` syzbot
0 siblings, 0 replies; 9+ messages in thread
From: syzbot @ 2023-11-04 1:23 UTC (permalink / raw)
To: hdanton, linux-kernel, syzkaller-bugs
Hello,
syzbot has tested the proposed patch but the reproducer is still triggering an issue:
KASAN: slab-use-after-free Read in usb_hcd_flush_endpoint
vhci_hcd: vhci_device speed not set
usb 9-1: device descriptor read/64, error -110
==================================================================
BUG: KASAN: slab-use-after-free in usb_hcd_flush_endpoint+0x1ab/0x3e0 drivers/usb/core/hcd.c:1779
Read of size 4 at addr ffff888019ecd204 by task kworker/1:0/23
CPU: 1 PID: 23 Comm: kworker/1:0 Not tainted 6.6.0-syzkaller-12893-ge392ea4d4d00-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/09/2023
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
__dump_stack lib/dump_stack.c:88 [inline]
dump_stack_lvl+0x1e7/0x2d0 lib/dump_stack.c:106
print_address_description mm/kasan/report.c:364 [inline]
print_report+0x163/0x540 mm/kasan/report.c:475
kasan_report+0x142/0x170 mm/kasan/report.c:588
usb_hcd_flush_endpoint+0x1ab/0x3e0 drivers/usb/core/hcd.c:1779
usb_disable_endpoint+0x123/0x180 drivers/usb/core/message.c:1300
usb_ep0_reinit drivers/usb/core/hub.c:4636 [inline]
hub_port_connect drivers/usb/core/hub.c:5485 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5599 [inline]
port_event drivers/usb/core/hub.c:5759 [inline]
hub_event+0x2ee5/0x50a0 drivers/usb/core/hub.c:5841
process_one_work kernel/workqueue.c:2630 [inline]
process_scheduled_works+0x90f/0x1400 kernel/workqueue.c:2703
worker_thread+0xa5f/0xff0 kernel/workqueue.c:2784
kthread+0x2d3/0x370 kernel/kthread.c:388
ret_from_fork+0x48/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:242
</TASK>
Allocated by task 23:
kasan_save_stack mm/kasan/common.c:45 [inline]
kasan_set_track+0x4f/0x70 mm/kasan/common.c:52
____kasan_kmalloc mm/kasan/common.c:374 [inline]
__kasan_kmalloc+0x98/0xb0 mm/kasan/common.c:383
kasan_kmalloc include/linux/kasan.h:198 [inline]
__do_kmalloc_node mm/slab_common.c:1007 [inline]
__kmalloc+0xb9/0x230 mm/slab_common.c:1020
kmalloc include/linux/slab.h:604 [inline]
usb_alloc_urb+0x3a/0x130 drivers/usb/core/urb.c:75
usb_internal_control_msg drivers/usb/core/message.c:96 [inline]
usb_control_msg+0x189/0x4c0 drivers/usb/core/message.c:154
get_bMaxPacketSize0 drivers/usb/core/hub.c:4744 [inline]
hub_port_init+0xaa6/0x23a0 drivers/usb/core/hub.c:4940
hub_port_connect drivers/usb/core/hub.c:5388 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5599 [inline]
port_event drivers/usb/core/hub.c:5759 [inline]
hub_event+0x2a3c/0x50a0 drivers/usb/core/hub.c:5841
process_one_work kernel/workqueue.c:2630 [inline]
process_scheduled_works+0x90f/0x1400 kernel/workqueue.c:2703
worker_thread+0xa5f/0xff0 kernel/workqueue.c:2784
kthread+0x2d3/0x370 kernel/kthread.c:388
ret_from_fork+0x48/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:242
Freed by task 23:
kasan_save_stack mm/kasan/common.c:45 [inline]
kasan_set_track+0x4f/0x70 mm/kasan/common.c:52
kasan_save_free_info+0x28/0x40 mm/kasan/generic.c:522
____kasan_slab_free+0xd6/0x120 mm/kasan/common.c:236
kasan_slab_free include/linux/kasan.h:164 [inline]
slab_free_hook mm/slub.c:1800 [inline]
slab_free_freelist_hook mm/slub.c:1826 [inline]
slab_free mm/slub.c:3809 [inline]
__kmem_cache_free+0x263/0x3a0 mm/slub.c:3822
usb_start_wait_urb+0x24b/0x520 drivers/usb/core/message.c:81
usb_internal_control_msg drivers/usb/core/message.c:103 [inline]
usb_control_msg+0x2b1/0x4c0 drivers/usb/core/message.c:154
get_bMaxPacketSize0 drivers/usb/core/hub.c:4744 [inline]
hub_port_init+0xaa6/0x23a0 drivers/usb/core/hub.c:4940
hub_port_connect drivers/usb/core/hub.c:5388 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5599 [inline]
port_event drivers/usb/core/hub.c:5759 [inline]
hub_event+0x2a3c/0x50a0 drivers/usb/core/hub.c:5841
process_one_work kernel/workqueue.c:2630 [inline]
process_scheduled_works+0x90f/0x1400 kernel/workqueue.c:2703
worker_thread+0xa5f/0xff0 kernel/workqueue.c:2784
kthread+0x2d3/0x370 kernel/kthread.c:388
ret_from_fork+0x48/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:242
Last potentially related work creation:
kasan_save_stack+0x3f/0x60 mm/kasan/common.c:45
__kasan_record_aux_stack+0xad/0xc0 mm/kasan/generic.c:492
__call_rcu_common kernel/rcu/tree.c:2667 [inline]
call_rcu+0x167/0xa70 kernel/rcu/tree.c:2781
addrconf_ifdown+0x18f1/0x1bb0 net/ipv6/addrconf.c:3958
addrconf_notify+0x3ce/0x1020
notifier_call_chain+0x18c/0x3a0 kernel/notifier.c:93
call_netdevice_notifiers_extack net/core/dev.c:2003 [inline]
call_netdevice_notifiers net/core/dev.c:2017 [inline]
unregister_netdevice_many_notify+0xd87/0x1710 net/core/dev.c:10983
ip6_tnl_exit_batch_net+0x5c8/0x610 net/ipv6/ip6_tunnel.c:2278
ops_exit_list net/core/net_namespace.c:175 [inline]
cleanup_net+0x767/0xb80 net/core/net_namespace.c:614
process_one_work kernel/workqueue.c:2630 [inline]
process_scheduled_works+0x90f/0x1400 kernel/workqueue.c:2703
worker_thread+0xa5f/0xff0 kernel/workqueue.c:2784
kthread+0x2d3/0x370 kernel/kthread.c:388
ret_from_fork+0x48/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:242
Second to last potentially related work creation:
kasan_save_stack+0x3f/0x60 mm/kasan/common.c:45
__kasan_record_aux_stack+0xad/0xc0 mm/kasan/generic.c:492
insert_work+0x3e/0x320 kernel/workqueue.c:1647
__queue_work+0xc06/0x1010 kernel/workqueue.c:1799
queue_work_on+0x14f/0x250 kernel/workqueue.c:1834
queue_work include/linux/workqueue.h:562 [inline]
call_usermodehelper_exec+0x276/0x480 kernel/umh.c:434
kobject_uevent_env+0x6a9/0x8e0 lib/kobject_uevent.c:618
kset_register+0x1ab/0x200 lib/kobject.c:873
class_register+0x1c3/0x2a0 drivers/base/class.c:205
cpuid_init+0x49/0x100 arch/x86/kernel/cpuid.c:161
do_one_initcall+0x234/0x800 init/main.c:1236
do_initcall_level+0x157/0x210 init/main.c:1298
do_initcalls+0x3f/0x80 init/main.c:1314
kernel_init_freeable+0x429/0x5c0 init/main.c:1551
kernel_init+0x1d/0x2a0 init/main.c:1441
ret_from_fork+0x48/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:242
The buggy address belongs to the object at ffff888019ecd200
which belongs to the cache kmalloc-192 of size 192
The buggy address is located 4 bytes inside of
freed 192-byte region [ffff888019ecd200, ffff888019ecd2c0)
The buggy address belongs to the physical page:
page:ffffea000067b340 refcount:1 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x19ecd
ksm flags: 0xfff00000000800(slab|node=0|zone=1|lastcpupid=0x7ff)
page_type: 0xffffffff()
raw: 00fff00000000800 ffff888012c41a00 ffffea00007faa00 dead000000000003
raw: 0000000000000000 0000000000100010 00000001ffffffff 0000000000000000
page dumped because: kasan: bad access detected
page_owner tracks the page as allocated
page last allocated via order 0, migratetype Unmovable, gfp_mask 0x12cc0(GFP_KERNEL|__GFP_NOWARN|__GFP_NORETRY), pid 1, tgid 1 (swapper/0), ts 3961051695, free_ts 3958343321
set_page_owner include/linux/page_owner.h:31 [inline]
post_alloc_hook+0x1e6/0x210 mm/page_alloc.c:1537
prep_new_page mm/page_alloc.c:1544 [inline]
get_page_from_freelist+0x339a/0x3530 mm/page_alloc.c:3312
__alloc_pages+0x255/0x670 mm/page_alloc.c:4568
alloc_pages_mpol+0x3de/0x640 mm/mempolicy.c:2133
alloc_slab_page+0x6a/0x160 mm/slub.c:1870
allocate_slab mm/slub.c:2017 [inline]
new_slab+0x84/0x2f0 mm/slub.c:2070
___slab_alloc+0xc85/0x1310 mm/slub.c:3223
__slab_alloc mm/slub.c:3322 [inline]
__slab_alloc_node mm/slub.c:3375 [inline]
slab_alloc_node mm/slub.c:3468 [inline]
__kmem_cache_alloc_node+0x21d/0x300 mm/slub.c:3517
kmalloc_trace+0x2a/0xe0 mm/slab_common.c:1098
kmalloc include/linux/slab.h:600 [inline]
kzalloc include/linux/slab.h:721 [inline]
call_usermodehelper_setup+0x8e/0x260 kernel/umh.c:363
kobject_uevent_env+0x68c/0x8e0 lib/kobject_uevent.c:614
kset_register+0x1ab/0x200 lib/kobject.c:873
class_register+0x1c3/0x2a0 drivers/base/class.c:205
msr_init+0x49/0x100 arch/x86/kernel/msr.c:270
do_one_initcall+0x234/0x800 init/main.c:1236
do_initcall_level+0x157/0x210 init/main.c:1298
page last free stack trace:
reset_page_owner include/linux/page_owner.h:24 [inline]
free_pages_prepare mm/page_alloc.c:1137 [inline]
free_unref_page_prepare+0x92a/0xa50 mm/page_alloc.c:2347
free_unref_page+0x37/0x3f0 mm/page_alloc.c:2487
mm_free_pgd kernel/fork.c:803 [inline]
__mmdrop+0xb8/0x3d0 kernel/fork.c:919
free_bprm+0x144/0x330 fs/exec.c:1490
kernel_execve+0x8f5/0xa10 fs/exec.c:2024
call_usermodehelper_exec_async+0x233/0x370 kernel/umh.c:110
ret_from_fork+0x48/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:242
Memory state around the buggy address:
ffff888019ecd100: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
ffff888019ecd180: 00 00 fc fc fc fc fc fc fc fc fc fc fc fc fc fc
>ffff888019ecd200: fa fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
^
ffff888019ecd280: fb fb fb fb fb fb fb fb fc fc fc fc fc fc fc fc
ffff888019ecd300: fa fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
==================================================================
Tested on:
commit: e392ea4d Merge tag 's390-6.7-1' of git://git.kernel.or..
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
console output: https://syzkaller.appspot.com/x/log.txt?x=15c491ef680000
kernel config: https://syzkaller.appspot.com/x/.config?x=94632a8e2ffd08bb
dashboard link: https://syzkaller.appspot.com/bug?extid=b6f11035e572f08bc20f
compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
patch: https://syzkaller.appspot.com/x/patch.diff?x=17af6aeb680000
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in hub_port_init (3)
[not found] <20231104074445.1237-1-hdanton@sina.com>
@ 2023-11-04 8:07 ` syzbot
0 siblings, 0 replies; 9+ messages in thread
From: syzbot @ 2023-11-04 8:07 UTC (permalink / raw)
To: hdanton, linux-kernel, syzkaller-bugs
Hello,
syzbot has tested the proposed patch but the reproducer is still triggering an issue:
kernel panic: KASAN: panic_on_warn set ...
>ffff888020985500: fa fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
^
ffff888020985580: fb fb fb fb fb fb fb fb fc fc fc fc fc fc fc fc
ffff888020985600: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
==================================================================
Kernel panic - not syncing: KASAN: panic_on_warn set ...
CPU: 0 PID: 2911 Comm: kworker/u4:13 Not tainted 6.6.0-syzkaller-14142-g90b0c2b2edd1-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 10/09/2023
Workqueue: usbip_event event_handler
Call Trace:
<TASK>
__dump_stack lib/dump_stack.c:88 [inline]
dump_stack_lvl+0x1e7/0x2d0 lib/dump_stack.c:106
panic+0x349/0x850 kernel/panic.c:344
check_panic_on_warn+0x82/0xa0 kernel/panic.c:237
end_report+0x6e/0x130 mm/kasan/report.c:225
kasan_report+0x153/0x170 mm/kasan/report.c:590
pickup_urb_and_free_priv+0x282/0x370 drivers/usb/usbip/vhci_rx.c:24
vhci_cleanup_unlink_list+0x12d/0x490 drivers/usb/usbip/vhci_hcd.c:966
vhci_device_unlink_cleanup drivers/usb/usbip/vhci_hcd.c:1000 [inline]
vhci_shutdown_connection+0x203/0x4a0 drivers/usb/usbip/vhci_hcd.c:1037
event_handler+0x24e/0x4b0 drivers/usb/usbip/usbip_event.c:79
process_one_work kernel/workqueue.c:2630 [inline]
process_scheduled_works+0x90f/0x1400 kernel/workqueue.c:2703
worker_thread+0xa5f/0xff0 kernel/workqueue.c:2784
kthread+0x2d3/0x370 kernel/kthread.c:388
ret_from_fork+0x48/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x11/0x20 arch/x86/entry/entry_64.S:242
</TASK>
Kernel Offset: disabled
Rebooting in 86400 seconds..
Tested on:
commit: 90b0c2b2 Merge tag 'pinctrl-v6.7-1' of git://git.kerne..
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
console output: https://syzkaller.appspot.com/x/log.txt?x=11d567f3680000
kernel config: https://syzkaller.appspot.com/x/.config?x=93ac5233c138249e
dashboard link: https://syzkaller.appspot.com/bug?extid=b6f11035e572f08bc20f
compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
patch: https://syzkaller.appspot.com/x/patch.diff?x=15c49eeb680000
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in hub_port_init (3)
[not found] <20231104112657.1312-1-hdanton@sina.com>
@ 2023-11-04 12:50 ` syzbot
0 siblings, 0 replies; 9+ messages in thread
From: syzbot @ 2023-11-04 12:50 UTC (permalink / raw)
To: hdanton, linux-kernel, syzkaller-bugs
Hello,
syzbot has tested the proposed patch and the reproducer did not trigger any issue:
Reported-and-tested-by: syzbot+b6f11035e572f08bc20f@syzkaller.appspotmail.com
Tested on:
commit: 90b0c2b2 Merge tag 'pinctrl-v6.7-1' of git://git.kerne..
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
console output: https://syzkaller.appspot.com/x/log.txt?x=10124527680000
kernel config: https://syzkaller.appspot.com/x/.config?x=93ac5233c138249e
dashboard link: https://syzkaller.appspot.com/bug?extid=b6f11035e572f08bc20f
compiler: Debian clang version 15.0.6, GNU ld (GNU Binutils for Debian) 2.40
patch: https://syzkaller.appspot.com/x/patch.diff?x=12d6f190e80000
Note: testing is done by a robot and is best-effort only.
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in hub_port_init (3)
2023-11-03 15:04 ` Alan Stern
@ 2023-11-08 11:25 ` Muhammad Usama Anjum
2023-11-08 16:12 ` Alan Stern
0 siblings, 1 reply; 9+ messages in thread
From: Muhammad Usama Anjum @ 2023-11-08 11:25 UTC (permalink / raw)
To: Alan Stern
Cc: Muhammad Usama Anjum, syzbot, gregkh, linux-kernel, linux-usb,
syzkaller-bugs
On 11/3/23 8:04 PM, Alan Stern wrote:
> On Fri, Nov 03, 2023 at 07:03:20PM +0500, Muhammad Usama Anjum wrote:
>> On 6/10/23 12:25 AM, syzbot wrote:
>>> syzbot has found a reproducer for the following issue on:
>>>
>>> HEAD commit: 33f2b5785a2b Merge tag 'drm-fixes-2023-06-09' of git://ano..
>>> git tree: upstream
>>> console+strace: https://syzkaller.appspot.com/x/log.txt?x=1206f143280000
>>> kernel config: https://syzkaller.appspot.com/x/.config?x=3c980bfe8b399968
>>> dashboard link: https://syzkaller.appspot.com/bug?extid=b6f11035e572f08bc20f
>>> 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=1676f51b280000
>>> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=129632fd280000
>>>
>>> Downloadable assets:
>>> disk image: https://storage.googleapis.com/syzbot-assets/a817d99af39d/disk-33f2b578.raw.xz
>>> vmlinux: https://storage.googleapis.com/syzbot-assets/8916e1d053fc/vmlinux-33f2b578.xz
>>> kernel image: https://storage.googleapis.com/syzbot-assets/e53956f3cfd4/bzImage-33f2b578.xz
>>>
>>> IMPORTANT: if you fix the issue, please add the following tag to the commit:
>>> Reported-by: syzbot+b6f11035e572f08bc20f@syzkaller.appspotmail.com
>>>
>>> INFO: task kworker/0:2:901 blocked for more than 143 seconds.
>>> Not tainted 6.4.0-rc5-syzkaller-00178-g33f2b5785a2b #0
>>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>>> task:kworker/0:2 state:D stack:26800 pid:901 ppid:2 flags:0x00004000
>>> Workqueue: usb_hub_wq hub_event
>>> Call Trace:
>>> <TASK>
>>> context_switch kernel/sched/core.c:5343 [inline]
>>> __schedule+0xc9a/0x5880 kernel/sched/core.c:6669
>>> schedule+0xde/0x1a0 kernel/sched/core.c:6745
>>> usb_kill_urb.part.0+0x19a/0x220 drivers/usb/core/urb.c:728
>>> usb_kill_urb+0x83/0xa0 drivers/usb/core/urb.c:717
>>> usb_start_wait_urb+0x24a/0x4b0 drivers/usb/core/message.c:64
>>> usb_internal_control_msg drivers/usb/core/message.c:102 [inline]
>>> usb_control_msg+0x320/0x4a0 drivers/usb/core/message.c:153
>>> hub_port_init+0x14f3/0x3900 drivers/usb/core/hub.c:4874
>>> hub_port_connect drivers/usb/core/hub.c:5336 [inline]
>>> hub_port_connect_change drivers/usb/core/hub.c:5551 [inline]
>>> port_event drivers/usb/core/hub.c:5711 [inline]
>>> hub_event+0x2b89/0x4e40 drivers/usb/core/hub.c:5793
>>> process_one_work+0x99a/0x15e0 kernel/workqueue.c:2405
>>> worker_thread+0x67d/0x10c0 kernel/workqueue.c:2552
>>> kthread+0x344/0x440 kernel/kthread.c:379
>>> ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308
>>> </TASK>
>>> INFO: task syz-executor104:5004 blocked for more than 143 seconds.
>> This is being reproduced on linux-next. The USB IP is being fuzzed. I'd
>> modified the reproducer to try to understand the issue. The execution of
>> application creates kworkers (can be found in hub->events). One of the usb
>> hub kworker gets stuck because of wrong use_count. I don't know USB side of
>> logic. But a worker shouldn't go to sleep indefinitely.
>
> I doubt that the problem is a wrong value for use_count. More likely
> it's a bug in the usbip driver.
>
>> My debug logs are as following which can help an expert USB developer to
>> pin point the problem:
>>
>> [ 118.904272][ T9] usb_submit_urb urb->use_count: 0
>> [ 118.904942][ T9] usb_hcd_submit_urb urb->use_count: 1
>> [ 118.905715][ T9] usb_submit_urb urb->use_count: 1
>> [ 118.906428][ T9] usb_start_wait_urb urb->use_count: 1
>> [ 123.938978][ T9] usb_kill_urb use_count: 1
>
> These don't mean much because they don't give the address of urb, so
> we don't know if the various lines all refer to the same URB or to
> different ones.
I've confirmed locally again that the logs belong to same urb. This kworker
gets stuck:
[ 131.064283] usb_control_msg
[ 131.065326] usb_internal_control_msg, urb: FFFF88814CC2AE00
urb->use_count: 0
[ 131.066320] usb_start_wait_urb urb: FFFF88814CC2AE00 urb->use_count: 0
[ 131.069988] usb_submit_urb urb: FFFF88814CC2AE00 urb->use_count: 0
[ 131.070881] usb_hcd_submit_urb urb: FFFF88814CC2AE00 urb->use_count 1
[ 131.072268] usb_submit_urb 0 urb: FFFF88814CC2AE00 urb->use_count: 1
[ 131.073186] usb_start_wait_urb urb: FFFF88814CC2AE00 urb->use_count: 1
[ 136.151750] usb_start_wait_urb wait_for_completion
[ 136.153286] usb_kill_urb might_sleep
[ 136.153859] vhci_hcd: vhci_urb_dequeue:875: vhci_urb_dequeue
[ 136.154853] vhci_hcd: vhci_urb_dequeue:952: vhci_urb_dequeue return
[ 136.155773] usb_kill_urb usb_hcd_unlink_urb use_count: 1
[ 285.831355] INFO: task kworker/0:4:1586 blocked for more than 143 seconds.
>
>> At this point, wait is being done on usb_kill_urb_queue as use_count isn't
>> zero and no event on usb_kill_urb_queue is received.
>
> Right. The usbip driver is supposed to terminate the URB in a timely
> fashion (because usb_kill_urb() calls usb_hcd_unlink_urb()), but it
> isn't doing so. When the URB completes, the event will occur.
>
>> The comment for usb_kill_urb is:
>>> * This routine may not be used in an interrupt context (such as a bottom
>>> * half or a completion handler), or when holding a spinlock, or in other
>>> * situations where the caller can't schedule().
>>
>> But several locks are held by this kworker and sleeps indefinitely.
>
> No spinlocks are held, only mutexes. The difference is that a task is
> allowed to sleep while holding a mutex, but it's not allowed to sleep
> while holding a spinlock.
>
> If you want to fix this problem (and probably a bunch of other ones in
> syzbot's list of pending bugs), figure out what's wrong with the
> ->urb_dequeue() callback routine in the usbip driver and fix it.
I'm looking at it, haven't found anything yet.
>
> Alan Stern
--
BR,
Muhammad Usama Anjum
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in hub_port_init (3)
2023-11-08 11:25 ` Muhammad Usama Anjum
@ 2023-11-08 16:12 ` Alan Stern
0 siblings, 0 replies; 9+ messages in thread
From: Alan Stern @ 2023-11-08 16:12 UTC (permalink / raw)
To: Muhammad Usama Anjum
Cc: syzbot, gregkh, linux-kernel, linux-usb, syzkaller-bugs
On Wed, Nov 08, 2023 at 04:25:45PM +0500, Muhammad Usama Anjum wrote:
> I've confirmed locally again that the logs belong to same urb. This kworker
> gets stuck:
>
> [ 131.064283] usb_control_msg
> [ 131.065326] usb_internal_control_msg, urb: FFFF88814CC2AE00
> urb->use_count: 0
> [ 131.066320] usb_start_wait_urb urb: FFFF88814CC2AE00 urb->use_count: 0
> [ 131.069988] usb_submit_urb urb: FFFF88814CC2AE00 urb->use_count: 0
> [ 131.070881] usb_hcd_submit_urb urb: FFFF88814CC2AE00 urb->use_count 1
> [ 131.072268] usb_submit_urb 0 urb: FFFF88814CC2AE00 urb->use_count: 1
> [ 131.073186] usb_start_wait_urb urb: FFFF88814CC2AE00 urb->use_count: 1
> [ 136.151750] usb_start_wait_urb wait_for_completion
> [ 136.153286] usb_kill_urb might_sleep
> [ 136.153859] vhci_hcd: vhci_urb_dequeue:875: vhci_urb_dequeue
> [ 136.154853] vhci_hcd: vhci_urb_dequeue:952: vhci_urb_dequeue return
> [ 136.155773] usb_kill_urb usb_hcd_unlink_urb use_count: 1
> [ 285.831355] INFO: task kworker/0:4:1586 blocked for more than 143 seconds.
Of course. It's waiting for the vhci_urb_dequeue() call to finish
unlinking the URB.
> > If you want to fix this problem (and probably a bunch of other ones in
> > syzbot's list of pending bugs), figure out what's wrong with the
> > ->urb_dequeue() callback routine in the usbip driver and fix it.
> I'm looking at it, haven't found anything yet.
I took a very quick look just now, and one thing stands out. If
vhci_urb_dequeue() is unable to allocate a vhci_unlink structure, it
calls usbip_event_add() and then returns without doing anything else.
But one of the things usbip_event_add() does is try to allocate a
usbip_event structure, and if that allocation fails then it returns
without doing anything. Now, if the memory allocation attempt in
vhci_urb_dequeue() fails then it seems quite likely that the attempt in
usbip_event_add() will also fail. Which means that nothing will happen
-- and that is a bug. URB-dequeue calls are not allowed to fail because
of memory pressure.
Now, I don't know if this is the cause of the trouble in the syzbot
test. You should trace what's going on in vhci_urb_dequeue() to see
exactly what it does.
Alan Stern
^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2023-11-08 16:12 UTC | newest]
Thread overview: 9+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2023-03-28 12:23 [syzbot] [usb?] INFO: task hung in hub_port_init (3) syzbot
2023-06-09 19:25 ` syzbot
2023-11-03 14:03 ` Muhammad Usama Anjum
2023-11-03 15:04 ` Alan Stern
2023-11-08 11:25 ` Muhammad Usama Anjum
2023-11-08 16:12 ` Alan Stern
[not found] <20231104010547.1505-1-hdanton@sina.com>
2023-11-04 1:23 ` syzbot
[not found] <20231104074445.1237-1-hdanton@sina.com>
2023-11-04 8:07 ` syzbot
[not found] <20231104112657.1312-1-hdanton@sina.com>
2023-11-04 12:50 ` syzbot
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).