Re: [syzbot] [usb?] INFO: rcu detected stall in raw_ioctl

[Alan Stern]

On Mon, Jun 10, 2024 at 10:58:02AM -0700, syzbot wrote:
> Hello,
> 
> syzbot has tested the proposed patch but the reproducer is still triggering an issue:
> BUG: soft lockup in raw_ioctl
> 
> dummy_hcd dummy_hcd.0: urbp 000000006bf6c1dd 40409880 next_frame 0000000000000000
> cdc_wdm 1-1:1.0: nonzero urb status received: -71
> cdc_wdm 1-1:1.0: wdm_int_callback - 0 bytes
> dummy_hcd dummy_hcd.0: urbp 000000003f481f40 40409880 next_frame 000000003f481f40
> watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [syz-executor415:10796]

The full console log shows that the cdc-wm and dummy-hcd loop uses less 
than 60 microseconds out of every 2400 or so.  That's not enough to 
cause this.  Something else must be going on.

> Call trace:
>  __daif_local_irq_restore arch/arm64/include/asm/irqflags.h:175 [inline]
>  arch_local_irq_restore arch/arm64/include/asm/irqflags.h:195 [inline]
>  console_emit_next_record kernel/printk/printk.c:2935 [inline]
>  console_flush_all+0x67c/0xb74 kernel/printk/printk.c:2994
>  console_unlock+0xec/0x3d4 kernel/printk/printk.c:3063
>  vprintk_emit+0x1ec/0x350 kernel/printk/printk.c:2345
>  vprintk_default+0xa0/0xe4 kernel/printk/printk.c:2360
>  vprintk+0x200/0x2d4 kernel/printk/printk_safe.c:45
>  _printk+0xdc/0x128 kernel/printk/printk.c:2370
>  usb_gadget_register_driver_owner+0x1f0/0x224 drivers/usb/gadget/udc/core.c:1711

Is this a coincidence?  If CPU #0 is getting stuck, why here?  Line 1711 
is a mutex_unlock() call; it shouldn't take long.  This doesn't seem to 
make sense.

Let's try to find out what the CPU is really doing when this happens.

Alan Stern

#syz test: git://git.kernel.org/pub/scm/linux/kernel/git/arm64/linux.git 8867bbd4a056

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
@@ -1826,6 +1826,7 @@ static void dummy_timer(struct timer_lis
 			break;
 		dum->ep[i].already_seen = 0;
 	}
+	dev_info(dummy_dev(dum_hcd), "Timer handler\n");
 
 restart:
 	list_for_each_entry_safe(urbp, tmp, &dum_hcd->urbp_list, urbp_list) {
@@ -1835,6 +1836,9 @@ restart:
 		struct dummy_ep		*ep = NULL;
 		int			status = -EINPROGRESS;
 
+		dev_info(dummy_dev(dum_hcd), "urbp %p %x next_frame %p\n",
+				urbp, urbp->urb->pipe, dum_hcd->next_frame_urbp);
+
 		/* stop when we reach URBs queued after the timer interrupt */
 		if (urbp == dum_hcd->next_frame_urbp)
 			break;
Index: usb-devel/drivers/usb/class/cdc-wdm.c
===================================================================
--- usb-devel.orig/drivers/usb/class/cdc-wdm.c
+++ usb-devel/drivers/usb/class/cdc-wdm.c
@@ -112,6 +112,7 @@ struct wdm_device {
 
 	enum wwan_port_type	wwanp_type;
 	struct wwan_port	*wwanp;
+	int			alancount;
 };
 
 static struct usb_driver wdm_driver;
@@ -255,6 +256,14 @@ static void wdm_int_callback(struct urb
 	desc = urb->context;
 	dr = (struct usb_cdc_notification *)desc->sbuf;
 
+	if (status == -EPROTO) {
+		if (desc->alancount >= 1)
+			return;
+		++desc->alancount;
+		dev_info(&desc->intf->dev, "Alan test\n");
+		dump_stack();
+	}
+
 	if (status) {
 		switch (status) {
 		case -ESHUTDOWN: