* Re: [syzbot] [usb?] INFO: task hung in usb_port_suspend
[not found] ` <670d65fa.050a0220.3e960.00c1.GAE@google.com>
@ 2024-10-15 14:22 ` Alan Stern
2024-10-15 14:54 ` syzbot
0 siblings, 1 reply; 12+ messages in thread
From: Alan Stern @ 2024-10-15 14:22 UTC (permalink / raw)
To: syzbot; +Cc: USB mailing list, linux-kernel, syzkaller-bugs
On Mon, Oct 14, 2024 at 11:42:02AM -0700, syzbot wrote:
> Hello,
>
> syzbot has tested the proposed patch but the reproducer is still triggering an issue:
Let's try to get some more debugging info.
Alan Stern
#syz test: https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git v6.12-rc3
Index: usb-devel/drivers/usb/gadget/udc/dummy_hcd.c
===================================================================
--- usb-devel.orig/drivers/usb/gadget/udc/dummy_hcd.c
+++ usb-devel/drivers/usb/gadget/udc/dummy_hcd.c
@@ -50,7 +50,7 @@
#define POWER_BUDGET 500 /* in mA; use 8 for low-power port testing */
#define POWER_BUDGET_3 900 /* in mA */
-#define DUMMY_TIMER_INT_NSECS 125000 /* 1 microframe */
+#define DUMMY_INT_KTIME ns_to_ktime(125000) /* 1 microframe */
static const char driver_name[] = "dummy_hcd";
static const char driver_desc[] = "USB Host+Gadget Emulator";
@@ -257,6 +257,9 @@ struct dummy_hcd {
unsigned active:1;
unsigned old_active:1;
unsigned resuming:1;
+
+ int alanflag;
+ const char *alanstr;
};
struct dummy {
@@ -323,6 +326,14 @@ static inline struct dummy *gadget_dev_t
return container_of(dev, struct dummy, gadget.dev);
}
+void alandbg(struct dummy_hcd *dum_hcd, const char *str);
+void alandbg(struct dummy_hcd *dum_hcd, const char *str)
+{
+ dum_hcd->alanstr = str;
+ if (dum_hcd->alanflag)
+ dev_info(dummy_dev(dum_hcd), str);
+}
+
/*-------------------------------------------------------------------------*/
/* DEVICE/GADGET SIDE UTILITY ROUTINES */
@@ -1303,9 +1314,11 @@ static int dummy_urb_enqueue(
urb->error_count = 1; /* mark as a new urb */
/* kick the scheduler, it'll do the rest */
- if (!hrtimer_active(&dum_hcd->timer))
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(DUMMY_TIMER_INT_NSECS),
+ if (!hrtimer_active(&dum_hcd->timer)) {
+ alandbg(dum_hcd, "start1");
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
HRTIMER_MODE_REL_SOFT);
+ }
done:
spin_unlock_irqrestore(&dum_hcd->dum->lock, flags);
@@ -1325,9 +1338,19 @@ static int dummy_urb_dequeue(struct usb_
rc = usb_hcd_check_unlink_urb(hcd, urb, status);
if (!rc && dum_hcd->rh_state != DUMMY_RH_RUNNING &&
- !list_empty(&dum_hcd->urbp_list))
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(0), HRTIMER_MODE_REL_SOFT);
-
+ !list_empty(&dum_hcd->urbp_list)) {
+ dev_info(dummy_dev(dum_hcd), "Dequeue restart %p\n", urb);
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
+ HRTIMER_MODE_REL_SOFT);
+ alandbg(dum_hcd, "start2");
+ } else {
+ dev_info(dummy_dev(dum_hcd), "Dequeue norestart: %d %d %d %p active %d %s\n",
+ rc, dum_hcd->rh_state,
+ list_empty(&dum_hcd->urbp_list), urb,
+ hrtimer_active(&dum_hcd->timer),
+ dum_hcd->alanstr);
+ }
+ ++dum_hcd->alanflag;
spin_unlock_irqrestore(&dum_hcd->dum->lock, flags);
return rc;
}
@@ -1813,10 +1836,12 @@ static enum hrtimer_restart dummy_timer(
/* look at each urb queued by the host side driver */
spin_lock_irqsave(&dum->lock, flags);
+ alandbg(dum_hcd, "handler1");
if (!dum_hcd->udev) {
dev_err(dummy_dev(dum_hcd),
"timer fired with no URBs pending?\n");
+ alandbg(dum_hcd, "handler2");
spin_unlock_irqrestore(&dum->lock, flags);
return HRTIMER_NORESTART;
}
@@ -1984,6 +2009,8 @@ return_urb:
ep->already_seen = ep->setup_stage = 0;
usb_hcd_unlink_urb_from_ep(dummy_hcd_to_hcd(dum_hcd), urb);
+ if (dum_hcd->alanflag)
+ dev_info(dummy_dev(dum_hcd), "Giveback %p\n", urb);
spin_unlock(&dum->lock);
usb_hcd_giveback_urb(dummy_hcd_to_hcd(dum_hcd), urb, status);
spin_lock(&dum->lock);
@@ -1994,12 +2021,17 @@ return_urb:
if (list_empty(&dum_hcd->urbp_list)) {
usb_put_dev(dum_hcd->udev);
dum_hcd->udev = NULL;
+ alandbg(dum_hcd, "handler3");
} else if (dum_hcd->rh_state == DUMMY_RH_RUNNING) {
- /* want a 1 msec delay here */
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(DUMMY_TIMER_INT_NSECS),
+ alandbg(dum_hcd, "handler-start");
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
HRTIMER_MODE_REL_SOFT);
+ } else {
+ alandbg(dum_hcd, "handler4");
}
+ if (dum_hcd->alanflag > 0)
+ --dum_hcd->alanflag;
spin_unlock_irqrestore(&dum->lock, flags);
return HRTIMER_NORESTART;
@@ -2390,8 +2422,11 @@ static int dummy_bus_resume(struct usb_h
} else {
dum_hcd->rh_state = DUMMY_RH_RUNNING;
set_link_state(dum_hcd);
- if (!list_empty(&dum_hcd->urbp_list))
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(0), HRTIMER_MODE_REL_SOFT);
+ if (!list_empty(&dum_hcd->urbp_list)) {
+ alandbg(dum_hcd, "start3");
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
+ HRTIMER_MODE_REL_SOFT);
+ }
hcd->state = HC_STATE_RUNNING;
}
spin_unlock_irq(&dum_hcd->dum->lock);
@@ -2490,6 +2525,7 @@ static int dummy_start(struct usb_hcd *h
{
struct dummy_hcd *dum_hcd = hcd_to_dummy_hcd(hcd);
+ dum_hcd->alanstr = "init";
/*
* HOST side init ... we emulate a root hub that'll only ever
* talk to one device (the gadget side). Also appears in sysfs,
@@ -2521,6 +2557,7 @@ static void dummy_stop(struct usb_hcd *h
{
struct dummy_hcd *dum_hcd = hcd_to_dummy_hcd(hcd);
+ alandbg(dum_hcd, "cancel");
hrtimer_cancel(&dum_hcd->timer);
device_remove_file(dummy_dev(dum_hcd), &dev_attr_urbs);
dev_info(dummy_dev(dum_hcd), "stopped\n");
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in usb_port_suspend
2024-10-15 14:22 ` [syzbot] [usb?] INFO: task hung in usb_port_suspend Alan Stern
@ 2024-10-15 14:54 ` syzbot
2024-10-15 19:23 ` Alan Stern
0 siblings, 1 reply; 12+ messages in thread
From: syzbot @ 2024-10-15 14:54 UTC (permalink / raw)
To: linux-kernel, linux-usb, stern, syzkaller-bugs
Hello,
syzbot has tested the proposed patch but the reproducer is still triggering an issue:
INFO: task hung in usb_port_suspend
INFO: task kworker/0:2:803 blocked for more than 143 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/0:2 state:D stack:23808 pid:803 tgid:803 ppid:2 flags:0x00004000
Workqueue: pm pm_runtime_work
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
usb_kill_urb.part.0+0x1ca/0x250 drivers/usb/core/urb.c:713
usb_kill_urb+0x83/0xa0 drivers/usb/core/urb.c:702
usb_start_wait_urb+0x255/0x4c0 drivers/usb/core/message.c:65
usb_internal_control_msg drivers/usb/core/message.c:103 [inline]
usb_control_msg+0x327/0x4b0 drivers/usb/core/message.c:154
usb_enable_remote_wakeup drivers/usb/core/hub.c:3365 [inline]
usb_port_suspend+0x339/0xf10 drivers/usb/core/hub.c:3472
usb_generic_driver_suspend+0xeb/0x1d0 drivers/usb/core/generic.c:302
usb_suspend_device drivers/usb/core/driver.c:1272 [inline]
usb_suspend_both+0x66d/0x9c0 drivers/usb/core/driver.c:1443
usb_runtime_suspend+0x49/0x180 drivers/usb/core/driver.c:1968
__rpm_callback+0xc5/0x4c0 drivers/base/power/runtime.c:394
rpm_callback+0x192/0x1d0 drivers/base/power/runtime.c:448
rpm_suspend+0x2e7/0x1200 drivers/base/power/runtime.c:672
__pm_runtime_suspend+0xbc/0x160 drivers/base/power/runtime.c:1142
pm_runtime_autosuspend include/linux/pm_runtime.h:342 [inline]
usb_runtime_idle+0x4c/0x60 drivers/usb/core/driver.c:2005
rpm_idle+0x2f7/0x740 drivers/base/power/runtime.c:524
pm_runtime_work+0x120/0x150 drivers/base/power/runtime.c:970
process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3229
process_scheduled_works kernel/workqueue.c:3310 [inline]
worker_thread+0x6c8/0xf00 kernel/workqueue.c:3391
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
INFO: task kworker/1:2:2737 blocked for more than 143 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:2 state:D stack:24544 pid:2737 tgid:2737 ppid:2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
rwsem_down_write_slowpath+0x539/0x12a0 kernel/locking/rwsem.c:1176
__down_write_common kernel/locking/rwsem.c:1304 [inline]
__down_write kernel/locking/rwsem.c:1313 [inline]
down_write+0x1d8/0x200 kernel/locking/rwsem.c:1578
usb_deregister_dev+0x7c/0x1e0 drivers/usb/core/file.c:186
wdm_disconnect+0x25/0x440 drivers/usb/class/cdc-wdm.c:1214
usb_unbind_interface+0x1e8/0x970 drivers/usb/core/driver.c:461
device_remove drivers/base/dd.c:569 [inline]
device_remove+0x122/0x170 drivers/base/dd.c:561
__device_release_driver drivers/base/dd.c:1273 [inline]
device_release_driver_internal+0x44a/0x610 drivers/base/dd.c:1296
bus_remove_device+0x22f/0x420 drivers/base/bus.c:576
device_del+0x396/0x9f0 drivers/base/core.c:3864
usb_disable_device+0x36c/0x7f0 drivers/usb/core/message.c:1418
usb_disconnect+0x2e1/0x920 drivers/usb/core/hub.c:2304
hub_port_connect drivers/usb/core/hub.c:5361 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5661 [inline]
port_event drivers/usb/core/hub.c:5821 [inline]
hub_event+0x1bed/0x4f40 drivers/usb/core/hub.c:5903
process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3229
process_scheduled_works kernel/workqueue.c:3310 [inline]
worker_thread+0x6c8/0xf00 kernel/workqueue.c:3391
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
INFO: task kworker/1:3:6528 blocked for more than 144 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:3 state:D stack:24080 pid:6528 tgid:6528 ppid:2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
rwsem_down_write_slowpath+0x539/0x12a0 kernel/locking/rwsem.c:1176
__down_write_common kernel/locking/rwsem.c:1304 [inline]
__down_write kernel/locking/rwsem.c:1313 [inline]
down_write+0x1d8/0x200 kernel/locking/rwsem.c:1578
usb_deregister_dev+0x7c/0x1e0 drivers/usb/core/file.c:186
wdm_disconnect+0x25/0x440 drivers/usb/class/cdc-wdm.c:1214
usb_unbind_interface+0x1e8/0x970 drivers/usb/core/driver.c:461
device_remove drivers/base/dd.c:569 [inline]
device_remove+0x122/0x170 drivers/base/dd.c:561
__device_release_driver drivers/base/dd.c:1273 [inline]
device_release_driver_internal+0x44a/0x610 drivers/base/dd.c:1296
bus_remove_device+0x22f/0x420 drivers/base/bus.c:576
device_del+0x396/0x9f0 drivers/base/core.c:3864
usb_disable_device+0x36c/0x7f0 drivers/usb/core/message.c:1418
usb_disconnect+0x2e1/0x920 drivers/usb/core/hub.c:2304
hub_port_connect drivers/usb/core/hub.c:5361 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5661 [inline]
port_event drivers/usb/core/hub.c:5821 [inline]
hub_event+0x1bed/0x4f40 drivers/usb/core/hub.c:5903
process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3229
process_scheduled_works kernel/workqueue.c:3310 [inline]
worker_thread+0x6c8/0xf00 kernel/workqueue.c:3391
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
INFO: task kworker/1:4:6532 blocked for more than 144 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:4 state:D stack:24272 pid:6532 tgid:6532 ppid:2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
rwsem_down_write_slowpath+0x539/0x12a0 kernel/locking/rwsem.c:1176
__down_write_common kernel/locking/rwsem.c:1304 [inline]
__down_write kernel/locking/rwsem.c:1313 [inline]
down_write+0x1d8/0x200 kernel/locking/rwsem.c:1578
usb_deregister_dev+0x7c/0x1e0 drivers/usb/core/file.c:186
wdm_disconnect+0x25/0x440 drivers/usb/class/cdc-wdm.c:1214
usb_unbind_interface+0x1e8/0x970 drivers/usb/core/driver.c:461
device_remove drivers/base/dd.c:569 [inline]
device_remove+0x122/0x170 drivers/base/dd.c:561
__device_release_driver drivers/base/dd.c:1273 [inline]
device_release_driver_internal+0x44a/0x610 drivers/base/dd.c:1296
bus_remove_device+0x22f/0x420 drivers/base/bus.c:576
device_del+0x396/0x9f0 drivers/base/core.c:3864
usb_disable_device+0x36c/0x7f0 drivers/usb/core/message.c:1418
usb_disconnect+0x2e1/0x920 drivers/usb/core/hub.c:2304
hub_port_connect drivers/usb/core/hub.c:5361 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5661 [inline]
port_event drivers/usb/core/hub.c:5821 [inline]
hub_event+0x1bed/0x4f40 drivers/usb/core/hub.c:5903
process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3229
process_scheduled_works kernel/workqueue.c:3310 [inline]
worker_thread+0x6c8/0xf00 kernel/workqueue.c:3391
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
INFO: task syz.0.41:6582 blocked for more than 144 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz.0.41 state:D stack:27488 pid:6582 tgid:6581 ppid:4249 flags:0x00004004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
__mutex_lock_common kernel/locking/mutex.c:684 [inline]
__mutex_lock+0x5b8/0x9c0 kernel/locking/mutex.c:752
wdm_open+0x5d/0x630 drivers/usb/class/cdc-wdm.c:715
usb_open+0x186/0x220 drivers/usb/core/file.c:47
chrdev_open+0x237/0x6a0 fs/char_dev.c:414
do_dentry_open+0x6cb/0x1390 fs/open.c:958
vfs_open+0x82/0x3f0 fs/open.c:1088
do_open fs/namei.c:3774 [inline]
path_openat+0x1e6a/0x2d60 fs/namei.c:3933
do_filp_open+0x1dc/0x430 fs/namei.c:3960
do_sys_openat2+0x17a/0x1e0 fs/open.c:1415
do_sys_open fs/open.c:1430 [inline]
__do_sys_openat fs/open.c:1446 [inline]
__se_sys_openat fs/open.c:1441 [inline]
__x64_sys_openat+0x175/0x210 fs/open.c:1441
do_syscall_x64 arch/x86/entry/common.c:52 [inline]
do_syscall_64+0xcd/0x250 arch/x86/entry/common.c:83
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7f812643c990
RSP: 002b:00007f8125eb8b70 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007f812643c990
RDX: 0000000000000002 RSI: 00007f8125eb8c10 RDI: 00000000ffffff9c
RBP: 00007f8125eb8c10 R08: 0000000000000000 R09: 00007f8125eb8987
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000000
R13: 0000000000000000 R14: 00007f81265f5f80 R15: 00007ffe0cde8e18
</TASK>
INFO: task syz.1.42:6583 blocked for more than 145 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz.1.42 state:D stack:27200 pid:6583 tgid:6583 ppid:4252 flags:0x00004006
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
rpm_resume+0x5a8/0x1330 drivers/base/power/runtime.c:834
rpm_resume+0x750/0x1330 drivers/base/power/runtime.c:892
__pm_runtime_resume+0xb6/0x170 drivers/base/power/runtime.c:1172
pm_runtime_resume_and_get include/linux/pm_runtime.h:430 [inline]
usb_autopm_get_interface+0x20/0xe0 drivers/usb/core/driver.c:1833
wdm_manage_power+0x1d/0xa0 drivers/usb/class/cdc-wdm.c:1134
wdm_release+0x26a/0x440 drivers/usb/class/cdc-wdm.c:779
__fput+0x3f6/0xb60 fs/file_table.c:431
task_work_run+0x14e/0x250 kernel/task_work.c:228
resume_user_mode_work include/linux/resume_user_mode.h:50 [inline]
exit_to_user_mode_loop kernel/entry/common.c:114 [inline]
exit_to_user_mode_prepare include/linux/entry-common.h:328 [inline]
__syscall_exit_to_user_mode_work kernel/entry/common.c:207 [inline]
syscall_exit_to_user_mode+0x24e/0x260 kernel/entry/common.c:218
do_syscall_64+0xda/0x250 arch/x86/entry/common.c:89
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7f3fe8bddff9
RSP: 002b:00007ffe2eff10a8 EFLAGS: 00000246 ORIG_RAX: 00000000000001b4
RAX: 0000000000000000 RBX: 00007f3fe8d97a80 RCX: 00007f3fe8bddff9
RDX: 0000000000000000 RSI: 000000000000001e RDI: 0000000000000003
RBP: 00007f3fe8d97a80 R08: 0000000000000000 R09: 00007ffe2eff139f
R10: 000000000003fdc8 R11: 0000000000000246 R12: 000000000002008b
R13: 00007ffe2eff11b0 R14: 0000000000000032 R15: ffffffffffffffff
</TASK>
Showing all locks held in the system:
1 lock held by khungtaskd/30:
#0: ffffffff88ebb100 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire include/linux/rcupdate.h:337 [inline]
#0: ffffffff88ebb100 (rcu_read_lock){....}-{1:2}, at: rcu_read_lock include/linux/rcupdate.h:849 [inline]
#0: ffffffff88ebb100 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x7f/0x390 kernel/locking/lockdep.c:6720
2 locks held by kworker/u8:6/277:
#0: ffff888100089148 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc900017cfd80 ((work_completion)(&sub_info->work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
3 locks held by kworker/0:2/803:
#0: ffff888100eed548 ((wq_completion)pm){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc90001cffd80 ((work_completion)(&dev->power.work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
#2: ffff888108306508 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3206 [inline]
#2: ffff888108306508 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_port_suspend+0x255/0xf10 drivers/usb/core/hub.c:3463
2 locks held by getty/2606:
#0: ffff88810fb730a0 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x24/0x80 drivers/tty/tty_ldisc.c:243
#1: ffffc900000432f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xfba/0x1480 drivers/tty/n_tty.c:2211
6 locks held by kworker/1:2/2737:
#0: ffff8881062f5948 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc9000188fd80 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
#2: ffff888109b9b190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#2: ffff888109b9b190 (&dev->mutex){....}-{3:3}, at: hub_event+0x1be/0x4f40 drivers/usb/core/hub.c:5849
#3: ffff88812f3d1190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#3: ffff88812f3d1190 (&dev->mutex){....}-{3:3}, at: usb_disconnect+0x10a/0x920 drivers/usb/core/hub.c:2295
#4: ffff8881289f3160 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#4: ffff8881289f3160 (&dev->mutex){....}-{3:3}, at: __device_driver_lock drivers/base/dd.c:1095 [inline]
#4: ffff8881289f3160 (&dev->mutex){....}-{3:3}, at: device_release_driver_internal+0xa4/0x610 drivers/base/dd.c:1293
#5: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_deregister_dev+0x7c/0x1e0 drivers/usb/core/file.c:186
6 locks held by kworker/1:3/6528:
#0: ffff8881062f5948 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc900014efd80 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
#2: ffff888109beb190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#2: ffff888109beb190 (&dev->mutex){....}-{3:3}, at: hub_event+0x1be/0x4f40 drivers/usb/core/hub.c:5849
#3: ffff888107798190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#3: ffff888107798190 (&dev->mutex){....}-{3:3}, at: usb_disconnect+0x10a/0x920 drivers/usb/core/hub.c:2295
#4: ffff888108ab9160 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#4: ffff888108ab9160 (&dev->mutex){....}-{3:3}, at: __device_driver_lock drivers/base/dd.c:1095 [inline]
#4: ffff888108ab9160 (&dev->mutex){....}-{3:3}, at: device_release_driver_internal+0xa4/0x610 drivers/base/dd.c:1293
#5: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_deregister_dev+0x7c/0x1e0 drivers/usb/core/file.c:186
6 locks held by kworker/1:4/6532:
#0: ffff8881062f5948 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc9000176fd80 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
#2: ffff888109bec190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#2: ffff888109bec190 (&dev->mutex){....}-{3:3}, at: hub_event+0x1be/0x4f40 drivers/usb/core/hub.c:5849
#3: ffff88810779a190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#3: ffff88810779a190 (&dev->mutex){....}-{3:3}, at: usb_disconnect+0x10a/0x920 drivers/usb/core/hub.c:2295
#4: ffff888108aba160 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#4: ffff888108aba160 (&dev->mutex){....}-{3:3}, at: __device_driver_lock drivers/base/dd.c:1095 [inline]
#4: ffff888108aba160 (&dev->mutex){....}-{3:3}, at: device_release_driver_internal+0xa4/0x610 drivers/base/dd.c:1293
#5: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_deregister_dev+0x7c/0x1e0 drivers/usb/core/file.c:186
2 locks held by syz.0.41/6582:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
#1: ffffffff89a968c8 (wdm_mutex){+.+.}-{3:3}, at: wdm_open+0x5d/0x630 drivers/usb/class/cdc-wdm.c:715
1 lock held by syz.1.42/6583:
#0: ffffffff89a968c8 (wdm_mutex){+.+.}-{3:3}, at: wdm_release+0x4b/0x440 drivers/usb/class/cdc-wdm.c:764
1 lock held by syz.0.52/7534:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.53/7543:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.78/8496:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.79/8501:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.101/9454:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.102/9455:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.127/10414:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.128/10416:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.151/11367:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.150/11370:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.174/12326:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.175/12330:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz-executor/12353:
#0: ffff8881f583d6d8 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested kernel/sched/core.c:593 [inline]
#0: ffff8881f583d6d8 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock kernel/sched/sched.h:1505 [inline]
#0: ffff8881f583d6d8 (&rq->__lock){-.-.}-{2:2}, at: rq_lock kernel/sched/sched.h:1804 [inline]
#0: ffff8881f583d6d8 (&rq->__lock){-.-.}-{2:2}, at: __schedule+0x293/0x34b0 kernel/sched/core.c:6582
1 lock held by modprobe/13201:
=============================================
NMI backtrace for cpu 1
CPU: 1 UID: 0 PID: 30 Comm: khungtaskd Not tainted 6.12.0-rc3-syzkaller-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 09/13/2024
Call Trace:
<TASK>
__dump_stack lib/dump_stack.c:94 [inline]
dump_stack_lvl+0x116/0x1f0 lib/dump_stack.c:120
nmi_cpu_backtrace+0x27b/0x390 lib/nmi_backtrace.c:113
nmi_trigger_cpumask_backtrace+0x29c/0x300 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:162 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:223 [inline]
watchdog+0xf0c/0x1240 kernel/hung_task.c:379
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 UID: 0 PID: 13206 Comm: modprobe Not tainted 6.12.0-rc3-syzkaller-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 09/13/2024
RIP: 0033:0x7f5f3fb3c0d5
Code: e9 4a ff ff ff 66 0f 6f 0c 0e 66 0f 73 db 0f 66 0f 73 d8 0f 90 66 0f 74 cb 66 0f f8 c8 66 0f d7 d1 f7 d2 66 90 49 8d 44 09 f0 <48> 8d 3c 07 48 8d 34 0e 45 85 c0 74 0e 48 87 f7 66 66 2e 0f 1f 84
RSP: 002b:00007ffc2841f138 EFLAGS: 00000287
RAX: 0000000000000004 RBX: 00007f5f3f8aaa78 RCX: 0000000000000010
RDX: 00000000ffff0100 RSI: 00007f5f3fa5a150 RDI: 00007f5f3f8bab70
RBP: 0000000000000009 R08: 0000000000000000 R09: 0000000000000004
R10: fffffffffffffb84 R11: 0000000000000007 R12: 00007f5f3fb17c30
R13: 00007ffc2841f1f4 R14: 00007f5f3fb165c0 R15: 00007f5f3fa5a15d
FS: 00007f5f3f815380 GS: 0000000000000000
Tested on:
commit: 8e929cb5 Linux 6.12-rc3
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git v6.12-rc3
console output: https://syzkaller.appspot.com/x/log.txt?x=1130845f980000
kernel config: https://syzkaller.appspot.com/x/.config?x=9878fe11046ea2c6
dashboard link: https://syzkaller.appspot.com/bug?extid=f342ea16c9d06d80b585
compiler: gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40
patch: https://syzkaller.appspot.com/x/patch.diff?x=16ed1030580000
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in usb_port_suspend
2024-10-15 14:54 ` syzbot
@ 2024-10-15 19:23 ` Alan Stern
2024-10-15 19:54 ` syzbot
0 siblings, 1 reply; 12+ messages in thread
From: Alan Stern @ 2024-10-15 19:23 UTC (permalink / raw)
To: syzbot; +Cc: linux-kernel, linux-usb, syzkaller-bugs
On Tue, Oct 15, 2024 at 07:54:03AM -0700, syzbot wrote:
> Hello,
>
> syzbot has tested the proposed patch but the reproducer is still triggering an issue:
No good; the console log shows that the timer must have been activated
and then stopped during a period that wasn't printed in the log. This
next patch tries to print out more of the history. Will it be enough?
Alan Stern
#syz test: https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git v6.12-rc3
Index: usb-devel/drivers/usb/gadget/udc/dummy_hcd.c
===================================================================
--- usb-devel.orig/drivers/usb/gadget/udc/dummy_hcd.c
+++ usb-devel/drivers/usb/gadget/udc/dummy_hcd.c
@@ -50,7 +50,7 @@
#define POWER_BUDGET 500 /* in mA; use 8 for low-power port testing */
#define POWER_BUDGET_3 900 /* in mA */
-#define DUMMY_TIMER_INT_NSECS 125000 /* 1 microframe */
+#define DUMMY_INT_KTIME ns_to_ktime(125000) /* 1 microframe */
static const char driver_name[] = "dummy_hcd";
static const char driver_desc[] = "USB Host+Gadget Emulator";
@@ -239,6 +239,12 @@ enum dummy_rh_state {
DUMMY_RH_RUNNING
};
+struct alaninfo {
+ const char * str;
+ int starts, stops;
+};
+#define MAX_INFO 16
+
struct dummy_hcd {
struct dummy *dum;
enum dummy_rh_state rh_state;
@@ -257,6 +263,10 @@ struct dummy_hcd {
unsigned active:1;
unsigned old_active:1;
unsigned resuming:1;
+
+ struct alaninfo alaninfo[MAX_INFO];
+ int alanindex;
+ int starts, stops;
};
struct dummy {
@@ -323,6 +333,44 @@ static inline struct dummy *gadget_dev_t
return container_of(dev, struct dummy, gadget.dev);
}
+void alandbg(struct dummy_hcd *dum_hcd, const char *str, int type);
+void alandbg(struct dummy_hcd *dum_hcd, const char *str, int type)
+{
+ int i = dum_hcd->alanindex;
+ struct alaninfo *info = &dum_hcd->alaninfo[i];
+
+ if (type == 1)
+ ++dum_hcd->starts;
+ else if (type == 2)
+ ++dum_hcd->stops;
+ info->str = str;
+ info->starts = dum_hcd->starts;
+ info->stops = dum_hcd->stops;
+
+ if (++i >= MAX_INFO)
+ i = 0;
+ dum_hcd->alanindex = i;
+}
+
+void alandump(struct dummy_hcd *dum_hcd);
+void alandump(struct dummy_hcd *dum_hcd)
+{
+ int i = dum_hcd->alanindex;
+ int j;
+ struct alaninfo *info = &dum_hcd->alaninfo[i];
+ char *p, buf[4 * 24];
+
+ p = buf;
+ for (j = 0; j < 4; ++j) {
+ if (--i < 0)
+ i = MAX_INFO - 1;
+ info = &dum_hcd->alaninfo[i];
+ p += sprintf(p, "%s %d %d ",
+ info->str, info->starts, info->stops);
+ }
+ dev_info(dummy_dev(dum_hcd), "%s\n", p);
+}
+
/*-------------------------------------------------------------------------*/
/* DEVICE/GADGET SIDE UTILITY ROUTINES */
@@ -1303,9 +1351,11 @@ static int dummy_urb_enqueue(
urb->error_count = 1; /* mark as a new urb */
/* kick the scheduler, it'll do the rest */
- if (!hrtimer_active(&dum_hcd->timer))
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(DUMMY_TIMER_INT_NSECS),
+ if (!hrtimer_active(&dum_hcd->timer)) {
+ alandbg(dum_hcd, "start1", 1);
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
HRTIMER_MODE_REL_SOFT);
+ }
done:
spin_unlock_irqrestore(&dum_hcd->dum->lock, flags);
@@ -1325,9 +1375,17 @@ static int dummy_urb_dequeue(struct usb_
rc = usb_hcd_check_unlink_urb(hcd, urb, status);
if (!rc && dum_hcd->rh_state != DUMMY_RH_RUNNING &&
- !list_empty(&dum_hcd->urbp_list))
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(0), HRTIMER_MODE_REL_SOFT);
-
+ !list_empty(&dum_hcd->urbp_list)) {
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
+ HRTIMER_MODE_REL_SOFT);
+ alandbg(dum_hcd, "start2", 1);
+ } else {
+ int active = hrtimer_active(&dum_hcd->timer);
+ dev_info(dummy_dev(dum_hcd), "Dequeue norestart: %d %d active %d\n",
+ rc, list_empty(&dum_hcd->urbp_list), active);
+ if (rc == 0 && !active)
+ alandump(dum_hcd);
+ }
spin_unlock_irqrestore(&dum_hcd->dum->lock, flags);
return rc;
}
@@ -1813,10 +1871,12 @@ static enum hrtimer_restart dummy_timer(
/* look at each urb queued by the host side driver */
spin_lock_irqsave(&dum->lock, flags);
+ alandbg(dum_hcd, "handler1", 0);
if (!dum_hcd->udev) {
dev_err(dummy_dev(dum_hcd),
"timer fired with no URBs pending?\n");
+ alandbg(dum_hcd, "handler2", 2);
spin_unlock_irqrestore(&dum->lock, flags);
return HRTIMER_NORESTART;
}
@@ -1994,10 +2054,13 @@ return_urb:
if (list_empty(&dum_hcd->urbp_list)) {
usb_put_dev(dum_hcd->udev);
dum_hcd->udev = NULL;
+ alandbg(dum_hcd, "handler3", 2);
} else if (dum_hcd->rh_state == DUMMY_RH_RUNNING) {
- /* want a 1 msec delay here */
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(DUMMY_TIMER_INT_NSECS),
+ alandbg(dum_hcd, "handler-start", 1);
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
HRTIMER_MODE_REL_SOFT);
+ } else {
+ alandbg(dum_hcd, "handler4", 2);
}
spin_unlock_irqrestore(&dum->lock, flags);
@@ -2390,8 +2453,11 @@ static int dummy_bus_resume(struct usb_h
} else {
dum_hcd->rh_state = DUMMY_RH_RUNNING;
set_link_state(dum_hcd);
- if (!list_empty(&dum_hcd->urbp_list))
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(0), HRTIMER_MODE_REL_SOFT);
+ if (!list_empty(&dum_hcd->urbp_list)) {
+ alandbg(dum_hcd, "start3", 1);
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
+ HRTIMER_MODE_REL_SOFT);
+ }
hcd->state = HC_STATE_RUNNING;
}
spin_unlock_irq(&dum_hcd->dum->lock);
@@ -2490,6 +2556,10 @@ static int dummy_start(struct usb_hcd *h
{
struct dummy_hcd *dum_hcd = hcd_to_dummy_hcd(hcd);
+ int i;
+ for (i = 0; i < MAX_INFO; ++i)
+ dum_hcd->alaninfo[i].str = "";
+
/*
* HOST side init ... we emulate a root hub that'll only ever
* talk to one device (the gadget side). Also appears in sysfs,
@@ -2521,6 +2591,7 @@ static void dummy_stop(struct usb_hcd *h
{
struct dummy_hcd *dum_hcd = hcd_to_dummy_hcd(hcd);
+ alandbg(dum_hcd, "cancel", 0);
hrtimer_cancel(&dum_hcd->timer);
device_remove_file(dummy_dev(dum_hcd), &dev_attr_urbs);
dev_info(dummy_dev(dum_hcd), "stopped\n");
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in usb_port_suspend
2024-10-15 19:23 ` Alan Stern
@ 2024-10-15 19:54 ` syzbot
2024-10-16 0:54 ` Alan Stern
0 siblings, 1 reply; 12+ messages in thread
From: syzbot @ 2024-10-15 19:54 UTC (permalink / raw)
To: linux-kernel, linux-usb, stern, syzkaller-bugs
Hello,
syzbot has tested the proposed patch but the reproducer is still triggering an issue:
INFO: task hung in usb_deregister_dev
INFO: task kworker/0:2:2512 blocked for more than 143 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/0:2 state:D stack:24064 pid:2512 tgid:2512 ppid:2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
rwsem_down_write_slowpath+0x539/0x12a0 kernel/locking/rwsem.c:1176
__down_write_common kernel/locking/rwsem.c:1304 [inline]
__down_write kernel/locking/rwsem.c:1313 [inline]
down_write+0x1d8/0x200 kernel/locking/rwsem.c:1578
usb_deregister_dev+0x7c/0x1e0 drivers/usb/core/file.c:186
wdm_disconnect+0x25/0x440 drivers/usb/class/cdc-wdm.c:1214
usb_unbind_interface+0x1e8/0x970 drivers/usb/core/driver.c:461
device_remove drivers/base/dd.c:569 [inline]
device_remove+0x122/0x170 drivers/base/dd.c:561
__device_release_driver drivers/base/dd.c:1273 [inline]
device_release_driver_internal+0x44a/0x610 drivers/base/dd.c:1296
bus_remove_device+0x22f/0x420 drivers/base/bus.c:576
device_del+0x396/0x9f0 drivers/base/core.c:3864
usb_disable_device+0x36c/0x7f0 drivers/usb/core/message.c:1418
usb_disconnect+0x2e1/0x920 drivers/usb/core/hub.c:2304
hub_port_connect drivers/usb/core/hub.c:5361 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5661 [inline]
port_event drivers/usb/core/hub.c:5821 [inline]
hub_event+0x1bed/0x4f40 drivers/usb/core/hub.c:5903
process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3229
process_scheduled_works kernel/workqueue.c:3310 [inline]
worker_thread+0x6c8/0xf00 kernel/workqueue.c:3391
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
INFO: task kworker/1:4:6549 blocked for more than 143 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:4 state:D stack:23808 pid:6549 tgid:6549 ppid:2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
rwsem_down_write_slowpath+0x539/0x12a0 kernel/locking/rwsem.c:1176
__down_write_common kernel/locking/rwsem.c:1304 [inline]
__down_write kernel/locking/rwsem.c:1313 [inline]
down_write+0x1d8/0x200 kernel/locking/rwsem.c:1578
usb_deregister_dev+0x7c/0x1e0 drivers/usb/core/file.c:186
wdm_disconnect+0x25/0x440 drivers/usb/class/cdc-wdm.c:1214
usb_unbind_interface+0x1e8/0x970 drivers/usb/core/driver.c:461
device_remove drivers/base/dd.c:569 [inline]
device_remove+0x122/0x170 drivers/base/dd.c:561
__device_release_driver drivers/base/dd.c:1273 [inline]
device_release_driver_internal+0x44a/0x610 drivers/base/dd.c:1296
bus_remove_device+0x22f/0x420 drivers/base/bus.c:576
device_del+0x396/0x9f0 drivers/base/core.c:3864
usb_disable_device+0x36c/0x7f0 drivers/usb/core/message.c:1418
usb_disconnect+0x2e1/0x920 drivers/usb/core/hub.c:2304
hub_port_connect drivers/usb/core/hub.c:5361 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5661 [inline]
port_event drivers/usb/core/hub.c:5821 [inline]
hub_event+0x1bed/0x4f40 drivers/usb/core/hub.c:5903
process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3229
process_scheduled_works kernel/workqueue.c:3310 [inline]
worker_thread+0x6c8/0xf00 kernel/workqueue.c:3391
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
INFO: task syz.0.138:6782 blocked for more than 144 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz.0.138 state:D stack:28384 pid:6782 tgid:6780 ppid:4252 flags:0x00004006
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
__mutex_lock_common kernel/locking/mutex.c:684 [inline]
__mutex_lock+0x5b8/0x9c0 kernel/locking/mutex.c:752
wdm_open+0x5d/0x630 drivers/usb/class/cdc-wdm.c:715
usb_open+0x186/0x220 drivers/usb/core/file.c:47
chrdev_open+0x237/0x6a0 fs/char_dev.c:414
do_dentry_open+0x6cb/0x1390 fs/open.c:958
vfs_open+0x82/0x3f0 fs/open.c:1088
do_open fs/namei.c:3774 [inline]
path_openat+0x1e6a/0x2d60 fs/namei.c:3933
do_filp_open+0x1dc/0x430 fs/namei.c:3960
do_sys_openat2+0x17a/0x1e0 fs/open.c:1415
do_sys_open fs/open.c:1430 [inline]
__do_sys_openat fs/open.c:1446 [inline]
__se_sys_openat fs/open.c:1441 [inline]
__x64_sys_openat+0x175/0x210 fs/open.c:1441
do_syscall_x64 arch/x86/entry/common.c:52 [inline]
do_syscall_64+0xcd/0x250 arch/x86/entry/common.c:83
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7fcc6387c990
RSP: 002b:00007fcc632feb70 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007fcc6387c990
RDX: 0000000000000002 RSI: 00007fcc632fec10 RDI: 00000000ffffff9c
RBP: 00007fcc632fec10 R08: 0000000000000000 R09: 00007fcc632fe987
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000000
R13: 0000000000000000 R14: 00007fcc63a35f80 R15: 00007ffeddcdbf28
</TASK>
INFO: task syz.2.140:6783 blocked for more than 144 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz.2.140 state:D stack:27856 pid:6783 tgid:6783 ppid:4261 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
rpm_resume+0x5a8/0x1330 drivers/base/power/runtime.c:834
rpm_resume+0x750/0x1330 drivers/base/power/runtime.c:892
__pm_runtime_resume+0xb6/0x170 drivers/base/power/runtime.c:1172
pm_runtime_resume_and_get include/linux/pm_runtime.h:430 [inline]
usb_autopm_get_interface+0x20/0xe0 drivers/usb/core/driver.c:1833
wdm_manage_power+0x1d/0xa0 drivers/usb/class/cdc-wdm.c:1134
wdm_release+0x26a/0x440 drivers/usb/class/cdc-wdm.c:779
__fput+0x3f6/0xb60 fs/file_table.c:431
task_work_run+0x14e/0x250 kernel/task_work.c:228
resume_user_mode_work include/linux/resume_user_mode.h:50 [inline]
exit_to_user_mode_loop kernel/entry/common.c:114 [inline]
exit_to_user_mode_prepare include/linux/entry-common.h:328 [inline]
__syscall_exit_to_user_mode_work kernel/entry/common.c:207 [inline]
syscall_exit_to_user_mode+0x24e/0x260 kernel/entry/common.c:218
do_syscall_64+0xda/0x250 arch/x86/entry/common.c:89
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7f90f837dff9
RSP: 002b:00007ffca65f11c8 EFLAGS: 00000246 ORIG_RAX: 00000000000001b4
RAX: 0000000000000000 RBX: 00007f90f8537a80 RCX: 00007f90f837dff9
RDX: 0000000000000000 RSI: 000000000000001e RDI: 0000000000000003
RBP: 00007f90f8537a80 R08: 0000000000000000 R09: 00007ffca65f14bf
R10: 000000000003fdc8 R11: 0000000000000246 R12: 000000000002740e
R13: 00007ffca65f12d0 R14: 0000000000000032 R15: ffffffffffffffff
</TASK>
INFO: task syz.4.141:6787 blocked for more than 144 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz.4.141 state:D stack:28432 pid:6787 tgid:6786 ppid:4264 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
rwsem_down_read_slowpath+0x61e/0xb20 kernel/locking/rwsem.c:1084
__down_read_common kernel/locking/rwsem.c:1248 [inline]
__down_read kernel/locking/rwsem.c:1261 [inline]
down_read+0x124/0x330 kernel/locking/rwsem.c:1526
usb_open+0x23/0x220 drivers/usb/core/file.c:38
chrdev_open+0x237/0x6a0 fs/char_dev.c:414
do_dentry_open+0x6cb/0x1390 fs/open.c:958
vfs_open+0x82/0x3f0 fs/open.c:1088
do_open fs/namei.c:3774 [inline]
path_openat+0x1e6a/0x2d60 fs/namei.c:3933
do_filp_open+0x1dc/0x430 fs/namei.c:3960
do_sys_openat2+0x17a/0x1e0 fs/open.c:1415
do_sys_open fs/open.c:1430 [inline]
__do_sys_openat fs/open.c:1446 [inline]
__se_sys_openat fs/open.c:1441 [inline]
__x64_sys_openat+0x175/0x210 fs/open.c:1441
do_syscall_x64 arch/x86/entry/common.c:52 [inline]
do_syscall_64+0xcd/0x250 arch/x86/entry/common.c:83
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7ff8ea88c990
RSP: 002b:00007ff8ea308b70 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007ff8ea88c990
RDX: 0000000000000002 RSI: 00007ff8ea308c10 RDI: 00000000ffffff9c
RBP: 00007ff8ea308c10 R08: 0000000000000000 R09: 00007ff8ea308987
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000000
R13: 0000000000000000 R14: 00007ff8eaa45f80 R15: 00007ffec702e308
</TASK>
Showing all locks held in the system:
3 locks held by kworker/0:1/9:
#0: ffff888100eed548 ((wq_completion)pm){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc9000009fd80 ((work_completion)(&dev->power.work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
#2: ffff888109b9f508 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3206 [inline]
#2: ffff888109b9f508 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_port_suspend+0x255/0xf10 drivers/usb/core/hub.c:3463
2 locks held by kworker/u8:1/28:
#0: ffff888100089148 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc900001e7d80 ((work_completion)(&sub_info->work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
1 lock held by khungtaskd/30:
#0: ffffffff88ebb100 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire include/linux/rcupdate.h:337 [inline]
#0: ffffffff88ebb100 (rcu_read_lock){....}-{1:2}, at: rcu_read_lock include/linux/rcupdate.h:849 [inline]
#0: ffffffff88ebb100 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x7f/0x390 kernel/locking/lockdep.c:6720
2 locks held by kworker/u8:4/50:
#0: ffff888100089148 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc90000537d80 ((work_completion)(&sub_info->work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
2 locks held by kworker/u8:7/1190:
#0: ffff888100089148 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc9000224fd80 ((work_completion)(&sub_info->work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
6 locks held by kworker/0:2/2512:
#0: ffff8881062c3548 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc9000541fd80 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
#2: ffff888109b11190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#2: ffff888109b11190 (&dev->mutex){....}-{3:3}, at: hub_event+0x1be/0x4f40 drivers/usb/core/hub.c:5849
#3: ffff88811b9b4190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#3: ffff88811b9b4190 (&dev->mutex){....}-{3:3}, at: usb_disconnect+0x10a/0x920 drivers/usb/core/hub.c:2295
#4: ffff88811f559160 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#4: ffff88811f559160 (&dev->mutex){....}-{3:3}, at: __device_driver_lock drivers/base/dd.c:1095 [inline]
#4: ffff88811f559160 (&dev->mutex){....}-{3:3}, at: device_release_driver_internal+0xa4/0x610 drivers/base/dd.c:1293
#5: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_deregister_dev+0x7c/0x1e0 drivers/usb/core/file.c:186
2 locks held by getty/2607:
#0: ffff88810aaf30a0 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x24/0x80 drivers/tty/tty_ldisc.c:243
#1: ffffc900000432f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xfba/0x1480 drivers/tty/n_tty.c:2211
6 locks held by kworker/1:4/6549:
#0: ffff8881062c3548 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc900024ffd80 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
#2: ffff888109b7c190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#2: ffff888109b7c190 (&dev->mutex){....}-{3:3}, at: hub_event+0x1be/0x4f40 drivers/usb/core/hub.c:5849
#3: ffff888124e37190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#3: ffff888124e37190 (&dev->mutex){....}-{3:3}, at: usb_disconnect+0x10a/0x920 drivers/usb/core/hub.c:2295
#4: ffff888111feb160 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#4: ffff888111feb160 (&dev->mutex){....}-{3:3}, at: __device_driver_lock drivers/base/dd.c:1095 [inline]
#4: ffff888111feb160 (&dev->mutex){....}-{3:3}, at: device_release_driver_internal+0xa4/0x610 drivers/base/dd.c:1293
#5: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_deregister_dev+0x7c/0x1e0 drivers/usb/core/file.c:186
2 locks held by syz.0.138/6782:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
#1: ffffffff89a968c8 (wdm_mutex){+.+.}-{3:3}, at: wdm_open+0x5d/0x630 drivers/usb/class/cdc-wdm.c:715
1 lock held by syz.2.140/6783:
#0: ffffffff89a968c8 (wdm_mutex){+.+.}-{3:3}, at: wdm_release+0x4b/0x440 drivers/usb/class/cdc-wdm.c:764
1 lock held by syz.4.141/6787:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.2.149/8119:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.148/8150:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.4.152/8191:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.2.169/9495:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.4.172/9568:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.170/9595:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.2.190/10846:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.4.192/10975:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.194/10999:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.2.211/12144:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.212/12387:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.4.214/12403:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.2.230/13364:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.233/13784:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.4.235/13803:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.253/14135:
#0: ffffffff88ec69f8 (rcu_state.exp_mutex){+.+.}-{3:3}, at: exp_funnel_lock+0x282/0x3b0 kernel/rcu/tree_exp.h:297
1 lock held by modprobe/14326:
1 lock held by modprobe/14327:
6 locks held by modprobe/14328:
=============================================
NMI backtrace for cpu 1
CPU: 1 UID: 0 PID: 30 Comm: khungtaskd Not tainted 6.12.0-rc3-syzkaller-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 09/13/2024
Call Trace:
<TASK>
__dump_stack lib/dump_stack.c:94 [inline]
dump_stack_lvl+0x116/0x1f0 lib/dump_stack.c:120
nmi_cpu_backtrace+0x27b/0x390 lib/nmi_backtrace.c:113
nmi_trigger_cpumask_backtrace+0x29c/0x300 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:162 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:223 [inline]
watchdog+0xf0c/0x1240 kernel/hung_task.c:379
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 UID: 0 PID: 14333 Comm: modprobe Not tainted 6.12.0-rc3-syzkaller-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 09/13/2024
RIP: 0010:security_file_alloc+0x8d/0x140 security/security.c:2859
Code: 00 00 00 e8 d5 6f 2e ff eb 1b e8 ce 6f 2e ff 66 90 31 ed e8 c5 6f 2e ff 89 e8 48 83 c4 08 5b 5d c3 cc cc cc cc e8 b3 6f 2e ff <48> 89 df e8 fb 6c 01 00 31 ff 89 c5 89 c6 e8 e0 71 2e ff 85 ed 74
RSP: 0018:ffffc90005f4fa60 EFLAGS: 00000293
RAX: 0000000000000000 RBX: ffff8881156e16c0 RCX: 1ffff11022adc2fd
RDX: ffff888101bb57c0 RSI: ffffffff82276f6d RDI: ffff8881156e17e8
RBP: ffff888100adb280 R08: 00000000ffffffff R09: 0000000000000000
R10: ffff88810ba90a20 R11: 0000000000000000 R12: 0000000000008000
R13: ffff8881156e1738 R14: ffffc90005f4fc30 R15: 0000000000000000
FS: 0000000000000000(0000) GS:ffff8881f5800000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f892cfbf270 CR3: 000000012565a000 CR4: 00000000003506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<NMI>
</NMI>
<TASK>
init_file+0x93/0x230 fs/file_table.c:153
alloc_empty_file+0x91/0x1e0 fs/file_table.c:213
path_openat+0xe1/0x2d60 fs/namei.c:3919
do_filp_open+0x1dc/0x430 fs/namei.c:3960
do_sys_openat2+0x17a/0x1e0 fs/open.c:1415
do_sys_open fs/open.c:1430 [inline]
__do_sys_openat fs/open.c:1446 [inline]
__se_sys_openat fs/open.c:1441 [inline]
__x64_sys_openat+0x175/0x210 fs/open.c:1441
do_syscall_x64 arch/x86/entry/common.c:52 [inline]
do_syscall_64+0xcd/0x250 arch/x86/entry/common.c:83
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7f892d266a46
Code: 10 00 00 00 44 8b 54 24 e0 48 89 44 24 c0 48 8d 44 24 d0 48 89 44 24 c8 44 89 c2 4c 89 ce bf 9c ff ff ff b8 01 01 00 00 0f 05 <48> 3d 00 f0 ff ff 76 0c f7 d8 89 05 0a 48 01 00 48 83 c8 ff c3 31
RSP: 002b:00007ffc0094ef28 EFLAGS: 00000287 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 00007ffc0094f188 RCX: 00007f892d266a46
RDX: 0000000000080000 RSI: 00007ffc0094efa0 RDI: 00000000ffffff9c
RBP: 00007ffc0094ef90 R08: 0000000000080000 R09: 00007ffc0094efa0
R10: 0000000000000000 R11: 0000000000000287 R12: 00007ffc0094efa0
R13: 0000000000000003 R14: 00007ffc0094f16f R15: 00000000ffffffff
</TASK>
Tested on:
commit: 8e929cb5 Linux 6.12-rc3
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git v6.12-rc3
console output: https://syzkaller.appspot.com/x/log.txt?x=16e7845f980000
kernel config: https://syzkaller.appspot.com/x/.config?x=9878fe11046ea2c6
dashboard link: https://syzkaller.appspot.com/bug?extid=f342ea16c9d06d80b585
compiler: gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40
patch: https://syzkaller.appspot.com/x/patch.diff?x=154a3727980000
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in usb_port_suspend
2024-10-15 19:54 ` syzbot
@ 2024-10-16 0:54 ` Alan Stern
2024-10-16 1:54 ` syzbot
0 siblings, 1 reply; 12+ messages in thread
From: Alan Stern @ 2024-10-16 0:54 UTC (permalink / raw)
To: syzbot; +Cc: linux-kernel, linux-usb, syzkaller-bugs
On Tue, Oct 15, 2024 at 12:54:02PM -0700, syzbot wrote:
> Hello,
>
> syzbot has tested the proposed patch but the reproducer is still triggering an issue:
Arghh... Mistake in the patch caused the debugging info not to be
printed. Here's a corrected version.
Alan Stern
#syz test: https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git v6.12-rc3
Index: usb-devel/drivers/usb/gadget/udc/dummy_hcd.c
===================================================================
--- usb-devel.orig/drivers/usb/gadget/udc/dummy_hcd.c
+++ usb-devel/drivers/usb/gadget/udc/dummy_hcd.c
@@ -50,7 +50,7 @@
#define POWER_BUDGET 500 /* in mA; use 8 for low-power port testing */
#define POWER_BUDGET_3 900 /* in mA */
-#define DUMMY_TIMER_INT_NSECS 125000 /* 1 microframe */
+#define DUMMY_INT_KTIME ns_to_ktime(125000) /* 1 microframe */
static const char driver_name[] = "dummy_hcd";
static const char driver_desc[] = "USB Host+Gadget Emulator";
@@ -239,6 +239,12 @@ enum dummy_rh_state {
DUMMY_RH_RUNNING
};
+struct alaninfo {
+ const char * str;
+ int starts, stops;
+};
+#define MAX_INFO 16
+
struct dummy_hcd {
struct dummy *dum;
enum dummy_rh_state rh_state;
@@ -257,6 +263,10 @@ struct dummy_hcd {
unsigned active:1;
unsigned old_active:1;
unsigned resuming:1;
+
+ struct alaninfo alaninfo[MAX_INFO];
+ int alanindex;
+ int starts, stops;
};
struct dummy {
@@ -323,6 +333,44 @@ static inline struct dummy *gadget_dev_t
return container_of(dev, struct dummy, gadget.dev);
}
+void alandbg(struct dummy_hcd *dum_hcd, const char *str, int type);
+void alandbg(struct dummy_hcd *dum_hcd, const char *str, int type)
+{
+ int i = dum_hcd->alanindex;
+ struct alaninfo *info = &dum_hcd->alaninfo[i];
+
+ if (type == 1)
+ ++dum_hcd->starts;
+ else if (type == 2)
+ ++dum_hcd->stops;
+ info->str = str;
+ info->starts = dum_hcd->starts;
+ info->stops = dum_hcd->stops;
+
+ if (++i >= MAX_INFO)
+ i = 0;
+ dum_hcd->alanindex = i;
+}
+
+void alandump(struct dummy_hcd *dum_hcd);
+void alandump(struct dummy_hcd *dum_hcd)
+{
+ int i = dum_hcd->alanindex;
+ int j;
+ struct alaninfo *info = &dum_hcd->alaninfo[i];
+ char *p, buf[4 * 24];
+
+ p = buf;
+ for (j = 0; j < 4; ++j) {
+ if (--i < 0)
+ i = MAX_INFO - 1;
+ info = &dum_hcd->alaninfo[i];
+ p += sprintf(p, "%s %d %d ",
+ info->str, info->starts, info->stops);
+ }
+ dev_info(dummy_dev(dum_hcd), "%s\n", buf);
+}
+
/*-------------------------------------------------------------------------*/
/* DEVICE/GADGET SIDE UTILITY ROUTINES */
@@ -1303,9 +1351,11 @@ static int dummy_urb_enqueue(
urb->error_count = 1; /* mark as a new urb */
/* kick the scheduler, it'll do the rest */
- if (!hrtimer_active(&dum_hcd->timer))
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(DUMMY_TIMER_INT_NSECS),
+ if (!hrtimer_active(&dum_hcd->timer)) {
+ alandbg(dum_hcd, "start1", 1);
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
HRTIMER_MODE_REL_SOFT);
+ }
done:
spin_unlock_irqrestore(&dum_hcd->dum->lock, flags);
@@ -1325,9 +1375,17 @@ static int dummy_urb_dequeue(struct usb_
rc = usb_hcd_check_unlink_urb(hcd, urb, status);
if (!rc && dum_hcd->rh_state != DUMMY_RH_RUNNING &&
- !list_empty(&dum_hcd->urbp_list))
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(0), HRTIMER_MODE_REL_SOFT);
-
+ !list_empty(&dum_hcd->urbp_list)) {
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
+ HRTIMER_MODE_REL_SOFT);
+ alandbg(dum_hcd, "start2", 1);
+ } else {
+ int active = hrtimer_active(&dum_hcd->timer);
+ dev_info(dummy_dev(dum_hcd), "Dequeue norestart: %d %d active %d\n",
+ rc, list_empty(&dum_hcd->urbp_list), active);
+ if (rc == 0 && !active)
+ alandump(dum_hcd);
+ }
spin_unlock_irqrestore(&dum_hcd->dum->lock, flags);
return rc;
}
@@ -1813,10 +1871,12 @@ static enum hrtimer_restart dummy_timer(
/* look at each urb queued by the host side driver */
spin_lock_irqsave(&dum->lock, flags);
+ alandbg(dum_hcd, "handler1", 0);
if (!dum_hcd->udev) {
dev_err(dummy_dev(dum_hcd),
"timer fired with no URBs pending?\n");
+ alandbg(dum_hcd, "handler2", 2);
spin_unlock_irqrestore(&dum->lock, flags);
return HRTIMER_NORESTART;
}
@@ -1994,10 +2054,13 @@ return_urb:
if (list_empty(&dum_hcd->urbp_list)) {
usb_put_dev(dum_hcd->udev);
dum_hcd->udev = NULL;
+ alandbg(dum_hcd, "handler3", 2);
} else if (dum_hcd->rh_state == DUMMY_RH_RUNNING) {
- /* want a 1 msec delay here */
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(DUMMY_TIMER_INT_NSECS),
+ alandbg(dum_hcd, "handler-start", 1);
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
HRTIMER_MODE_REL_SOFT);
+ } else {
+ alandbg(dum_hcd, "handler4", 2);
}
spin_unlock_irqrestore(&dum->lock, flags);
@@ -2390,8 +2453,11 @@ static int dummy_bus_resume(struct usb_h
} else {
dum_hcd->rh_state = DUMMY_RH_RUNNING;
set_link_state(dum_hcd);
- if (!list_empty(&dum_hcd->urbp_list))
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(0), HRTIMER_MODE_REL_SOFT);
+ if (!list_empty(&dum_hcd->urbp_list)) {
+ alandbg(dum_hcd, "start3", 1);
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
+ HRTIMER_MODE_REL_SOFT);
+ }
hcd->state = HC_STATE_RUNNING;
}
spin_unlock_irq(&dum_hcd->dum->lock);
@@ -2490,6 +2556,10 @@ static int dummy_start(struct usb_hcd *h
{
struct dummy_hcd *dum_hcd = hcd_to_dummy_hcd(hcd);
+ int i;
+ for (i = 0; i < MAX_INFO; ++i)
+ dum_hcd->alaninfo[i].str = "";
+
/*
* HOST side init ... we emulate a root hub that'll only ever
* talk to one device (the gadget side). Also appears in sysfs,
@@ -2521,6 +2591,7 @@ static void dummy_stop(struct usb_hcd *h
{
struct dummy_hcd *dum_hcd = hcd_to_dummy_hcd(hcd);
+ alandbg(dum_hcd, "cancel", 0);
hrtimer_cancel(&dum_hcd->timer);
device_remove_file(dummy_dev(dum_hcd), &dev_attr_urbs);
dev_info(dummy_dev(dum_hcd), "stopped\n");
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in usb_port_suspend
2024-10-16 0:54 ` Alan Stern
@ 2024-10-16 1:54 ` syzbot
2024-10-16 2:11 ` Alan Stern
0 siblings, 1 reply; 12+ messages in thread
From: syzbot @ 2024-10-16 1:54 UTC (permalink / raw)
To: linux-kernel, linux-usb, stern, syzkaller-bugs
Hello,
syzbot has tested the proposed patch but the reproducer is still triggering an issue:
INFO: task hung in usb_register_dev
INFO: task kworker/1:3:2749 blocked for more than 143 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:3 state:D stack:23024 pid:2749 tgid:2749 ppid:2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
rwsem_down_write_slowpath+0x539/0x12a0 kernel/locking/rwsem.c:1176
__down_write_common kernel/locking/rwsem.c:1304 [inline]
__down_write kernel/locking/rwsem.c:1313 [inline]
down_write+0x1d8/0x200 kernel/locking/rwsem.c:1578
usb_register_dev+0x11c/0x550 drivers/usb/core/file.c:134
wdm_create+0x1269/0x1870 drivers/usb/class/cdc-wdm.c:1113
wdm_probe+0x239/0x2e0 drivers/usb/class/cdc-wdm.c:1165
usb_probe_interface+0x309/0x9d0 drivers/usb/core/driver.c:399
call_driver_probe drivers/base/dd.c:579 [inline]
really_probe+0x23e/0xa90 drivers/base/dd.c:658
__driver_probe_device+0x1de/0x440 drivers/base/dd.c:800
driver_probe_device+0x4c/0x1b0 drivers/base/dd.c:830
__device_attach_driver+0x1df/0x310 drivers/base/dd.c:958
bus_for_each_drv+0x157/0x1e0 drivers/base/bus.c:459
__device_attach+0x1e8/0x4b0 drivers/base/dd.c:1030
bus_probe_device+0x17f/0x1c0 drivers/base/bus.c:534
device_add+0x114b/0x1a70 drivers/base/core.c:3675
usb_set_configuration+0x10cb/0x1c50 drivers/usb/core/message.c:2210
usb_generic_driver_probe+0xb1/0x110 drivers/usb/core/generic.c:254
usb_probe_device+0xec/0x3e0 drivers/usb/core/driver.c:294
call_driver_probe drivers/base/dd.c:579 [inline]
really_probe+0x23e/0xa90 drivers/base/dd.c:658
__driver_probe_device+0x1de/0x440 drivers/base/dd.c:800
driver_probe_device+0x4c/0x1b0 drivers/base/dd.c:830
__device_attach_driver+0x1df/0x310 drivers/base/dd.c:958
bus_for_each_drv+0x157/0x1e0 drivers/base/bus.c:459
__device_attach+0x1e8/0x4b0 drivers/base/dd.c:1030
bus_probe_device+0x17f/0x1c0 drivers/base/bus.c:534
device_add+0x114b/0x1a70 drivers/base/core.c:3675
usb_new_device+0xd90/0x1a10 drivers/usb/core/hub.c:2651
hub_port_connect drivers/usb/core/hub.c:5521 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5661 [inline]
port_event drivers/usb/core/hub.c:5821 [inline]
hub_event+0x2e58/0x4f40 drivers/usb/core/hub.c:5903
process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3229
process_scheduled_works kernel/workqueue.c:3310 [inline]
worker_thread+0x6c8/0xf00 kernel/workqueue.c:3391
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
INFO: task syz.2.212:6930 blocked for more than 143 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz.2.212 state:D stack:28432 pid:6930 tgid:6927 ppid:4256 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
__mutex_lock_common kernel/locking/mutex.c:684 [inline]
__mutex_lock+0x5b8/0x9c0 kernel/locking/mutex.c:752
wdm_open+0x5d/0x630 drivers/usb/class/cdc-wdm.c:715
usb_open+0x186/0x220 drivers/usb/core/file.c:47
chrdev_open+0x237/0x6a0 fs/char_dev.c:414
do_dentry_open+0x6cb/0x1390 fs/open.c:958
vfs_open+0x82/0x3f0 fs/open.c:1088
do_open fs/namei.c:3774 [inline]
path_openat+0x1e6a/0x2d60 fs/namei.c:3933
do_filp_open+0x1dc/0x430 fs/namei.c:3960
do_sys_openat2+0x17a/0x1e0 fs/open.c:1415
do_sys_open fs/open.c:1430 [inline]
__do_sys_openat fs/open.c:1446 [inline]
__se_sys_openat fs/open.c:1441 [inline]
__x64_sys_openat+0x175/0x210 fs/open.c:1441
do_syscall_x64 arch/x86/entry/common.c:52 [inline]
do_syscall_64+0xcd/0x250 arch/x86/entry/common.c:83
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7fdc49bec990
RSP: 002b:00007fdc4966eb70 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007fdc49bec990
RDX: 0000000000000002 RSI: 00007fdc4966ec10 RDI: 00000000ffffff9c
RBP: 00007fdc4966ec10 R08: 0000000000000000 R09: 00007fdc4966e987
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000000
R13: 0000000000000000 R14: 00007fdc49da5f80 R15: 00007ffed2825e78
</TASK>
INFO: task syz.0.211:6928 blocked for more than 144 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz.0.211 state:D stack:27856 pid:6928 tgid:6928 ppid:4251 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
__mutex_lock_common kernel/locking/mutex.c:684 [inline]
__mutex_lock+0x5b8/0x9c0 kernel/locking/mutex.c:752
wdm_release+0x4b/0x440 drivers/usb/class/cdc-wdm.c:764
__fput+0x3f6/0xb60 fs/file_table.c:431
task_work_run+0x14e/0x250 kernel/task_work.c:228
resume_user_mode_work include/linux/resume_user_mode.h:50 [inline]
exit_to_user_mode_loop kernel/entry/common.c:114 [inline]
exit_to_user_mode_prepare include/linux/entry-common.h:328 [inline]
__syscall_exit_to_user_mode_work kernel/entry/common.c:207 [inline]
syscall_exit_to_user_mode+0x24e/0x260 kernel/entry/common.c:218
do_syscall_64+0xda/0x250 arch/x86/entry/common.c:89
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7fd96296dff9
RSP: 002b:00007ffcaa4c7618 EFLAGS: 00000246 ORIG_RAX: 00000000000001b4
RAX: 0000000000000000 RBX: 00007fd962b27a80 RCX: 00007fd96296dff9
RDX: 0000000000000000 RSI: 000000000000001e RDI: 0000000000000003
RBP: 00007fd962b27a80 R08: 0000000000000000 R09: 00007ffcaa4c790f
R10: 000000000003fdc8 R11: 0000000000000246 R12: 000000000002b754
R13: 00007ffcaa4c7720 R14: 0000000000000032 R15: ffffffffffffffff
</TASK>
INFO: task syz.1.214:6931 blocked for more than 144 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz.1.214 state:D stack:27792 pid:6931 tgid:6931 ppid:4255 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
__mutex_lock_common kernel/locking/mutex.c:684 [inline]
__mutex_lock+0x5b8/0x9c0 kernel/locking/mutex.c:752
wdm_release+0x4b/0x440 drivers/usb/class/cdc-wdm.c:764
__fput+0x3f6/0xb60 fs/file_table.c:431
task_work_run+0x14e/0x250 kernel/task_work.c:228
resume_user_mode_work include/linux/resume_user_mode.h:50 [inline]
exit_to_user_mode_loop kernel/entry/common.c:114 [inline]
exit_to_user_mode_prepare include/linux/entry-common.h:328 [inline]
__syscall_exit_to_user_mode_work kernel/entry/common.c:207 [inline]
syscall_exit_to_user_mode+0x24e/0x260 kernel/entry/common.c:218
do_syscall_64+0xda/0x250 arch/x86/entry/common.c:89
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7fcf6aefdff9
RSP: 002b:00007ffeac8e10d8 EFLAGS: 00000246 ORIG_RAX: 00000000000001b4
RAX: 0000000000000000 RBX: 00007fcf6b0b7a80 RCX: 00007fcf6aefdff9
RDX: 0000000000000000 RSI: 000000000000001e RDI: 0000000000000003
RBP: 00007fcf6b0b7a80 R08: 0000000000000000 R09: 00007ffeac8e13cf
R10: 000000000003fdc8 R11: 0000000000000246 R12: 000000000002b754
R13: 00007ffeac8e11e0 R14: 0000000000000032 R15: ffffffffffffffff
</TASK>
INFO: task syz.4.213:6934 blocked for more than 144 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz.4.213 state:D stack:28024 pid:6934 tgid:6933 ppid:4261 flags:0x00004004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
rpm_resume+0x5a8/0x1330 drivers/base/power/runtime.c:834
rpm_resume+0x750/0x1330 drivers/base/power/runtime.c:892
__pm_runtime_resume+0xb6/0x170 drivers/base/power/runtime.c:1172
pm_runtime_resume_and_get include/linux/pm_runtime.h:430 [inline]
usb_autopm_get_interface+0x20/0xe0 drivers/usb/core/driver.c:1833
wdm_open+0x24a/0x630 drivers/usb/class/cdc-wdm.c:730
usb_open+0x186/0x220 drivers/usb/core/file.c:47
chrdev_open+0x237/0x6a0 fs/char_dev.c:414
do_dentry_open+0x6cb/0x1390 fs/open.c:958
vfs_open+0x82/0x3f0 fs/open.c:1088
do_open fs/namei.c:3774 [inline]
path_openat+0x1e6a/0x2d60 fs/namei.c:3933
do_filp_open+0x1dc/0x430 fs/namei.c:3960
do_sys_openat2+0x17a/0x1e0 fs/open.c:1415
do_sys_open fs/open.c:1430 [inline]
__do_sys_openat fs/open.c:1446 [inline]
__se_sys_openat fs/open.c:1441 [inline]
__x64_sys_openat+0x175/0x210 fs/open.c:1441
do_syscall_x64 arch/x86/entry/common.c:52 [inline]
do_syscall_64+0xcd/0x250 arch/x86/entry/common.c:83
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7fbedff2c990
RSP: 002b:00007fbedf9aeb70 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007fbedff2c990
RDX: 0000000000000002 RSI: 00007fbedf9aec10 RDI: 00000000ffffff9c
RBP: 00007fbedf9aec10 R08: 0000000000000000 R09: 00007fbedf9ae987
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000000
R13: 0000000000000000 R14: 00007fbee00e5f80 R15: 00007ffd8a3f7b78
</TASK>
INFO: task syz.3.215:6938 blocked for more than 145 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz.3.215 state:D stack:28432 pid:6938 tgid:6937 ppid:4265 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
rwsem_down_read_slowpath+0x61e/0xb20 kernel/locking/rwsem.c:1084
__down_read_common kernel/locking/rwsem.c:1248 [inline]
__down_read kernel/locking/rwsem.c:1261 [inline]
down_read+0x124/0x330 kernel/locking/rwsem.c:1526
usb_open+0x23/0x220 drivers/usb/core/file.c:38
chrdev_open+0x237/0x6a0 fs/char_dev.c:414
do_dentry_open+0x6cb/0x1390 fs/open.c:958
vfs_open+0x82/0x3f0 fs/open.c:1088
do_open fs/namei.c:3774 [inline]
path_openat+0x1e6a/0x2d60 fs/namei.c:3933
do_filp_open+0x1dc/0x430 fs/namei.c:3960
do_sys_openat2+0x17a/0x1e0 fs/open.c:1415
do_sys_open fs/open.c:1430 [inline]
__do_sys_openat fs/open.c:1446 [inline]
__se_sys_openat fs/open.c:1441 [inline]
__x64_sys_openat+0x175/0x210 fs/open.c:1441
do_syscall_x64 arch/x86/entry/common.c:52 [inline]
do_syscall_64+0xcd/0x250 arch/x86/entry/common.c:83
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7f5db0e7c990
RSP: 002b:00007f5db08f8b70 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007f5db0e7c990
RDX: 0000000000000002 RSI: 00007f5db08f8c10 RDI: 00000000ffffff9c
RBP: 00007f5db08f8c10 R08: 0000000000000000 R09: 00007f5db08f8987
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000000
R13: 0000000000000000 R14: 00007f5db1035f80 R15: 00007ffdea149328
</TASK>
Showing all locks held in the system:
3 locks held by kworker/0:0/8:
#0: ffff888100eed548 ((wq_completion)pm){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc9000008fd80 ((work_completion)(&dev->power.work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
#2: ffff888109f05508 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3206 [inline]
#2: ffff888109f05508 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_port_suspend+0x255/0xf10 drivers/usb/core/hub.c:3463
2 locks held by kworker/u8:0/11:
#0: ffff888100089148 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc900000bfd80 ((work_completion)(&sub_info->work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
1 lock held by khungtaskd/30:
#0: ffffffff88ebb100 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire include/linux/rcupdate.h:337 [inline]
#0: ffffffff88ebb100 (rcu_read_lock){....}-{1:2}, at: rcu_read_lock include/linux/rcupdate.h:849 [inline]
#0: ffffffff88ebb100 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x7f/0x390 kernel/locking/lockdep.c:6720
2 locks held by kworker/u8:5/88:
#0: ffff888100089148 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc90000577d80 ((work_completion)(&sub_info->work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
2 locks held by kworker/u8:6/740:
#0: ffff888100089148 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc90001b7fd80 ((work_completion)(&sub_info->work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
2 locks held by kworker/u8:7/1143:
#0: ffff888100089148 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc90001f7fd80 ((work_completion)(&sub_info->work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
2 locks held by kworker/u8:8/1341:
#0: ffff888100089148 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc9000290fd80 ((work_completion)(&sub_info->work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
2 locks held by getty/2607:
#0: ffff88810f7b90a0 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x24/0x80 drivers/tty/tty_ldisc.c:243
#1: ffffc900000432f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xfba/0x1480 drivers/tty/n_tty.c:2211
6 locks held by kworker/1:3/2749:
#0: ffff888105efad48 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc900014bfd80 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
#2: ffff888109f80190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#2: ffff888109f80190 (&dev->mutex){....}-{3:3}, at: hub_event+0x1be/0x4f40 drivers/usb/core/hub.c:5849
#3: ffff888117a26190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#3: ffff888117a26190 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7f/0x4b0 drivers/base/dd.c:1005
#4: ffff888117a27160 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#4: ffff888117a27160 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7f/0x4b0 drivers/base/dd.c:1005
#5: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_register_dev+0x11c/0x550 drivers/usb/core/file.c:134
2 locks held by syz.2.212/6930:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
#1: ffffffff89a968c8 (wdm_mutex){+.+.}-{3:3}, at: wdm_open+0x5d/0x630 drivers/usb/class/cdc-wdm.c:715
1 lock held by syz.0.211/6928:
#0: ffffffff89a968c8 (wdm_mutex){+.+.}-{3:3}, at: wdm_release+0x4b/0x440 drivers/usb/class/cdc-wdm.c:764
1 lock held by syz.1.214/6931:
#0: ffffffff89a968c8 (wdm_mutex){+.+.}-{3:3}, at: wdm_release+0x4b/0x440 drivers/usb/class/cdc-wdm.c:764
2 locks held by syz.4.213/6934:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
#1: ffffffff89a968c8 (wdm_mutex){+.+.}-{3:3}, at: wdm_open+0x5d/0x630 drivers/usb/class/cdc-wdm.c:715
1 lock held by syz.3.215/6938:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.3.219/9202:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.217/9206:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.216/9215:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.2.218/9218:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.4.220/9221:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.4.225/11478:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.222/11483:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.2.223/11501:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.3.224/11503:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.221/11505:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.4.230/13758:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.226/13767:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.2.228/13772:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.3.229/13779:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.227/13788:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by modprobe/15403:
1 lock held by modprobe/15424:
#0: ffff8881f583d6d8 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock_nested kernel/sched/core.c:593 [inline]
#0: ffff8881f583d6d8 (&rq->__lock){-.-.}-{2:2}, at: raw_spin_rq_lock kernel/sched/sched.h:1505 [inline]
#0: ffff8881f583d6d8 (&rq->__lock){-.-.}-{2:2}, at: rq_lock kernel/sched/sched.h:1804 [inline]
#0: ffff8881f583d6d8 (&rq->__lock){-.-.}-{2:2}, at: __schedule+0x293/0x34b0 kernel/sched/core.c:6582
1 lock held by modprobe/15425:
1 lock held by modprobe/15426:
1 lock held by modprobe/15427:
1 lock held by modprobe/15428:
=============================================
NMI backtrace for cpu 1
CPU: 1 UID: 0 PID: 30 Comm: khungtaskd Not tainted 6.12.0-rc3-syzkaller-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 09/13/2024
Call Trace:
<TASK>
__dump_stack lib/dump_stack.c:94 [inline]
dump_stack_lvl+0x116/0x1f0 lib/dump_stack.c:120
nmi_cpu_backtrace+0x27b/0x390 lib/nmi_backtrace.c:113
nmi_trigger_cpumask_backtrace+0x29c/0x300 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:162 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:223 [inline]
watchdog+0xf0c/0x1240 kernel/hung_task.c:379
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 UID: 0 PID: 15432 Comm: modprobe Not tainted 6.12.0-rc3-syzkaller-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 09/13/2024
RIP: 0010:native_save_fl arch/x86/include/asm/irqflags.h:26 [inline]
RIP: 0010:arch_local_save_flags arch/x86/include/asm/irqflags.h:87 [inline]
RIP: 0010:check_preemption_disabled+0x2d/0xe0 lib/smp_processor_id.c:19
Code: 53 48 83 ec 08 65 8b 1d 1d 31 15 79 65 8b 05 12 31 15 79 a9 ff ff ff 7f 74 0f 48 83 c4 08 89 d8 5b 5d 41 5c c3 cc cc cc cc 9c <58> f6 c4 02 74 ea 65 48 8b 05 e5 30 15 79 f6 40 2f 04 48 89 fd 74
RSP: 0000:ffffc900043afc78 EFLAGS: 00000046
RAX: 0000000080000000 RBX: 0000000000000000 RCX: 1ffffffff1f5b434
RDX: 0000000000000001 RSI: ffffffff8727f4a0 RDI: ffffffff8746ea40
RBP: 7a9c3eb05b4f2345 R08: 0000000000000000 R09: fffffbfff1f55dc1
R10: ffffffff8faaee0f R11: 0000000000000000 R12: 0000000000000200
R13: ffff888100ebc000 R14: ffff88811a232e40 R15: ffff88811ae90d40
FS: 0000000000000000(0000) GS:ffff8881f5800000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007ff853262380 CR3: 0000000113168000 CR4: 00000000003506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<NMI>
</NMI>
<TASK>
lockdep_recursion_finish kernel/locking/lockdep.c:467 [inline]
lockdep_hardirqs_on_prepare+0x17d/0x420 kernel/locking/lockdep.c:4407
trace_hardirqs_on+0x36/0x40 kernel/trace/trace_preemptirq.c:61
memcg1_commit_charge+0x105/0x170 mm/memcontrol-v1.c:1521
charge_memcg mm/memcontrol.c:4472 [inline]
__mem_cgroup_charge+0xae/0x270 mm/memcontrol.c:4483
mem_cgroup_charge include/linux/memcontrol.h:694 [inline]
folio_prealloc mm/memory.c:1070 [inline]
alloc_anon_folio mm/memory.c:4721 [inline]
do_anonymous_page mm/memory.c:4778 [inline]
do_pte_missing mm/memory.c:3963 [inline]
handle_pte_fault mm/memory.c:5751 [inline]
__handle_mm_fault+0x1656/0x3390 mm/memory.c:5894
handle_mm_fault+0x3fa/0xaa0 mm/memory.c:6062
do_user_addr_fault+0x613/0x12c0 arch/x86/mm/fault.c:1338
handle_page_fault arch/x86/mm/fault.c:1481 [inline]
exc_page_fault+0x5c/0xc0 arch/x86/mm/fault.c:1539
asm_exc_page_fault+0x26/0x30 arch/x86/include/asm/idtentry.h:623
RIP: 0033:0x7ff85357a0b8
Code: 48 89 c5 31 c0 48 85 ed 74 49 31 d2 48 8d 44 1d ff b9 70 02 00 00 48 f7 f3 48 0f af c3 4d 8d 84 05 40 f6 ff ff 31 c0 4c 89 c7 <f3> ab 49 89 a8 c0 09 00 00 4c 89 c7 e8 33 fa ff ff 48 85 c0 75 13
RSP: 002b:00007ffc3678d0b0 EFLAGS: 00010246
RAX: 0000000000000000 RBX: 0000000000000040 RCX: 0000000000000270
RDX: 000000000000001f RSI: 0000000000000008 RDI: 00007ff853262380
RBP: 00007ff853261b60 R08: 00007ff853262380 R09: 0000000000000000
R10: 0000000000000000 R11: 00007ff853261740 R12: 0000000000000041
R13: 00000000000011c0 R14: 0000000000000000 R15: 00007ff85359b2a0
</TASK>
Tested on:
commit: 8e929cb5 Linux 6.12-rc3
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git v6.12-rc3
console output: https://syzkaller.appspot.com/x/log.txt?x=13022c40580000
kernel config: https://syzkaller.appspot.com/x/.config?x=9878fe11046ea2c6
dashboard link: https://syzkaller.appspot.com/bug?extid=f342ea16c9d06d80b585
compiler: gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40
patch: https://syzkaller.appspot.com/x/patch.diff?x=16642c40580000
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in usb_port_suspend
2024-10-16 1:54 ` syzbot
@ 2024-10-16 2:11 ` Alan Stern
2024-10-16 2:34 ` syzbot
0 siblings, 1 reply; 12+ messages in thread
From: Alan Stern @ 2024-10-16 2:11 UTC (permalink / raw)
To: syzbot; +Cc: linux-kernel, linux-usb, syzkaller-bugs
On Tue, Oct 15, 2024 at 06:54:02PM -0700, syzbot wrote:
> Hello,
>
> syzbot has tested the proposed patch but the reproducer is still triggering an issue:
The console log shows that an URB must have been submitted at a time
that doesn't show. Better add another debug tracer for submissions.
I'm getting there (slowly)...
Alan Stern
#syz test: https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git v6.12-rc3
Index: usb-devel/drivers/usb/gadget/udc/dummy_hcd.c
===================================================================
--- usb-devel.orig/drivers/usb/gadget/udc/dummy_hcd.c
+++ usb-devel/drivers/usb/gadget/udc/dummy_hcd.c
@@ -50,7 +50,7 @@
#define POWER_BUDGET 500 /* in mA; use 8 for low-power port testing */
#define POWER_BUDGET_3 900 /* in mA */
-#define DUMMY_TIMER_INT_NSECS 125000 /* 1 microframe */
+#define DUMMY_INT_KTIME ns_to_ktime(125000) /* 1 microframe */
static const char driver_name[] = "dummy_hcd";
static const char driver_desc[] = "USB Host+Gadget Emulator";
@@ -239,6 +239,12 @@ enum dummy_rh_state {
DUMMY_RH_RUNNING
};
+struct alaninfo {
+ const char * str;
+ int starts, stops;
+};
+#define MAX_INFO 16
+
struct dummy_hcd {
struct dummy *dum;
enum dummy_rh_state rh_state;
@@ -257,6 +263,10 @@ struct dummy_hcd {
unsigned active:1;
unsigned old_active:1;
unsigned resuming:1;
+
+ struct alaninfo alaninfo[MAX_INFO];
+ int alanindex;
+ int starts, stops;
};
struct dummy {
@@ -323,6 +333,44 @@ static inline struct dummy *gadget_dev_t
return container_of(dev, struct dummy, gadget.dev);
}
+void alandbg(struct dummy_hcd *dum_hcd, const char *str, int type);
+void alandbg(struct dummy_hcd *dum_hcd, const char *str, int type)
+{
+ int i = dum_hcd->alanindex;
+ struct alaninfo *info = &dum_hcd->alaninfo[i];
+
+ if (type == 1)
+ ++dum_hcd->starts;
+ else if (type == 2)
+ ++dum_hcd->stops;
+ info->str = str;
+ info->starts = dum_hcd->starts;
+ info->stops = dum_hcd->stops;
+
+ if (++i >= MAX_INFO)
+ i = 0;
+ dum_hcd->alanindex = i;
+}
+
+void alandump(struct dummy_hcd *dum_hcd);
+void alandump(struct dummy_hcd *dum_hcd)
+{
+ int i = dum_hcd->alanindex;
+ int j;
+ struct alaninfo *info = &dum_hcd->alaninfo[i];
+ char *p, buf[4 * 24];
+
+ p = buf;
+ for (j = 0; j < 4; ++j) {
+ if (--i < 0)
+ i = MAX_INFO - 1;
+ info = &dum_hcd->alaninfo[i];
+ p += sprintf(p, "%s %d %d ",
+ info->str, info->starts, info->stops);
+ }
+ dev_info(dummy_dev(dum_hcd), "%s\n", buf);
+}
+
/*-------------------------------------------------------------------------*/
/* DEVICE/GADGET SIDE UTILITY ROUTINES */
@@ -1303,9 +1351,12 @@ static int dummy_urb_enqueue(
urb->error_count = 1; /* mark as a new urb */
/* kick the scheduler, it'll do the rest */
- if (!hrtimer_active(&dum_hcd->timer))
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(DUMMY_TIMER_INT_NSECS),
+ if (!hrtimer_active(&dum_hcd->timer)) {
+ alandbg(dum_hcd, "start1", 1);
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
HRTIMER_MODE_REL_SOFT);
+ } else
+ alandbg(dum_hcd, "submit", 0);
done:
spin_unlock_irqrestore(&dum_hcd->dum->lock, flags);
@@ -1325,9 +1376,20 @@ static int dummy_urb_dequeue(struct usb_
rc = usb_hcd_check_unlink_urb(hcd, urb, status);
if (!rc && dum_hcd->rh_state != DUMMY_RH_RUNNING &&
- !list_empty(&dum_hcd->urbp_list))
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(0), HRTIMER_MODE_REL_SOFT);
-
+ !list_empty(&dum_hcd->urbp_list)) {
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
+ HRTIMER_MODE_REL_SOFT);
+ alandbg(dum_hcd, "start2", 1);
+ } else {
+ int active = hrtimer_active(&dum_hcd->timer);
+ dev_info(dummy_dev(dum_hcd), "Dequeue norestart: %d %d active %d\n",
+ rc, list_empty(&dum_hcd->urbp_list), active);
+ if (rc == 0) {
+ if (!active)
+ alandump(dum_hcd);
+ alandbg(dum_hcd, "unlink", 0);
+ }
+ }
spin_unlock_irqrestore(&dum_hcd->dum->lock, flags);
return rc;
}
@@ -1813,10 +1875,12 @@ static enum hrtimer_restart dummy_timer(
/* look at each urb queued by the host side driver */
spin_lock_irqsave(&dum->lock, flags);
+ alandbg(dum_hcd, "handler1", 0);
if (!dum_hcd->udev) {
dev_err(dummy_dev(dum_hcd),
"timer fired with no URBs pending?\n");
+ alandbg(dum_hcd, "handler2", 2);
spin_unlock_irqrestore(&dum->lock, flags);
return HRTIMER_NORESTART;
}
@@ -1994,10 +2058,13 @@ return_urb:
if (list_empty(&dum_hcd->urbp_list)) {
usb_put_dev(dum_hcd->udev);
dum_hcd->udev = NULL;
+ alandbg(dum_hcd, "handler3", 2);
} else if (dum_hcd->rh_state == DUMMY_RH_RUNNING) {
- /* want a 1 msec delay here */
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(DUMMY_TIMER_INT_NSECS),
+ alandbg(dum_hcd, "handler-start", 1);
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
HRTIMER_MODE_REL_SOFT);
+ } else {
+ alandbg(dum_hcd, "handler4", 2);
}
spin_unlock_irqrestore(&dum->lock, flags);
@@ -2390,8 +2457,11 @@ static int dummy_bus_resume(struct usb_h
} else {
dum_hcd->rh_state = DUMMY_RH_RUNNING;
set_link_state(dum_hcd);
- if (!list_empty(&dum_hcd->urbp_list))
- hrtimer_start(&dum_hcd->timer, ns_to_ktime(0), HRTIMER_MODE_REL_SOFT);
+ if (!list_empty(&dum_hcd->urbp_list)) {
+ alandbg(dum_hcd, "start3", 1);
+ hrtimer_start(&dum_hcd->timer, DUMMY_INT_KTIME,
+ HRTIMER_MODE_REL_SOFT);
+ }
hcd->state = HC_STATE_RUNNING;
}
spin_unlock_irq(&dum_hcd->dum->lock);
@@ -2490,6 +2560,10 @@ static int dummy_start(struct usb_hcd *h
{
struct dummy_hcd *dum_hcd = hcd_to_dummy_hcd(hcd);
+ int i;
+ for (i = 0; i < MAX_INFO; ++i)
+ dum_hcd->alaninfo[i].str = "";
+
/*
* HOST side init ... we emulate a root hub that'll only ever
* talk to one device (the gadget side). Also appears in sysfs,
@@ -2521,6 +2595,7 @@ static void dummy_stop(struct usb_hcd *h
{
struct dummy_hcd *dum_hcd = hcd_to_dummy_hcd(hcd);
+ alandbg(dum_hcd, "cancel", 0);
hrtimer_cancel(&dum_hcd->timer);
device_remove_file(dummy_dev(dum_hcd), &dev_attr_urbs);
dev_info(dummy_dev(dum_hcd), "stopped\n");
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in usb_port_suspend
2024-10-16 2:11 ` Alan Stern
@ 2024-10-16 2:34 ` syzbot
2024-10-16 14:40 ` Alan Stern
0 siblings, 1 reply; 12+ messages in thread
From: syzbot @ 2024-10-16 2:34 UTC (permalink / raw)
To: linux-kernel, linux-usb, stern, syzkaller-bugs
Hello,
syzbot has tested the proposed patch but the reproducer is still triggering an issue:
INFO: task hung in usb_deregister_dev
INFO: task kworker/1:0:24 blocked for more than 143 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:0 state:D stack:23808 pid:24 tgid:24 ppid:2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
rwsem_down_write_slowpath+0x539/0x12a0 kernel/locking/rwsem.c:1176
__down_write_common kernel/locking/rwsem.c:1304 [inline]
__down_write kernel/locking/rwsem.c:1313 [inline]
down_write+0x1d8/0x200 kernel/locking/rwsem.c:1578
usb_deregister_dev+0x7c/0x1e0 drivers/usb/core/file.c:186
wdm_disconnect+0x25/0x440 drivers/usb/class/cdc-wdm.c:1214
usb_unbind_interface+0x1e8/0x970 drivers/usb/core/driver.c:461
device_remove drivers/base/dd.c:569 [inline]
device_remove+0x122/0x170 drivers/base/dd.c:561
__device_release_driver drivers/base/dd.c:1273 [inline]
device_release_driver_internal+0x44a/0x610 drivers/base/dd.c:1296
bus_remove_device+0x22f/0x420 drivers/base/bus.c:576
device_del+0x396/0x9f0 drivers/base/core.c:3864
usb_disable_device+0x36c/0x7f0 drivers/usb/core/message.c:1418
usb_disconnect+0x2e1/0x920 drivers/usb/core/hub.c:2304
hub_port_connect drivers/usb/core/hub.c:5361 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5661 [inline]
port_event drivers/usb/core/hub.c:5821 [inline]
hub_event+0x1bed/0x4f40 drivers/usb/core/hub.c:5903
process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3229
process_scheduled_works kernel/workqueue.c:3310 [inline]
worker_thread+0x6c8/0xf00 kernel/workqueue.c:3391
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
INFO: task kworker/1:1:36 blocked for more than 143 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:1 state:D stack:24144 pid:36 tgid:36 ppid:2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
rwsem_down_write_slowpath+0x539/0x12a0 kernel/locking/rwsem.c:1176
__down_write_common kernel/locking/rwsem.c:1304 [inline]
__down_write kernel/locking/rwsem.c:1313 [inline]
down_write+0x1d8/0x200 kernel/locking/rwsem.c:1578
usb_deregister_dev+0x7c/0x1e0 drivers/usb/core/file.c:186
wdm_disconnect+0x25/0x440 drivers/usb/class/cdc-wdm.c:1214
usb_unbind_interface+0x1e8/0x970 drivers/usb/core/driver.c:461
device_remove drivers/base/dd.c:569 [inline]
device_remove+0x122/0x170 drivers/base/dd.c:561
__device_release_driver drivers/base/dd.c:1273 [inline]
device_release_driver_internal+0x44a/0x610 drivers/base/dd.c:1296
bus_remove_device+0x22f/0x420 drivers/base/bus.c:576
device_del+0x396/0x9f0 drivers/base/core.c:3864
usb_disable_device+0x36c/0x7f0 drivers/usb/core/message.c:1418
usb_disconnect+0x2e1/0x920 drivers/usb/core/hub.c:2304
hub_port_connect drivers/usb/core/hub.c:5361 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5661 [inline]
port_event drivers/usb/core/hub.c:5821 [inline]
hub_event+0x1bed/0x4f40 drivers/usb/core/hub.c:5903
process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3229
process_scheduled_works kernel/workqueue.c:3310 [inline]
worker_thread+0x6c8/0xf00 kernel/workqueue.c:3391
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
INFO: task kworker/1:3:6534 blocked for more than 144 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:3 state:D stack:23808 pid:6534 tgid:6534 ppid:2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
rwsem_down_write_slowpath+0x539/0x12a0 kernel/locking/rwsem.c:1176
__down_write_common kernel/locking/rwsem.c:1304 [inline]
__down_write kernel/locking/rwsem.c:1313 [inline]
down_write+0x1d8/0x200 kernel/locking/rwsem.c:1578
usb_register_dev+0x11c/0x550 drivers/usb/core/file.c:134
wdm_create+0x1269/0x1870 drivers/usb/class/cdc-wdm.c:1113
wdm_probe+0x239/0x2e0 drivers/usb/class/cdc-wdm.c:1165
usb_probe_interface+0x309/0x9d0 drivers/usb/core/driver.c:399
call_driver_probe drivers/base/dd.c:579 [inline]
really_probe+0x23e/0xa90 drivers/base/dd.c:658
__driver_probe_device+0x1de/0x440 drivers/base/dd.c:800
driver_probe_device+0x4c/0x1b0 drivers/base/dd.c:830
__device_attach_driver+0x1df/0x310 drivers/base/dd.c:958
bus_for_each_drv+0x157/0x1e0 drivers/base/bus.c:459
__device_attach+0x1e8/0x4b0 drivers/base/dd.c:1030
bus_probe_device+0x17f/0x1c0 drivers/base/bus.c:534
device_add+0x114b/0x1a70 drivers/base/core.c:3675
usb_set_configuration+0x10cb/0x1c50 drivers/usb/core/message.c:2210
usb_generic_driver_probe+0xb1/0x110 drivers/usb/core/generic.c:254
usb_probe_device+0xec/0x3e0 drivers/usb/core/driver.c:294
call_driver_probe drivers/base/dd.c:579 [inline]
really_probe+0x23e/0xa90 drivers/base/dd.c:658
__driver_probe_device+0x1de/0x440 drivers/base/dd.c:800
driver_probe_device+0x4c/0x1b0 drivers/base/dd.c:830
__device_attach_driver+0x1df/0x310 drivers/base/dd.c:958
bus_for_each_drv+0x157/0x1e0 drivers/base/bus.c:459
__device_attach+0x1e8/0x4b0 drivers/base/dd.c:1030
bus_probe_device+0x17f/0x1c0 drivers/base/bus.c:534
device_add+0x114b/0x1a70 drivers/base/core.c:3675
usb_new_device+0xd90/0x1a10 drivers/usb/core/hub.c:2651
hub_port_connect drivers/usb/core/hub.c:5521 [inline]
hub_port_connect_change drivers/usb/core/hub.c:5661 [inline]
port_event drivers/usb/core/hub.c:5821 [inline]
hub_event+0x2e58/0x4f40 drivers/usb/core/hub.c:5903
process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3229
process_scheduled_works kernel/workqueue.c:3310 [inline]
worker_thread+0x6c8/0xf00 kernel/workqueue.c:3391
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
INFO: task kworker/1:4:6535 blocked for more than 144 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/1:4 state:D stack:23808 pid:6535 tgid:6535 ppid:2 flags:0x00004000
Workqueue: pm pm_runtime_work
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
usb_kill_urb.part.0+0x1ca/0x250 drivers/usb/core/urb.c:713
usb_kill_urb+0x83/0xa0 drivers/usb/core/urb.c:702
usb_start_wait_urb+0x255/0x4c0 drivers/usb/core/message.c:65
usb_internal_control_msg drivers/usb/core/message.c:103 [inline]
usb_control_msg+0x327/0x4b0 drivers/usb/core/message.c:154
usb_enable_remote_wakeup drivers/usb/core/hub.c:3365 [inline]
usb_port_suspend+0x339/0xf10 drivers/usb/core/hub.c:3472
usb_generic_driver_suspend+0xeb/0x1d0 drivers/usb/core/generic.c:302
usb_suspend_device drivers/usb/core/driver.c:1272 [inline]
usb_suspend_both+0x66d/0x9c0 drivers/usb/core/driver.c:1443
usb_runtime_suspend+0x49/0x180 drivers/usb/core/driver.c:1968
__rpm_callback+0xc5/0x4c0 drivers/base/power/runtime.c:394
rpm_callback+0x192/0x1d0 drivers/base/power/runtime.c:448
rpm_suspend+0x2e7/0x1200 drivers/base/power/runtime.c:672
__pm_runtime_suspend+0xbc/0x160 drivers/base/power/runtime.c:1142
pm_runtime_autosuspend include/linux/pm_runtime.h:342 [inline]
usb_runtime_idle+0x4c/0x60 drivers/usb/core/driver.c:2005
rpm_idle+0x2f7/0x740 drivers/base/power/runtime.c:524
pm_runtime_work+0x120/0x150 drivers/base/power/runtime.c:970
process_one_work+0x9c5/0x1ba0 kernel/workqueue.c:3229
process_scheduled_works kernel/workqueue.c:3310 [inline]
worker_thread+0x6c8/0xf00 kernel/workqueue.c:3391
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
INFO: task syz.4.93:6688 blocked for more than 144 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz.4.93 state:D stack:27856 pid:6688 tgid:6688 ppid:4261 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
__mutex_lock_common kernel/locking/mutex.c:684 [inline]
__mutex_lock+0x5b8/0x9c0 kernel/locking/mutex.c:752
wdm_release+0x4b/0x440 drivers/usb/class/cdc-wdm.c:764
__fput+0x3f6/0xb60 fs/file_table.c:431
task_work_run+0x14e/0x250 kernel/task_work.c:228
resume_user_mode_work include/linux/resume_user_mode.h:50 [inline]
exit_to_user_mode_loop kernel/entry/common.c:114 [inline]
exit_to_user_mode_prepare include/linux/entry-common.h:328 [inline]
__syscall_exit_to_user_mode_work kernel/entry/common.c:207 [inline]
syscall_exit_to_user_mode+0x24e/0x260 kernel/entry/common.c:218
do_syscall_64+0xda/0x250 arch/x86/entry/common.c:89
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7ff46cc3dff9
RSP: 002b:00007fffd3498058 EFLAGS: 00000246 ORIG_RAX: 00000000000001b4
RAX: 0000000000000000 RBX: 000000000002232c RCX: 00007ff46cc3dff9
RDX: 0000000000000000 RSI: 000000000000001e RDI: 0000000000000003
RBP: 00007ff46cdf7a80 R08: 0000000000000001 R09: 00007fffd349834f
R10: 00007ff46cac0000 R11: 0000000000000246 R12: 00000000000226cf
R13: 00007fffd3498160 R14: 0000000000000032 R15: ffffffffffffffff
</TASK>
INFO: task syz.0.94:6692 blocked for more than 145 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz.0.94 state:D stack:27120 pid:6692 tgid:6691 ppid:4250 flags:0x00004004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
rpm_resume+0x5a8/0x1330 drivers/base/power/runtime.c:834
rpm_resume+0x750/0x1330 drivers/base/power/runtime.c:892
__pm_runtime_resume+0xb6/0x170 drivers/base/power/runtime.c:1172
pm_runtime_resume_and_get include/linux/pm_runtime.h:430 [inline]
usb_autopm_get_interface+0x20/0xe0 drivers/usb/core/driver.c:1833
wdm_open+0x24a/0x630 drivers/usb/class/cdc-wdm.c:730
usb_open+0x186/0x220 drivers/usb/core/file.c:47
chrdev_open+0x237/0x6a0 fs/char_dev.c:414
do_dentry_open+0x6cb/0x1390 fs/open.c:958
vfs_open+0x82/0x3f0 fs/open.c:1088
do_open fs/namei.c:3774 [inline]
path_openat+0x1e6a/0x2d60 fs/namei.c:3933
do_filp_open+0x1dc/0x430 fs/namei.c:3960
do_sys_openat2+0x17a/0x1e0 fs/open.c:1415
do_sys_open fs/open.c:1430 [inline]
__do_sys_openat fs/open.c:1446 [inline]
__se_sys_openat fs/open.c:1441 [inline]
__x64_sys_openat+0x175/0x210 fs/open.c:1441
do_syscall_x64 arch/x86/entry/common.c:52 [inline]
do_syscall_64+0xcd/0x250 arch/x86/entry/common.c:83
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7f264e65c990
RSP: 002b:00007f264e0d8b70 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007f264e65c990
RDX: 0000000000000002 RSI: 00007f264e0d8c10 RDI: 00000000ffffff9c
RBP: 00007f264e0d8c10 R08: 0000000000000000 R09: 00007f264e0d8987
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000000
R13: 0000000000000000 R14: 00007f264e815f80 R15: 00007ffe0b725c08
</TASK>
INFO: task syz.1.95:6694 blocked for more than 145 seconds.
Not tainted 6.12.0-rc3-syzkaller-dirty #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:syz.1.95 state:D stack:28432 pid:6694 tgid:6693 ppid:4257 flags:0x00000004
Call Trace:
<TASK>
context_switch kernel/sched/core.c:5322 [inline]
__schedule+0x105f/0x34b0 kernel/sched/core.c:6682
__schedule_loop kernel/sched/core.c:6759 [inline]
schedule+0xe7/0x350 kernel/sched/core.c:6774
schedule_preempt_disabled+0x13/0x30 kernel/sched/core.c:6831
rwsem_down_read_slowpath+0x61e/0xb20 kernel/locking/rwsem.c:1084
__down_read_common kernel/locking/rwsem.c:1248 [inline]
__down_read kernel/locking/rwsem.c:1261 [inline]
down_read+0x124/0x330 kernel/locking/rwsem.c:1526
usb_open+0x23/0x220 drivers/usb/core/file.c:38
chrdev_open+0x237/0x6a0 fs/char_dev.c:414
do_dentry_open+0x6cb/0x1390 fs/open.c:958
vfs_open+0x82/0x3f0 fs/open.c:1088
do_open fs/namei.c:3774 [inline]
path_openat+0x1e6a/0x2d60 fs/namei.c:3933
do_filp_open+0x1dc/0x430 fs/namei.c:3960
do_sys_openat2+0x17a/0x1e0 fs/open.c:1415
do_sys_open fs/open.c:1430 [inline]
__do_sys_openat fs/open.c:1446 [inline]
__se_sys_openat fs/open.c:1441 [inline]
__x64_sys_openat+0x175/0x210 fs/open.c:1441
do_syscall_x64 arch/x86/entry/common.c:52 [inline]
do_syscall_64+0xcd/0x250 arch/x86/entry/common.c:83
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7fbe0b20c990
RSP: 002b:00007fbe0ac8eb70 EFLAGS: 00000293 ORIG_RAX: 0000000000000101
RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007fbe0b20c990
RDX: 0000000000000002 RSI: 00007fbe0ac8ec10 RDI: 00000000ffffff9c
RBP: 00007fbe0ac8ec10 R08: 0000000000000000 R09: 00007fbe0ac8e987
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000000
R13: 0000000000000000 R14: 00007fbe0b3c5f80 R15: 00007ffe707cfc08
</TASK>
Showing all locks held in the system:
6 locks held by kworker/1:0/24:
#0: ffff888106299d48 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc9000019fd80 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
#2: ffff888109785190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#2: ffff888109785190 (&dev->mutex){....}-{3:3}, at: hub_event+0x1be/0x4f40 drivers/usb/core/hub.c:5849
#3: ffff888105ecf190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#3: ffff888105ecf190 (&dev->mutex){....}-{3:3}, at: usb_disconnect+0x10a/0x920 drivers/usb/core/hub.c:2295
#4: ffff888105ede160 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#4: ffff888105ede160 (&dev->mutex){....}-{3:3}, at: __device_driver_lock drivers/base/dd.c:1095 [inline]
#4: ffff888105ede160 (&dev->mutex){....}-{3:3}, at: device_release_driver_internal+0xa4/0x610 drivers/base/dd.c:1293
#5: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_deregister_dev+0x7c/0x1e0 drivers/usb/core/file.c:186
1 lock held by khungtaskd/30:
#0: ffffffff88ebb100 (rcu_read_lock){....}-{1:2}, at: rcu_lock_acquire include/linux/rcupdate.h:337 [inline]
#0: ffffffff88ebb100 (rcu_read_lock){....}-{1:2}, at: rcu_read_lock include/linux/rcupdate.h:849 [inline]
#0: ffffffff88ebb100 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x7f/0x390 kernel/locking/lockdep.c:6720
6 locks held by kworker/1:1/36:
#0: ffff888106299d48 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc90000267d80 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
#2: ffff8881097a5190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#2: ffff8881097a5190 (&dev->mutex){....}-{3:3}, at: hub_event+0x1be/0x4f40 drivers/usb/core/hub.c:5849
#3: ffff88812e7bc190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#3: ffff88812e7bc190 (&dev->mutex){....}-{3:3}, at: usb_disconnect+0x10a/0x920 drivers/usb/core/hub.c:2295
#4: ffff888131992160 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#4: ffff888131992160 (&dev->mutex){....}-{3:3}, at: __device_driver_lock drivers/base/dd.c:1095 [inline]
#4: ffff888131992160 (&dev->mutex){....}-{3:3}, at: device_release_driver_internal+0xa4/0x610 drivers/base/dd.c:1293
#5: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_deregister_dev+0x7c/0x1e0 drivers/usb/core/file.c:186
2 locks held by kworker/u8:3/46:
#0: ffff888100089148 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc90000517d80 ((work_completion)(&sub_info->work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
2 locks held by getty/2606:
#0: ffff88810f73f0a0 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x24/0x80 drivers/tty/tty_ldisc.c:243
#1: ffffc900000432f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0xfba/0x1480 drivers/tty/n_tty.c:2211
2 locks held by kworker/u8:7/4832:
#0: ffff888100089148 ((wq_completion)events_unbound){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc90002a3fd80 ((work_completion)(&sub_info->work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
6 locks held by kworker/1:3/6534:
#0: ffff888106299d48 ((wq_completion)usb_hub_wq){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc90001bdfd80 ((work_completion)(&hub->events)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
#2: ffff888109735190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#2: ffff888109735190 (&dev->mutex){....}-{3:3}, at: hub_event+0x1be/0x4f40 drivers/usb/core/hub.c:5849
#3: ffff888100fc7190 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#3: ffff888100fc7190 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7f/0x4b0 drivers/base/dd.c:1005
#4: ffff888100fc1160 (&dev->mutex){....}-{3:3}, at: device_lock include/linux/device.h:1014 [inline]
#4: ffff888100fc1160 (&dev->mutex){....}-{3:3}, at: __device_attach+0x7f/0x4b0 drivers/base/dd.c:1005
#5: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_register_dev+0x11c/0x550 drivers/usb/core/file.c:134
3 locks held by kworker/1:4/6535:
#0: ffff8881026e8548 ((wq_completion)pm){+.+.}-{0:0}, at: process_one_work+0x129b/0x1ba0 kernel/workqueue.c:3204
#1: ffffc90001bcfd80 ((work_completion)(&dev->power.work)){+.+.}-{0:0}, at: process_one_work+0x921/0x1ba0 kernel/workqueue.c:3205
#2: ffff888109b38508 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_lock_port drivers/usb/core/hub.c:3206 [inline]
#2: ffff888109b38508 (&port_dev->status_lock){+.+.}-{3:3}, at: usb_port_suspend+0x255/0xf10 drivers/usb/core/hub.c:3463
1 lock held by syz.4.93/6688:
#0: ffffffff89a968c8 (wdm_mutex){+.+.}-{3:3}, at: wdm_release+0x4b/0x440 drivers/usb/class/cdc-wdm.c:764
2 locks held by syz.0.94/6692:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
#1: ffffffff89a968c8 (wdm_mutex){+.+.}-{3:3}, at: wdm_open+0x5d/0x630 drivers/usb/class/cdc-wdm.c:715
1 lock held by syz.1.95/6694:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.4.104/8014:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.102/8025:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.106/8099:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.4.125/9473:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.123/9479:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.127/9504:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.146/10885:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.4.148/10909:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.147/10912:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.168/12230:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.4.169/12276:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.167/12316:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.188/13565:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.4.190/13705:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.0.191/13720:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
1 lock held by syz.1.209/14857:
#0: ffffffff899dae90 (minor_rwsem){++++}-{3:3}, at: usb_open+0x23/0x220 drivers/usb/core/file.c:38
=============================================
NMI backtrace for cpu 1
CPU: 1 UID: 0 PID: 30 Comm: khungtaskd Not tainted 6.12.0-rc3-syzkaller-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 09/13/2024
Call Trace:
<TASK>
__dump_stack lib/dump_stack.c:94 [inline]
dump_stack_lvl+0x116/0x1f0 lib/dump_stack.c:120
nmi_cpu_backtrace+0x27b/0x390 lib/nmi_backtrace.c:113
nmi_trigger_cpumask_backtrace+0x29c/0x300 lib/nmi_backtrace.c:62
trigger_all_cpu_backtrace include/linux/nmi.h:162 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:223 [inline]
watchdog+0xf0c/0x1240 kernel/hung_task.c:379
kthread+0x2c1/0x3a0 kernel/kthread.c:389
ret_from_fork+0x45/0x80 arch/x86/kernel/process.c:147
ret_from_fork_asm+0x1a/0x30 arch/x86/entry/entry_64.S:244
</TASK>
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 UID: 0 PID: 14907 Comm: modprobe Not tainted 6.12.0-rc3-syzkaller-dirty #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 09/13/2024
RIP: 0010:stack_access_ok+0xc/0x200 arch/x86/kernel/unwind_orc.c:389
Code: ff e9 b0 fe ff ff 0f 1f 84 00 00 00 00 00 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 48 b8 00 00 00 00 00 fc ff df 41 57 <41> 56 4c 8d 77 08 41 55 41 54 49 89 d4 4c 89 f2 55 48 c1 ea 03 48
RSP: 0018:ffffc9000564e6e8 EFLAGS: 00000287
RAX: dffffc0000000000 RBX: 0000000000000001 RCX: ffffffff8aba1902
RDX: 0000000000000008 RSI: ffffc9000564fd60 RDI: ffffc9000564e768
RBP: ffffc9000564fd60 R08: 0000000000000001 R09: ffffffff8aba1906
R10: ffffc9000564e768 R11: 0000000000009eb0 R12: ffffc9000564e7b8
R13: ffffc9000564e768 R14: ffffc9000564fd90 R15: ffffc9000564fd88
FS: 0000000000000000(0000) GS:ffff8881f5800000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f40557b3020 CR3: 00000001171fc000 CR4: 00000000003506f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
<NMI>
</NMI>
<TASK>
deref_stack_reg arch/x86/kernel/unwind_orc.c:403 [inline]
unwind_next_frame+0x15dd/0x20c0 arch/x86/kernel/unwind_orc.c:648
arch_stack_walk+0x95/0x100 arch/x86/kernel/stacktrace.c:25
stack_trace_save+0x95/0xd0 kernel/stacktrace.c:122
kasan_save_stack+0x33/0x60 mm/kasan/common.c:47
kasan_save_track+0x14/0x30 mm/kasan/common.c:68
unpoison_slab_object mm/kasan/common.c:319 [inline]
__kasan_slab_alloc+0x6e/0x70 mm/kasan/common.c:345
kasan_slab_alloc include/linux/kasan.h:247 [inline]
slab_post_alloc_hook mm/slub.c:4085 [inline]
slab_alloc_node mm/slub.c:4134 [inline]
kmem_cache_alloc_noprof+0x11c/0x2b0 mm/slub.c:4141
fill_pool+0x11c/0x5c0 lib/debugobjects.c:168
debug_objects_fill_pool lib/debugobjects.c:615 [inline]
debug_object_activate+0x151/0x540 lib/debugobjects.c:704
debug_rcu_head_queue kernel/rcu/rcu.h:224 [inline]
__call_rcu_common.constprop.0+0x2c/0x7a0 kernel/rcu/tree.c:3071
mas_free lib/maple_tree.c:1303 [inline]
mas_topiary_replace+0x2a84/0x3620 lib/maple_tree.c:2586
mas_wmb_replace lib/maple_tree.c:2643 [inline]
mas_split+0x99e/0x10b0 lib/maple_tree.c:3373
mas_commit_b_node.isra.0+0x76/0xb0 lib/maple_tree.c:3393
mas_wr_bnode+0x156/0x1e0 lib/maple_tree.c:4044
mas_wr_store_entry+0x9c7/0x30e0 lib/maple_tree.c:4085
mas_store_prealloc+0x77e/0x1690 lib/maple_tree.c:5520
mmap_region+0x16b5/0x2900 mm/mmap.c:1513
do_mmap+0xc00/0xfc0 mm/mmap.c:496
vm_mmap_pgoff+0x1ba/0x350 mm/util.c:588
ksys_mmap_pgoff+0x7d/0x5c0 mm/mmap.c:542
__do_sys_mmap arch/x86/kernel/sys_x86_64.c:86 [inline]
__se_sys_mmap arch/x86/kernel/sys_x86_64.c:79 [inline]
__x64_sys_mmap+0x125/0x190 arch/x86/kernel/sys_x86_64.c:79
do_syscall_x64 arch/x86/entry/common.c:52 [inline]
do_syscall_64+0xcd/0x250 arch/x86/entry/common.c:83
entry_SYSCALL_64_after_hwframe+0x77/0x7f
RIP: 0033:0x7f40557d0b74
Code: 63 08 44 89 e8 5b 41 5c 41 5d c3 41 89 ca 41 f7 c1 ff 0f 00 00 74 0c c7 05 f5 46 01 00 16 00 00 00 eb 17 b8 09 00 00 00 0f 05 <48> 3d 00 f0 ff ff 76 0c f7 d8 89 05 dc 46 01 00 48 83 c8 ff c3 0f
RSP: 002b:00007ffeffcbd918 EFLAGS: 00000246 ORIG_RAX: 0000000000000009
RAX: ffffffffffffffda RBX: 00000000000000a0 RCX: 00007f40557d0b74
RDX: 0000000000000003 RSI: 0000000000002000 RDI: 0000000000000000
RBP: 0000000000002000 R08: 00000000ffffffff R09: 0000000000000000
R10: 0000000000000022 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000000002 R14: 0000000000000000 R15: 00007f40557e52a0
</TASK>
Tested on:
commit: 8e929cb5 Linux 6.12-rc3
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git v6.12-rc3
console output: https://syzkaller.appspot.com/x/log.txt?x=106f5887980000
kernel config: https://syzkaller.appspot.com/x/.config?x=9878fe11046ea2c6
dashboard link: https://syzkaller.appspot.com/bug?extid=f342ea16c9d06d80b585
compiler: gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40
patch: https://syzkaller.appspot.com/x/patch.diff?x=10375887980000
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in usb_port_suspend
2024-10-16 2:34 ` syzbot
@ 2024-10-16 14:40 ` Alan Stern
2024-10-16 15:02 ` syzbot
0 siblings, 1 reply; 12+ messages in thread
From: Alan Stern @ 2024-10-16 14:40 UTC (permalink / raw)
To: syzbot; +Cc: linux-kernel, linux-usb, syzkaller-bugs
On Tue, Oct 15, 2024 at 07:34:02PM -0700, syzbot wrote:
> Hello,
>
> syzbot has tested the proposed patch but the reproducer is still triggering an issue:
Okay, the information in the console log confirms it. The issue is
definitely caused by the use of hrtimer_active() in dummy_urb_enqueue().
This patch should be the correct solution.
Alan Stern
#syz test: https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git
v6.12-rc3
---
drivers/usb/gadget/udc/dummy_hcd.c | 20 +++++++++++++++-----
1 file changed, 15 insertions(+), 5 deletions(-)
Index: usb-devel/drivers/usb/gadget/udc/dummy_hcd.c
===================================================================
--- usb-devel.orig/drivers/usb/gadget/udc/dummy_hcd.c
+++ usb-devel/drivers/usb/gadget/udc/dummy_hcd.c
@@ -254,6 +254,7 @@ struct dummy_hcd {
u32 stream_en_ep;
u8 num_stream[30 / 2];
+ unsigned timer_pending:1;
unsigned active:1;
unsigned old_active:1;
unsigned resuming:1;
@@ -1303,9 +1304,11 @@ static int dummy_urb_enqueue(
urb->error_count = 1; /* mark as a new urb */
/* kick the scheduler, it'll do the rest */
- if (!hrtimer_active(&dum_hcd->timer))
+ if (!dum_hcd->timer_pending) {
+ dum_hcd->timer_pending = 1;
hrtimer_start(&dum_hcd->timer, ns_to_ktime(DUMMY_TIMER_INT_NSECS),
HRTIMER_MODE_REL_SOFT);
+ }
done:
spin_unlock_irqrestore(&dum_hcd->dum->lock, flags);
@@ -1324,9 +1327,10 @@ static int dummy_urb_dequeue(struct usb_
spin_lock_irqsave(&dum_hcd->dum->lock, flags);
rc = usb_hcd_check_unlink_urb(hcd, urb, status);
- if (!rc && dum_hcd->rh_state != DUMMY_RH_RUNNING &&
- !list_empty(&dum_hcd->urbp_list))
+ if (rc == 0 && !dum_hcd->timer_pending) {
+ dum_hcd->timer_pending = 1;
hrtimer_start(&dum_hcd->timer, ns_to_ktime(0), HRTIMER_MODE_REL_SOFT);
+ }
spin_unlock_irqrestore(&dum_hcd->dum->lock, flags);
return rc;
@@ -1813,6 +1817,7 @@ static enum hrtimer_restart dummy_timer(
/* look at each urb queued by the host side driver */
spin_lock_irqsave(&dum->lock, flags);
+ dum_hcd->timer_pending = 0;
if (!dum_hcd->udev) {
dev_err(dummy_dev(dum_hcd),
@@ -1994,8 +1999,10 @@ return_urb:
if (list_empty(&dum_hcd->urbp_list)) {
usb_put_dev(dum_hcd->udev);
dum_hcd->udev = NULL;
- } else if (dum_hcd->rh_state == DUMMY_RH_RUNNING) {
+ } else if (!dum_hcd->timer_pending &&
+ dum_hcd->rh_state == DUMMY_RH_RUNNING) {
/* want a 1 msec delay here */
+ dum_hcd->timer_pending = 1;
hrtimer_start(&dum_hcd->timer, ns_to_ktime(DUMMY_TIMER_INT_NSECS),
HRTIMER_MODE_REL_SOFT);
}
@@ -2390,8 +2397,10 @@ static int dummy_bus_resume(struct usb_h
} else {
dum_hcd->rh_state = DUMMY_RH_RUNNING;
set_link_state(dum_hcd);
- if (!list_empty(&dum_hcd->urbp_list))
+ if (!list_empty(&dum_hcd->urbp_list)) {
+ dum_hcd->timer_pending = 1;
hrtimer_start(&dum_hcd->timer, ns_to_ktime(0), HRTIMER_MODE_REL_SOFT);
+ }
hcd->state = HC_STATE_RUNNING;
}
spin_unlock_irq(&dum_hcd->dum->lock);
@@ -2522,6 +2531,7 @@ static void dummy_stop(struct usb_hcd *h
struct dummy_hcd *dum_hcd = hcd_to_dummy_hcd(hcd);
hrtimer_cancel(&dum_hcd->timer);
+ dum_hcd->timer_pending = 0;
device_remove_file(dummy_dev(dum_hcd), &dev_attr_urbs);
dev_info(dummy_dev(dum_hcd), "stopped\n");
}
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [syzbot] [usb?] INFO: task hung in usb_port_suspend
2024-10-16 14:40 ` Alan Stern
@ 2024-10-16 15:02 ` syzbot
2024-10-16 15:44 ` [PATCH] USB: gadget: dummy-hcd: Fix "task hung" problem Alan Stern
0 siblings, 1 reply; 12+ messages in thread
From: syzbot @ 2024-10-16 15:02 UTC (permalink / raw)
To: linux-kernel, linux-usb, stern, syzkaller-bugs
Hello,
syzbot has tested the proposed patch and the reproducer did not trigger any issue:
Reported-by: syzbot+f342ea16c9d06d80b585@syzkaller.appspotmail.com
Tested-by: syzbot+f342ea16c9d06d80b585@syzkaller.appspotmail.com
Tested on:
commit: 8e929cb5 Linux 6.12-rc3
git tree: https://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb.git v6.12-rc3
console output: https://syzkaller.appspot.com/x/log.txt?x=10a8545f980000
kernel config: https://syzkaller.appspot.com/x/.config?x=9878fe11046ea2c6
dashboard link: https://syzkaller.appspot.com/bug?extid=f342ea16c9d06d80b585
compiler: gcc (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40
patch: https://syzkaller.appspot.com/x/patch.diff?x=12d0545f980000
Note: testing is done by a robot and is best-effort only.
^ permalink raw reply [flat|nested] 12+ messages in thread
* [PATCH] USB: gadget: dummy-hcd: Fix "task hung" problem
2024-10-16 15:02 ` syzbot
@ 2024-10-16 15:44 ` Alan Stern
2024-10-17 6:43 ` Greg KH
0 siblings, 1 reply; 12+ messages in thread
From: Alan Stern @ 2024-10-16 15:44 UTC (permalink / raw)
To: Greg KH; +Cc: Marcello Sylvester Bauer, USB mailing list, syzbot,
syzkaller-bugs
The syzbot fuzzer has been encountering "task hung" problems ever
since the dummy-hcd driver was changed to use hrtimers instead of
regular timers. It turns out that the problems are caused by a subtle
difference between the timer_pending() and hrtimer_active() APIs.
The changeover blindly replaced the first by the second. However,
timer_pending() returns True when the timer is queued but not when its
callback is running, whereas hrtimer_active() returns True when the
hrtimer is queued _or_ its callback is running. This difference
occasionally caused dummy_urb_enqueue() to think that the callback
routine had not yet started when in fact it was almost finished. As a
result the hrtimer was not restarted, which made it impossible for the
driver to dequeue later the URB that was just enqueued. This caused
usb_kill_urb() to hang, and things got worse from there.
Since hrtimers have no API for telling when they are queued and the
callback isn't running, the driver must keep track of this for itself.
That's what this patch does, adding a new "timer_pending" flag and
setting or clearing it at the appropriate times.
Reported-by: syzbot+f342ea16c9d06d80b585@syzkaller.appspotmail.com
Closes: https://lore.kernel.org/linux-usb/6709234e.050a0220.3e960.0011.GAE@google.com/
Tested-by: syzbot+f342ea16c9d06d80b585@syzkaller.appspotmail.com
Signed-off-by: Alan Stern <stern@rowland.harvard.edu>
Fixes: a7f3813e589f ("usb: gadget: dummy_hcd: Switch to hrtimer transfer scheduler")
Cc: Marcello Sylvester Bauer <sylv@sylv.io>
Cc: stable@vger.kernel.org
---
I expect this will fix a lot of the bugs that syzbot has found in the
last few months.
drivers/usb/gadget/udc/dummy_hcd.c | 20 +++++++++++++++-----
1 file changed, 15 insertions(+), 5 deletions(-)
Index: usb-devel/drivers/usb/gadget/udc/dummy_hcd.c
===================================================================
--- usb-devel.orig/drivers/usb/gadget/udc/dummy_hcd.c
+++ usb-devel/drivers/usb/gadget/udc/dummy_hcd.c
@@ -254,6 +254,7 @@ struct dummy_hcd {
u32 stream_en_ep;
u8 num_stream[30 / 2];
+ unsigned timer_pending:1;
unsigned active:1;
unsigned old_active:1;
unsigned resuming:1;
@@ -1303,9 +1304,11 @@ static int dummy_urb_enqueue(
urb->error_count = 1; /* mark as a new urb */
/* kick the scheduler, it'll do the rest */
- if (!hrtimer_active(&dum_hcd->timer))
+ if (!dum_hcd->timer_pending) {
+ dum_hcd->timer_pending = 1;
hrtimer_start(&dum_hcd->timer, ns_to_ktime(DUMMY_TIMER_INT_NSECS),
HRTIMER_MODE_REL_SOFT);
+ }
done:
spin_unlock_irqrestore(&dum_hcd->dum->lock, flags);
@@ -1324,9 +1327,10 @@ static int dummy_urb_dequeue(struct usb_
spin_lock_irqsave(&dum_hcd->dum->lock, flags);
rc = usb_hcd_check_unlink_urb(hcd, urb, status);
- if (!rc && dum_hcd->rh_state != DUMMY_RH_RUNNING &&
- !list_empty(&dum_hcd->urbp_list))
+ if (rc == 0 && !dum_hcd->timer_pending) {
+ dum_hcd->timer_pending = 1;
hrtimer_start(&dum_hcd->timer, ns_to_ktime(0), HRTIMER_MODE_REL_SOFT);
+ }
spin_unlock_irqrestore(&dum_hcd->dum->lock, flags);
return rc;
@@ -1813,6 +1817,7 @@ static enum hrtimer_restart dummy_timer(
/* look at each urb queued by the host side driver */
spin_lock_irqsave(&dum->lock, flags);
+ dum_hcd->timer_pending = 0;
if (!dum_hcd->udev) {
dev_err(dummy_dev(dum_hcd),
@@ -1994,8 +1999,10 @@ return_urb:
if (list_empty(&dum_hcd->urbp_list)) {
usb_put_dev(dum_hcd->udev);
dum_hcd->udev = NULL;
- } else if (dum_hcd->rh_state == DUMMY_RH_RUNNING) {
+ } else if (!dum_hcd->timer_pending &&
+ dum_hcd->rh_state == DUMMY_RH_RUNNING) {
/* want a 1 msec delay here */
+ dum_hcd->timer_pending = 1;
hrtimer_start(&dum_hcd->timer, ns_to_ktime(DUMMY_TIMER_INT_NSECS),
HRTIMER_MODE_REL_SOFT);
}
@@ -2390,8 +2397,10 @@ static int dummy_bus_resume(struct usb_h
} else {
dum_hcd->rh_state = DUMMY_RH_RUNNING;
set_link_state(dum_hcd);
- if (!list_empty(&dum_hcd->urbp_list))
+ if (!list_empty(&dum_hcd->urbp_list)) {
+ dum_hcd->timer_pending = 1;
hrtimer_start(&dum_hcd->timer, ns_to_ktime(0), HRTIMER_MODE_REL_SOFT);
+ }
hcd->state = HC_STATE_RUNNING;
}
spin_unlock_irq(&dum_hcd->dum->lock);
@@ -2522,6 +2531,7 @@ static void dummy_stop(struct usb_hcd *h
struct dummy_hcd *dum_hcd = hcd_to_dummy_hcd(hcd);
hrtimer_cancel(&dum_hcd->timer);
+ dum_hcd->timer_pending = 0;
device_remove_file(dummy_dev(dum_hcd), &dev_attr_urbs);
dev_info(dummy_dev(dum_hcd), "stopped\n");
}
^ permalink raw reply [flat|nested] 12+ messages in thread
* Re: [PATCH] USB: gadget: dummy-hcd: Fix "task hung" problem
2024-10-16 15:44 ` [PATCH] USB: gadget: dummy-hcd: Fix "task hung" problem Alan Stern
@ 2024-10-17 6:43 ` Greg KH
0 siblings, 0 replies; 12+ messages in thread
From: Greg KH @ 2024-10-17 6:43 UTC (permalink / raw)
To: Alan Stern
Cc: Marcello Sylvester Bauer, USB mailing list, syzbot,
syzkaller-bugs
On Wed, Oct 16, 2024 at 11:44:45AM -0400, Alan Stern wrote:
> The syzbot fuzzer has been encountering "task hung" problems ever
> since the dummy-hcd driver was changed to use hrtimers instead of
> regular timers. It turns out that the problems are caused by a subtle
> difference between the timer_pending() and hrtimer_active() APIs.
>
> The changeover blindly replaced the first by the second. However,
> timer_pending() returns True when the timer is queued but not when its
> callback is running, whereas hrtimer_active() returns True when the
> hrtimer is queued _or_ its callback is running. This difference
> occasionally caused dummy_urb_enqueue() to think that the callback
> routine had not yet started when in fact it was almost finished. As a
> result the hrtimer was not restarted, which made it impossible for the
> driver to dequeue later the URB that was just enqueued. This caused
> usb_kill_urb() to hang, and things got worse from there.
>
> Since hrtimers have no API for telling when they are queued and the
> callback isn't running, the driver must keep track of this for itself.
> That's what this patch does, adding a new "timer_pending" flag and
> setting or clearing it at the appropriate times.
>
> Reported-by: syzbot+f342ea16c9d06d80b585@syzkaller.appspotmail.com
> Closes: https://lore.kernel.org/linux-usb/6709234e.050a0220.3e960.0011.GAE@google.com/
> Tested-by: syzbot+f342ea16c9d06d80b585@syzkaller.appspotmail.com
> Signed-off-by: Alan Stern <stern@rowland.harvard.edu>
> Fixes: a7f3813e589f ("usb: gadget: dummy_hcd: Switch to hrtimer transfer scheduler")
> Cc: Marcello Sylvester Bauer <sylv@sylv.io>
> Cc: stable@vger.kernel.org
>
> ---
>
> I expect this will fix a lot of the bugs that syzbot has found in the
> last few months.
Nice! Thanks for tracking this down and fixing it.
greg k-h
^ permalink raw reply [flat|nested] 12+ messages in thread
end of thread, other threads:[~2024-10-17 6:43 UTC | newest]
Thread overview: 12+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
[not found] <6f7bdad6-d266-45c6-ad2d-2d0b1c33e4a6@rowland.harvard.edu>
[not found] ` <670d65fa.050a0220.3e960.00c1.GAE@google.com>
2024-10-15 14:22 ` [syzbot] [usb?] INFO: task hung in usb_port_suspend Alan Stern
2024-10-15 14:54 ` syzbot
2024-10-15 19:23 ` Alan Stern
2024-10-15 19:54 ` syzbot
2024-10-16 0:54 ` Alan Stern
2024-10-16 1:54 ` syzbot
2024-10-16 2:11 ` Alan Stern
2024-10-16 2:34 ` syzbot
2024-10-16 14:40 ` Alan Stern
2024-10-16 15:02 ` syzbot
2024-10-16 15:44 ` [PATCH] USB: gadget: dummy-hcd: Fix "task hung" problem Alan Stern
2024-10-17 6:43 ` Greg KH
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox