I have a UPS plugged into USB being monitored by apcupsd, and once and a while a control in transfer is submitted which isn't completed. When not completed the usbhid control request queue fills up until no more control requests can be submitted (not that any of the previous ones are being serviced), preventing the UPS from being monitored. As the control request doesn't complete the hid-core.c hid_ctrl completion handler doesn't get called, and things stop there. Further control requests to the hid-core pile up in the queue until the queue is filled up, then it complains for each new request. The only way out is to kill apcupsd (and wait for it exit), then reload the ohci_hcd module with the stock 2.6.31 kernel. I've included a debug patch that will kill the urb when the queue is nearly full and resubmit it. While it does work, I don't consider this the right solution and it still leaves the UPS unmonitored for the nearly hour that it takes the control queue to fill up and trigger my routine. The usb monitor doesn't say why the control request doesn't complete, just that it was submitted and didn't complete. Any ideas? I can try changes or enable other debugging, just keep in mind the time for this to reproduce, which could be a week or a month between stuck control requests. Kernel log 2.6.31 with added print messages showing the queue filling up. Jan 13 23:47:47 SubSpace kernel: usbhid control queue 1 max 256 Jan 13 23:47:57 SubSpace kernel: usbhid control queue 2 max 256 Jan 13 23:48:07 SubSpace kernel: usbhid control queue 3 max 256 Jan 13 23:48:18 SubSpace kernel: usbhid control queue 4 max 256 Jan 13 23:48:28 SubSpace kernel: usbhid control queue 5 max 256 Jan 13 23:48:38 SubSpace kernel: usbhid control queue 6 max 256 Jan 13 23:48:48 SubSpace kernel: usbhid control queue 7 max 256 Jan 13 23:48:58 SubSpace kernel: usbhid control queue 8 max 256 Jan 13 23:49:08 SubSpace kernel: usbhid control queue 9 max 256 Jan 13 23:49:18 SubSpace kernel: usbhid control queue 10 max 256 ... Jan 14 00:30:44 SubSpace kernel: usbhid control queue 255 max 256 Jan 14 00:30:44 SubSpace kernel: generic-usb 0003:051D:0002.0001: control queue full Jan 14 00:30:54 SubSpace kernel: usbhid control queue 255 max 256 Jan 14 00:30:54 SubSpace kernel: generic-usb 0003:051D:0002.0001: control queue full /sys/kernel/debug/usb/usbmon/1u with a comment and some timestamps thrown in. deb6be60 2035135411 C Ii:1:002:1 0:64 6 = 0c640000 3000 deb6be60 2035135448 S Ii:1:002:1 -115:64 6 < debd4c40 2035215964 S Ci:1:002:0 s a1 01 0326 0000 0004 8 < debd4c40 2035288374 C Ci:1:002:0 0 4 = 26383130 debd4c40 2035388963 S Ci:1:002:0 s a1 01 0314 0000 0003 8 < debd4c40 2035390345 C Ci:1:002:0 0 3 = 140000 debd4c40 2035449700 S Ci:1:002:0 s a1 01 0314 0000 0003 8 < debd4c40 2035451329 C Ci:1:002:0 0 3 = 140000 debd4c40 2035490585 S Ci:1:002:0 s a1 01 0306 0000 0004 8 < debd4c40 2035492320 C Ci:1:002:0 0 4 = 06000008 debd4c40 2035531573 S Ci:1:002:0 s a1 01 030c 0000 0006 8 < debd4c40 2035533313 C Ci:1:002:0 0 6 = 0c640000 3000 debd4c40 2035552482 S Ci:1:002:0 s a1 01 030c 0000 0006 8 < debd4c40 2035554309 C Ci:1:002:0 0 6 = 0c640000 3000 deb6be60 2038078714 C Ii:1:002:1 0:64 4 = 06000008 deb6be60 2038078756 S Ii:1:002:1 -115:64 6 < deb6be60 2039134465 C Ii:1:002:1 0:64 6 = 0c640000 3200 deb6be60 2039134502 S Ii:1:002:1 -115:64 6 < debd4c40 2039214970 S Ci:1:002:0 s a1 01 0326 0000 0004 8 < debd4c40 2039286427 C Ci:1:002:0 0 4 = 26383130 debd4c40 2039392488 S Ci:1:002:0 s a1 01 0314 0000 0003 8 < debd4c40 2039394396 C Ci:1:002:0 0 3 = 140000 debd4c40 2039453754 S Ci:1:002:0 s a1 01 0314 0000 0003 8 < debd4c40 2039455383 C Ci:1:002:0 0 3 = 140000 debd4c40 2039494659 S Ci:1:002:0 s a1 01 0306 0000 0004 8 < debd4c40 2039496376 C Ci:1:002:0 0 4 = 06000008 debd4c40 2039535654 S Ci:1:002:0 s a1 01 030c 0000 0006 8 < debd4c40 2039537362 C Ci:1:002:0 0 6 = 0c640000 3200 debd4c40 2039556523 S Ci:1:002:0 s a1 01 030c 0000 0006 8 < debd4c40 2039558358 C Ci:1:002:0 0 6 = 0c640000 3200 deb6be60 2042109759 C Ii:1:002:1 0:64 4 = 06000008 deb6be60 2042109799 S Ii:1:002:1 -115:64 6 < Wed Jan 13 23:47:18 CST 2010 debd4c40 2099775374 S Ci:1:002:0 s a1 01 0326 0000 0004 8 < debd4c40 2099849088 C Ci:1:002:0 0 4 = 26383130 debd4c40 2099969889 S Ci:1:002:0 s a1 01 0314 0000 0003 8 < debd4c40 2099971051 C Ci:1:002:0 0 3 = 140000 debd4c40 2100030411 S Ci:1:002:0 s a1 01 0314 0000 0003 8 < debd4c40 2100032039 C Ci:1:002:0 0 3 = 140000 debd4c40 2100071310 S Ci:1:002:0 s a1 01 0306 0000 0004 8 < -- last mention of debd4c40 in the log (which goes on for 3 days) deb6be60 2115116471 C Ii:1:002:1 0:64 6 = 0c640000 3000 deb6be60 2115116568 S Ii:1:002:1 -115:64 6 < deb6be60 2118091767 C Ii:1:002:1 0:64 4 = 06000008 deb6be60 2118091801 S Ii:1:002:1 -115:64 6 < deb6be60 2119115523 C Ii:1:002:1 0:64 6 = 0c640000 3200 deb6be60 2119115555 S Ii:1:002:1 -115:64 6 < deb6be60 2122090821 C Ii:1:002:1 0:64 4 = 06000008 deb6be60 2122090856 S Ii:1:002:1 -115:64 6 < deb6be60 2127113630 C Ii:1:002:1 0:64 6 = 0c640000 3000 deb6be60 2127113664 S Ii:1:002:1 -115:64 6 < deb6be60 2130088939 C Ii:1:002:1 0:64 4 = 06000008 deb6be60 2130088971 S Ii:1:002:1 -115:64 6 < deb6be60 2131112683 C Ii:1:002:1 0:64 6 = 0c640000 3200 deb6be60 2131112715 S Ii:1:002:1 -115:64 6 < deb6be60 2134087979 C Ii:1:002:1 0:64 4 = 06000008 deb6be60 2134088013 S Ii:1:002:1 -115:64 6 < deb6be60 2135111736 C Ii:1:002:1 0:64 6 = 0c640000 3000 deb6be60 2135111767 S Ii:1:002:1 -115:64 6 < deb6be60 2138087031 C Ii:1:002:1 0:64 4 = 06000008 deb6be60 2138087065 S Ii:1:002:1 -115:64 6 < deb6be60 2139110788 C Ii:1:002:1 0:64 6 = 0c640000 3200 deb6be60 2139110820 S Ii:1:002:1 -115:64 6 < Wed Jan 13 23:48:18 CST 2010 deb6be60 2142086085 C Ii:1:002:1 0:64 4 = 06000008 deb6be60 2142086118 S Ii:1:002:1 -115:64 6 < Kernel log 2.6.31 with included patch. usbhid control queue 253 urb d1c301e0 max 256 usbhid control queue 254 urb d1c301e0 max 256 usbhid killing urb d1c301e0 to try to restart. drivers/hid/usbhid/hid-core.c: usb_submit_urb(ctrl) failed usbhid control queue kill, submit 0 usbhid control queue 251 urb d1c301e0 max 256 drivers/hid/usbhid/hid-core.c: usb_submit_urb(ctrl) failed usbhid control queue 0 urb d1c301e0 max 256 /sys/kernel/debug/usb/usbmon/1u Fri Feb 5 04:32:40 CST 2010 d1c301e0 2316039284 S Ci:1:002:0 s a1 01 0326 0000 0004 8 < d1c301e0 2316111744 C Ci:1:002:0 0 4 = 26343130 d1c301e0 2316212317 S Ci:1:002:0 s a1 01 0314 0000 0003 8 < d1c301e0 2316213716 C Ci:1:002:0 0 3 = 140000 d1c301e0 2316273046 S Ci:1:002:0 s a1 01 0314 0000 0003 8 < de7cfde0 2334333394 C Ii:1:002:1 0:64 6 = 0c640000 3c00 de7cfde0 2334333468 S Ii:1:002:1 -115:64 6 < de7cfde0 2337308683 C Ii:1:002:1 0:64 4 = 06000008 de7cfde0 2337308711 S Ii:1:002:1 -115:64 6 < de7cfde0 2338332437 C Ii:1:002:1 0:64 6 = 0c640000 3f00 de7cfde0 2338332462 S Ii:1:002:1 -115:64 6 < ... just interrupt transfers de7cfde0 750927954 C Ii:1:002:1 0:64 4 = 06000008 de7cfde0 750927982 S Ii:1:002:1 -115:64 6 < Fri Feb 5 05:37:41 CST 2010 Fri Feb 5 05:38:41 CST 2010 Fri Feb 5 05:39:41 CST 2010 d1c301e0 904546899 C Ci:1:002:0 -2 3 = 140000 d1c301e0 904546946 S Ci:1:002:0 s a1 01 0306 0000 0004 8 < d1c301e0 0 E Ci:0:002:0 -1 0 d1c301e0 904547161 S Ci:1:002:0 s a1 01 0306 0000 0004 8 < d1c301e0 904548882 C Ci:1:002:0 0 4 = 06000008 d1c301e0 904548906 S Ci:1:002:0 s a1 01 030c 0000 0006 8 < d1c301e0 904549866 C Ci:1:002:0 0 6 = 0c640000 3f00 d1c301e0 904549875 S Ci:1:002:0 s a1 01 030c 0000 0006 8 < d1c301e0 904550866 C Ci:1:002:0 0 6 = 0c640000 3f00 d1c301e0 904550873 S Ci:1:002:0 s a1 01 0326 0000 0004 8 < d1c301e0 904620858 C Ci:1:002:0 0 4 = 26343130 d1c301e0 904620879 S Ci:1:002:0 s a1 01 0314 0000 0003 8 < d1c301e0 904621850 C Ci:1:002:0 0 3 = 140000 00:00.0 Host bridge: Silicon Integrated Systems [SiS] 635 Host (rev 11) 00:01.0 PCI bridge: Silicon Integrated Systems [SiS] Virtual PCI-to-PCI bridge (AGP) 00:02.2 USB Controller: Silicon Integrated Systems [SiS] USB 1.1 Controller (rev 07) 00:02.3 USB Controller: Silicon Integrated Systems [SiS] USB 1.1 Controller (rev 07) T: Bus=01 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 1 Spd=12 MxCh= 3 B: Alloc= 3/900 us ( 0%), #Int= 1, #Iso= 0 D: Ver= 1.10 Cls=09(hub ) Sub=00 Prot=00 MxPS=64 #Cfgs= 1 P: Vendor=1d6b ProdID=0001 Rev= 2.06 S: Manufacturer=Linux 2.6.31 ohci_hcd S: Product=OHCI Host Controller S: SerialNumber=0000:00:02.2 C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr= 0mA I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub E: Ad=81(I) Atr=03(Int.) MxPS= 2 Ivl=255ms T: Bus=01 Lev=01 Prnt=01 Port=00 Cnt=01 Dev#= 2 Spd=1.5 MxCh= 0 D: Ver= 1.00 Cls=00(>ifc ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1 P: Vendor=051d ProdID=0002 Rev= 0.06 S: Manufacturer=American Power Conversion S: Product=BackUPS Pro 500 FW:16.3.D USB FW:4 S: SerialNumber=NB9921360588 C:* #Ifs= 1 Cfg#= 1 Atr=a0 MxPwr= 30mA I:* If#= 0 Alt= 0 #EPs= 1 Cls=03(HID ) Sub=01 Prot=00 Driver=usbhid E: Ad=81(I) Atr=03(Int.) MxPS= 8 Ivl=100ms MANDATE : 1999-05-20 SERIALNO : NB9921360588 FIRMWARE : 16.3.D USB FW:4 APCMODEL : BackUPS Pro 500 -- David Fries <david@xxxxxxxxx> http://fries.net/~david/ (PGP encryption key available) diff --git a/drivers/hid/usbhid/hid-core.c b/drivers/hid/usbhid/hid-core.c index 3c1fcb7..cb80d28 100644 --- a/drivers/hid/usbhid/hid-core.c +++ b/drivers/hid/usbhid/hid-core.c @@ -519,6 +519,35 @@ void __usbhid_submit_report(struct hid_device *hid, struct hid_report *report, u return; } + { + static int last_high; + int count = usbhid->ctrlhead - usbhid->ctrltail; + if(count < 0) + count += HID_CONTROL_FIFO_SIZE; + //if(count > last_high) + if(count != last_high) + { + printk("usbhid control queue %d urb %p max %d\n", + count, usbhid->urbctrl, HID_CONTROL_FIFO_SIZE); + last_high = count; + /* reset each time control queue full message is + * printed + */ + if(((usbhid->ctrlhead + 1) & + (HID_CONTROL_FIFO_SIZE - 1)) + == usbhid->ctrltail) + { + last_high = 0; + } + } + if(count+2 == HID_CONTROL_FIFO_SIZE) { + printk("usbhid killing urb %p to try to restart.\n", + usbhid->urbctrl); + queue_work(resumption_waker, + &usbhid->ctrl_restart_work); + } + } + if ((head = (usbhid->ctrlhead + 1) & (HID_CONTROL_FIFO_SIZE - 1)) == usbhid->ctrltail) { dev_warn(&hid->dev, "control queue full\n"); return; @@ -816,6 +845,17 @@ static void __usbhid_restart_queues(struct work_struct *work) usb_autopm_put_interface(usbhid->intf); } +static void hid_ctrl_restart(struct work_struct *work) +{ + struct usbhid_device *usbhid = + container_of(work, struct usbhid_device, ctrl_restart_work); + int s; + + usb_kill_urb(usbhid->urbctrl); + s = usb_submit_urb(usbhid->urbctrl, GFP_ATOMIC); + printk("usbhid control queue kill, submit %d\n", s); +} + static void hid_free_buffers(struct usb_device *dev, struct hid_device *hid) { struct usbhid_device *usbhid = hid->driver_data; @@ -983,6 +1023,7 @@ static int usbhid_start(struct hid_device *hid) init_waitqueue_head(&usbhid->wait); INIT_WORK(&usbhid->reset_work, hid_reset); INIT_WORK(&usbhid->restart_work, __usbhid_restart_queues); + INIT_WORK(&usbhid->ctrl_restart_work, hid_ctrl_restart); setup_timer(&usbhid->io_retry, hid_retry_timeout, (unsigned long) hid); spin_lock_init(&usbhid->lock); @@ -1201,6 +1242,7 @@ static void hid_cancel_delayed_stuff(struct usbhid_device *usbhid) del_timer_sync(&usbhid->io_retry); cancel_work_sync(&usbhid->restart_work); cancel_work_sync(&usbhid->reset_work); + cancel_work_sync(&usbhid->ctrl_restart_work); } static void hid_cease_io(struct usbhid_device *usbhid) @@ -1221,6 +1263,7 @@ static int hid_pre_reset(struct usb_interface *intf) set_bit(HID_RESET_PENDING, &usbhid->iofl); spin_unlock_irq(&usbhid->lock); cancel_work_sync(&usbhid->restart_work); + cancel_work_sync(&usbhid->ctrl_restart_work); hid_cease_io(usbhid); return 0; diff --git a/drivers/hid/usbhid/usbhid.h b/drivers/hid/usbhid/usbhid.h index 08f505c..8fbb373 100644 --- a/drivers/hid/usbhid/usbhid.h +++ b/drivers/hid/usbhid/usbhid.h @@ -94,6 +94,7 @@ struct usbhid_device { unsigned int retry_delay; /* Delay length in ms */ struct work_struct reset_work; /* Task context for resets */ struct work_struct restart_work; /* waking up for output to be done in a task */ + struct work_struct ctrl_restart_work; /* waking up for output to be done in a task */ wait_queue_head_t wait; /* For sleeping */ int ledcount; /* counting the number of active leds */ }; -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
