Hi All, I'm the USB driver maintainer for the Apcupsd project and I currently have 2 users (cc:ed) who are experiencing lockups (apcupsd hangs, usually in an unkillable state) on particlar model UPSes after anywhere from minutes to hours of uptime. I've debugged about as far as I can without enlisting some expert help.
Details are below. Please feel free to ask for more info or experimentation if it will be useful. Thanks in advance for your help! --Adam Background Apcupsd uses the hiddev driver for userspace access to HID compatible UPSes. The device node is monitored for events caused by interrupt transfers (which tend to happen every 5 seconds or so) and generates some control transfers of its own to poll various feature reports. Problem After some period of time (minutes to hours), the BackUPS CS 650 and BackUPS BR 800 models cease to respond to control transfers. Based on HID debug I can see that a control transfer is sent by apcupsd but a response never comes back. hid-core.c complains "timeout waiting for ctrl or out queue to clear". After that, no further control transfers go thru, instead the timeout error repeats. Interrupt transfers continue to be processed every 6 seconds as expected. (See dmesg log snippet below). Eventually, the timeout error is joined by a "control queue full" error as well. Hardware/Software Details There are so few commonalities between the 2 systems experiencing problems it's very hard to pin down the source. The breakdown is as follows: One user has an OHCI based system (AMD-768) and the other has UHCI (802801EB/ER). Both exhibit the lockup with identical symptoms, which would seem to rule out a low-level HCD problem. CS650 and BR800 UPSes exhibit the lockup behavior. RS1000 and BF350 models do not lock up when connected to the very same systems. (So clearly this is a UPS-specific problem, and it wouldn't be the first UPS firmware bug we've seen, but since Windows doesn't exhibit the problem APC denies there's anything wrong.) Both users have tried different kernels up to and including 2.6.11.x, as well as BIOS upgrades, etc. dmesg Log (annotated): # First we see a few batches of interrupt transfers, every 4-5 seconds May 18 16:37:16 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:16 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 8a 04 May 18 16:37:16 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:16 jesus kernel: drivers/usb/input/hid-core.c: report 12 (size 1) = 64 May 18 16:37:16 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:16 jesus kernel: drivers/usb/input/hid-core.c: report 7 (size 2) = 0c 00 May 18 16:37:16 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:16 jesus kernel: drivers/usb/input/hid-core.c: report 22 (size 1) = 06 May 18 16:37:20 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:20 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 8a 04 May 18 16:37:20 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:20 jesus kernel: drivers/usb/input/hid-core.c: report 12 (size 1) = 64 May 18 16:37:20 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:20 jesus kernel: drivers/usb/input/hid-core.c: report 7 (size 2) = 0c 00 May 18 16:37:20 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:20 jesus kernel: drivers/usb/input/hid-core.c: report 22 (size 1) = 06 May 18 16:37:25 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:25 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 8a 04 May 18 16:37:25 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:25 jesus kernel: drivers/usb/input/hid-core.c: report 12 (size 1) = 64 May 18 16:37:25 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:25 jesus kernel: drivers/usb/input/hid-core.c: report 7 (size 2) = 0c 00 May 18 16:37:25 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:25 jesus kernel: drivers/usb/input/hid-core.c: report 22 (size 1) = 06 May 18 16:37:27 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:27 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 74 04 May 18 16:37:27 jesus kernel: hid-debug: input Battery System.RunTimeToEmpty = 1140 # Now apcupsd submits a few control URBs to poll some reports May 18 16:37:27 jesus kernel: drivers/usb/input/hid-core.c: submitting ctrl urb: Get_Report wValue=0x0307 wIndex=0x0000 wLength=3 May 18 16:37:27 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:27 jesus kernel: drivers/usb/input/hid-core.c: report 7 (size 2) = 0c 00 May 18 16:37:27 jesus kernel: drivers/usb/input/hid-core.c: submitting ctrl urb: Get_Report wValue=0x0307 wIndex=0x0000 wLength=3 May 18 16:37:27 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:27 jesus kernel: drivers/usb/input/hid-core.c: report 7 (size 2) = 0c 00 May 18 16:37:27 jesus kernel: drivers/usb/input/hid-core.c: submitting ctrl urb: Get_Report wValue=0x0307 wIndex=0x0000 wLength=3 # Two seconds elapse with no response to the last control URB. # Eventually we see some more interrupt transfers come in. May 18 16:37:29 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:29 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 65 04 May 18 16:37:29 jesus kernel: hid-debug: input Battery System.RunTimeToEmpty = 1125 May 18 16:37:29 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:29 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 65 04 May 18 16:37:29 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:29 jesus kernel: drivers/usb/input/hid-core.c: report 12 (size 1) = 64 May 18 16:37:29 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:29 jesus kernel: drivers/usb/input/hid-core.c: report 7 (size 2) = 0c 00 May 18 16:37:29 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:29 jesus kernel: drivers/usb/input/hid-core.c: report 22 (size 1) = 06 May 18 16:37:31 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:31 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 74 04 May 18 16:37:31 jesus kernel: hid-debug: input Battery System.RunTimeToEmpty = 1140 May 18 16:37:33 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:33 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 74 04 May 18 16:37:33 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:33 jesus kernel: drivers/usb/input/hid-core.c: report 12 (size 1) = 64 May 18 16:37:33 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:33 jesus kernel: drivers/usb/input/hid-core.c: report 7 (size 2) = 0c 00 May 18 16:37:33 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:33 jesus kernel: drivers/usb/input/hid-core.c: report 22 (size 1) = 06 May 18 16:37:37 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:37 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 74 04 May 18 16:37:37 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:37 jesus kernel: drivers/usb/input/hid-core.c: report 12 (size 1) = 64 May 18 16:37:37 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:37 jesus kernel: drivers/usb/input/hid-core.c: report 7 (size 2) = 0c 00 May 18 16:37:37 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:37 jesus kernel: drivers/usb/input/hid-core.c: report 22 (size 1) = 06 # Here the control URB times out. May 18 16:37:37 jesus kernel: drivers/usb/input/hid-core.c: timeout waiting for ctrl or out queue to clear # The timeout repeats every 10 seconds with intervening interrupt URBs. May 18 16:37:38 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:38 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 65 04 May 18 16:37:38 jesus kernel: hid-debug: input Battery System.RunTimeToEmpty = 1125 May 18 16:37:41 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:41 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 4e 04 May 18 16:37:41 jesus kernel: hid-debug: input Battery System.RunTimeToEmpty = 1102 May 18 16:37:41 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:41 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 4e 04 May 18 16:37:41 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:41 jesus kernel: drivers/usb/input/hid-core.c: report 12 (size 1) = 64 May 18 16:37:41 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:41 jesus kernel: drivers/usb/input/hid-core.c: report 7 (size 2) = 0c 00 May 18 16:37:41 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:41 jesus kernel: drivers/usb/input/hid-core.c: report 22 (size 1) = 06 May 18 16:37:42 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:42 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 65 04 May 18 16:37:42 jesus kernel: hid-debug: input Battery System.RunTimeToEmpty = 1125 May 18 16:37:45 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:45 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 65 04 May 18 16:37:45 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:45 jesus kernel: drivers/usb/input/hid-core.c: report 12 (size 1) = 64 May 18 16:37:45 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:45 jesus kernel: drivers/usb/input/hid-core.c: report 7 (size 2) = 0c 00 May 18 16:37:45 jesus kernel: drivers/usb/input/hid-core.c: report (size 2) (numbered) May 18 16:37:45 jesus kernel: drivers/usb/input/hid-core.c: report 22 (size 1) = 06 May 18 16:37:46 jesus kernel: drivers/usb/input/hid-core.c: report (size 3) (numbered) May 18 16:37:46 jesus kernel: drivers/usb/input/hid-core.c: report 13 (size 2) = 74 04 May 18 16:37:46 jesus kernel: hid-debug: input Battery System.RunTimeToEmpty = 1140 May 18 16:37:47 jesus kernel: drivers/usb/input/hid-core.c: timeout waiting for ctrl or out queue to clear # The above sequence repeats for almost an hour, at which point the # timeout message is joined by 'control queue full' May 18 17:23:58 jesus kernel: drivers/usb/input/hid-core.c: timeout waiting for ctrl or out queue to clear May 18 17:23:58 jesus kernel: drivers/usb/input/hid-core.c: control queue full ------------------------------------------------------- This SF.Net email is sponsored by Yahoo. Introducing Yahoo! Search Developer Network - Create apps using Yahoo! Search APIs Find out how you can build Yahoo! directly into your own Applications - visit http://developer.yahoo.net/?fr=offad-ysdn-ostg-q22005 _______________________________________________ [email protected] To unsubscribe, use the last form field at: https://lists.sourceforge.net/lists/listinfo/linux-usb-devel
