[Nut-upsuser] USBDEVFS_CONTROL failed cmd usbhid-ups

[Arnaud Quette]

Hi Tom,

sorry for the late answer.
ATM, there is not much you can do

2009/11/25 Thomas Gutzler <thomas.gutzler at gmail.com>:
> Hi again,
>
> Are there any thoughts, comments or suggestions for this problem or
> should I just ignore it?
>
> Tom
>
> On Mon, Nov 23, 2009 at 14:10, Thomas Gutzler <thomas.gutzler at gmail.com> wrote:
>> Hi,
>>
>> I keep getting the following messages (or similar) in my syslog:
>> Nov 23 11:38:08 io kernel: [763936.921566] usb 3-2: usbfs:
>> USBDEVFS_CONTROL failed cmd usbhid-ups rqt 161 rq 1 len 5 ret -110
>> Nov 23 11:38:08 io kernel: [763936.972569] usb 3-2: usbfs:
>> USBDEVFS_CONTROL failed cmd usbhid-ups rqt 161 rq 1 len 5 ret -75
>> Nov 23 11:38:08 io kernel: [763936.976568] usb 3-2: usbfs:
>> USBDEVFS_CONTROL failed cmd usbhid-ups rqt 161 rq 1 len 2 ret -71
>> Nov 23 11:38:08 io kernel: [763936.980565] usb 3-2: usbfs:
>> USBDEVFS_CONTROL failed cmd usbhid-ups rqt 161 rq 1 len 2 ret -71
>> Nov 23 11:38:08 io kernel: [763936.984567] usb 3-2: usbfs:
>> USBDEVFS_CONTROL failed cmd usbhid-ups rqt 161 rq 1 len 2 ret -71
>> Nov 23 11:38:08 io kernel: [763936.988564] usb 3-2: usbfs:
>> USBDEVFS_CONTROL failed cmd usbhid-ups rqt 161 rq 1 len 2 ret -71
>> Nov 23 11:38:08 io kernel: [763937.038568] usb 3-2: usbfs:
>> USBDEVFS_CONTROL failed cmd usbhid-ups rqt 161 rq 1 len 5 ret -71
>> Nov 23 11:38:08 io kernel: [763937.041275] hub 3-0:1.0: port 2 disabled
>> by hub (EMI?), re-enabling...
>> Nov 23 11:38:08 io kernel: [763937.046927] usb 3-2: usbfs:
>> USBDEVFS_CONTROL failed cmd usbhid-ups rqt 161 rq 1 len 5 ret -71
>> Nov 23 11:38:08 io kernel: [763937.046930] usb 3-2: USB disconnect,
>> address 101
>> Nov 23 11:38:08 io kernel: [763937.320015] usb 3-2: new full speed USB
>> device using uhci_hcd and address 102
>> Nov 23 11:38:08 io kernel: [763937.390033] hub 3-0:1.0: unable to
>> enumerate USB device on port 2
>> Nov 23 11:38:10 io kernel: [763938.570009] usb 3-2: new low speed USB
>> device using uhci_hcd and address 103
>> Nov 23 11:38:10 io kernel: [763939.456680] usb 3-2: configuration #1
>> chosen from 1 choice
>> Nov 23 11:38:15 io kernel: [763944.044783] generic-usb
>> 0003:0463:FFFF.00AC: hiddev96,hidraw0: USB HID v1.00 Device [EATON
>> ELLIPSE] on usb-0000:00:1a.0-2/input0
>> Nov 23 11:38:16 io upsd[2392]: Data for UPS [new] is stale - check driver
>> Nov 23 11:38:18 io upsd[2392]: UPS [new] data is no longer stale

well, this varies between kernel revision, but there is a timeout
(110), followed by an overflow (75) and several protocol errors (71).
the 2 later being due to the first, it ends up with a software
disconnexion (disabling / enabling)

>> Sometimes it detects a low speed device right away without trying full
>> speed first. Everything else is the same.

have you tried different USB ports?

>> I found a few similar posts on this list but none of them seemed to
>> include a suggestion how to solve it and they were all for different
>> UPSes. Possibly a bug in the driver?
>> I got around 110 'USBDEVFS_CONTROL failed cmd' within the last 8 hours
>> and 12 'port 2 disabled by hub (EMI?), re-enabling...'
>>
>> Even though I have two very similar UPSes (both MGE Ellipse 1500 via
>> usb), only one of them seems to be having problems with the driver. I'm
>> getting the odd 'data is stale' warning for the other ups (<10 per day)
>> but it never caused the port to be disabled so far.
>> I'm pretty sure it's not EMI because both cables are right next to each
>> other and seem of similar quality.
>>
>> I've also noticed that the average system load has gone up from 0.1 to
>> 0.3 after connecting both UPSes and setting up nut, which I didn't
>> expect on a 2GHz dual core; I set pollfreq=30 for both in ups.conf.
>> I'm running nut 2.4.1-2ubuntu4 on a 64 bit linux 2.6.28-16 kernel.
>>
>> Any suggestions?
>> I'm happy to provide debug information or try out patches or the 2.5 tree.

sadly, there is not much we can do at the NUT level.
note that pollfreq already defaults to 30 (seconds), so you don't need
to add this if you don't change the value.
you might want to set it to a higher value, and rely more on interrupt
data (sent by the UPS itself, without polling request), but you might
miss some events / data update.
you can try to set ups.test.interval to some higher value, since the
above might be due to a temporary overload of the UPS core (already
busy doing something, it considers the communication link to be of a
lower priority).

for the system load, I still have to do a powertop pass and some more
tuning to improve the driver.
but Arjen has (will) also started to work on the libusb 1.0 support,
which should improve the things a bit.

cheers,
Arnaud
-- 
Linux / Unix Expert R&D - Eaton - http://www.eaton.com/mgeops
Network UPS Tools (NUT) Project Leader - http://www.networkupstools.org/
Debian Developer - http://www.debian.org
Free Software Developer - http://arnaud.quette.free.fr/