On 11/3/23 8:04 PM, Alan Stern wrote: > On Fri, Nov 03, 2023 at 07:03:20PM +0500, Muhammad Usama Anjum wrote: >> On 6/10/23 12:25 AM, syzbot wrote: >>> syzbot has found a reproducer for the following issue on: >>> >>> HEAD commit: 33f2b5785a2b Merge tag 'drm-fixes-2023-06-09' of git://ano.. >>> git tree: upstream >>> console+strace: https://syzkaller.appspot.com/x/log.txt?x=1206f143280000 >>> kernel config: https://syzkaller.appspot.com/x/.config?x=3c980bfe8b399968 >>> dashboard link: https://syzkaller.appspot.com/bug?extid=b6f11035e572f08bc20f >>> compiler: gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2 >>> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=1676f51b280000 >>> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=129632fd280000 >>> >>> Downloadable assets: >>> disk image: https://storage.googleapis.com/syzbot-assets/a817d99af39d/disk-33f2b578.raw.xz >>> vmlinux: https://storage.googleapis.com/syzbot-assets/8916e1d053fc/vmlinux-33f2b578.xz >>> kernel image: https://storage.googleapis.com/syzbot-assets/e53956f3cfd4/bzImage-33f2b578.xz >>> >>> IMPORTANT: if you fix the issue, please add the following tag to the commit: >>> Reported-by: syzbot+b6f11035e572f08bc20f@xxxxxxxxxxxxxxxxxxxxxxxxx >>> >>> INFO: task kworker/0:2:901 blocked for more than 143 seconds. >>> Not tainted 6.4.0-rc5-syzkaller-00178-g33f2b5785a2b #0 >>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. >>> task:kworker/0:2 state:D stack:26800 pid:901 ppid:2 flags:0x00004000 >>> Workqueue: usb_hub_wq hub_event >>> Call Trace: >>> <TASK> >>> context_switch kernel/sched/core.c:5343 [inline] >>> __schedule+0xc9a/0x5880 kernel/sched/core.c:6669 >>> schedule+0xde/0x1a0 kernel/sched/core.c:6745 >>> usb_kill_urb.part.0+0x19a/0x220 drivers/usb/core/urb.c:728 >>> usb_kill_urb+0x83/0xa0 drivers/usb/core/urb.c:717 >>> usb_start_wait_urb+0x24a/0x4b0 drivers/usb/core/message.c:64 >>> usb_internal_control_msg drivers/usb/core/message.c:102 [inline] >>> usb_control_msg+0x320/0x4a0 drivers/usb/core/message.c:153 >>> hub_port_init+0x14f3/0x3900 drivers/usb/core/hub.c:4874 >>> hub_port_connect drivers/usb/core/hub.c:5336 [inline] >>> hub_port_connect_change drivers/usb/core/hub.c:5551 [inline] >>> port_event drivers/usb/core/hub.c:5711 [inline] >>> hub_event+0x2b89/0x4e40 drivers/usb/core/hub.c:5793 >>> process_one_work+0x99a/0x15e0 kernel/workqueue.c:2405 >>> worker_thread+0x67d/0x10c0 kernel/workqueue.c:2552 >>> kthread+0x344/0x440 kernel/kthread.c:379 >>> ret_from_fork+0x1f/0x30 arch/x86/entry/entry_64.S:308 >>> </TASK> >>> INFO: task syz-executor104:5004 blocked for more than 143 seconds. >> This is being reproduced on linux-next. The USB IP is being fuzzed. I'd >> modified the reproducer to try to understand the issue. The execution of >> application creates kworkers (can be found in hub->events). One of the usb >> hub kworker gets stuck because of wrong use_count. I don't know USB side of >> logic. But a worker shouldn't go to sleep indefinitely. > > I doubt that the problem is a wrong value for use_count. More likely > it's a bug in the usbip driver. > >> My debug logs are as following which can help an expert USB developer to >> pin point the problem: >> >> [ 118.904272][ T9] usb_submit_urb urb->use_count: 0 >> [ 118.904942][ T9] usb_hcd_submit_urb urb->use_count: 1 >> [ 118.905715][ T9] usb_submit_urb urb->use_count: 1 >> [ 118.906428][ T9] usb_start_wait_urb urb->use_count: 1 >> [ 123.938978][ T9] usb_kill_urb use_count: 1 > > These don't mean much because they don't give the address of urb, so > we don't know if the various lines all refer to the same URB or to > different ones. I've confirmed locally again that the logs belong to same urb. This kworker gets stuck: [ 131.064283] usb_control_msg [ 131.065326] usb_internal_control_msg, urb: FFFF88814CC2AE00 urb->use_count: 0 [ 131.066320] usb_start_wait_urb urb: FFFF88814CC2AE00 urb->use_count: 0 [ 131.069988] usb_submit_urb urb: FFFF88814CC2AE00 urb->use_count: 0 [ 131.070881] usb_hcd_submit_urb urb: FFFF88814CC2AE00 urb->use_count 1 [ 131.072268] usb_submit_urb 0 urb: FFFF88814CC2AE00 urb->use_count: 1 [ 131.073186] usb_start_wait_urb urb: FFFF88814CC2AE00 urb->use_count: 1 [ 136.151750] usb_start_wait_urb wait_for_completion [ 136.153286] usb_kill_urb might_sleep [ 136.153859] vhci_hcd: vhci_urb_dequeue:875: vhci_urb_dequeue [ 136.154853] vhci_hcd: vhci_urb_dequeue:952: vhci_urb_dequeue return [ 136.155773] usb_kill_urb usb_hcd_unlink_urb use_count: 1 [ 285.831355] INFO: task kworker/0:4:1586 blocked for more than 143 seconds. > >> At this point, wait is being done on usb_kill_urb_queue as use_count isn't >> zero and no event on usb_kill_urb_queue is received. > > Right. The usbip driver is supposed to terminate the URB in a timely > fashion (because usb_kill_urb() calls usb_hcd_unlink_urb()), but it > isn't doing so. When the URB completes, the event will occur. > >> The comment for usb_kill_urb is: >>> * This routine may not be used in an interrupt context (such as a bottom >>> * half or a completion handler), or when holding a spinlock, or in other >>> * situations where the caller can't schedule(). >> >> But several locks are held by this kworker and sleeps indefinitely. > > No spinlocks are held, only mutexes. The difference is that a task is > allowed to sleep while holding a mutex, but it's not allowed to sleep > while holding a spinlock. > > If you want to fix this problem (and probably a bunch of other ones in > syzbot's list of pending bugs), figure out what's wrong with the > ->urb_dequeue() callback routine in the usbip driver and fix it. I'm looking at it, haven't found anything yet. > > Alan Stern -- BR, Muhammad Usama Anjum
