* 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