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");
