Nut upsuser - Apr 2014 - Eaton Nova AVR repeated USBDEVFS_CONTROL failed cmd usbhid-ups

I have nut 2.6.4-2.3+deb7u1 on debian 7 32bit, with UPS Eaton Nova AVR 
1250 connected via USB.

It happens several times a day that I get a message about

Apr  3 16:41:49 kernel: [422581.049671] usb 5-1: usbfs: USBDEVFS_CONTROL 
failed cmd usbhid-ups rqt 161 rq 1 len 4 ret -110
Apr  3 16:41:54 kernel: [422586.041057] usb 5-1: usbfs: USBDEVFS_CONTROL 
failed cmd usbhid-ups rqt 161 rq 1 len 3 ret -110
Apr  3 16:41:54 kernel: [422586.086977] usb 5-1: usbfs: USBDEVFS_CONTROL 
failed cmd usbhid-ups rqt 161 rq 1 len 3 ret -75
Apr  3 16:41:54 kernel: [422586.090986] usb 5-1: usbfs: USBDEVFS_CONTROL 
failed cmd usbhid-ups rqt 161 rq 1 len 3 ret -71
Apr  3 16:41:54 kernel: [422586.094963] usb 5-1: usbfs: USBDEVFS_CONTROL 
failed cmd usbhid-ups rqt 161 rq 1 len 3 ret -71
Apr  3 16:41:54 kernel: [422586.145875] usb 5-1: usbfs: USBDEVFS_CONTROL 
failed cmd usbhid-ups rqt 161 rq 1 len 4 ret -71
Apr  3 16:41:54 kernel: [422586.149868] usb 5-1: usbfs: USBDEVFS_CONTROL 
failed cmd usbhid-ups rqt 161 rq 1 len 4 ret -71
Apr  3 16:41:54 kernel: [422586.153861] usb 5-1: usbfs: USBDEVFS_CONTROL 
failed cmd usbhid-ups rqt 161 rq 1 len 3 ret -71
Apr  3 16:41:54 kernel: [422586.157855] usb 5-1: usbfs: USBDEVFS_CONTROL 
failed cmd usbhid-ups rqt 161 rq 1 len 3 ret -71
Apr  3 16:41:54 kernel: [422586.161847] usb 5-1: usbfs: USBDEVFS_CONTROL 
failed cmd usbhid-ups rqt 161 rq 1 len 3 ret -71
Apr  3 16:41:54 kernel: [422586.165856] usb 5-1: usbfs: USBDEVFS_CONTROL 
failed cmd usbhid-ups rqt 161 rq 1 len 3 ret -71
Apr  3 16:41:54 kernel: [422586.331313] hub 5-0:1.0: port 1 disabled by 
hub (EMI?), re-enabling...
Apr  3 16:41:54 kernel: [422586.331377] usb 5-1: USB disconnect, device 
number 3
Apr  3 16:41:54 kernel: [422586.515007] hub 5-0:1.0: unable to enumerate 
USB device on port 1
Apr  3 16:41:55 kernel: [422587.569163] usb 5-1: new low-speed USB device 
number 5 using uhci_hcd
Apr  3 16:41:56 kernel: [422588.356065] usb 5-1: New USB device found, 
idVendor=0463, idProduct=ffff
Apr  3 16:41:56 kernel: [422588.356070] usb 5-1: New USB device strings: 
Mfr=1, Product=2, SerialNumber=0
Apr  3 16:41:56 kernel: [422588.356073] usb 5-1: Product: NOVA AVR
Apr  3 16:41:56 kernel: [422588.356076] usb 5-1: Manufacturer: EATON
Apr  3 16:41:58 kernel: [422589.633644] generic-usb 0003:0463:FFFF.0005: 
hiddev0,hidraw0: USB HID v1.00 Device [EATON NOVA AVR] on 
usb-0000:00:1d.0-1/input0

I tried many times repeated advice on the net to increase the pollinterval 
to 10s. It may decrease the number of "failures" but may be just a 
coincidence. I also sometimes receive a something that looks like false 
alarms but it could be that this UPS is just more sensitive than the 
other.

I may try to get
  /lib/nut/usbhid-ups -DD -a eaton
while the error happens if this helps. The same thing was happening on 
debian 6 with much older nut. I was hoping for upgrade to fix it, but it 
still happens.

Is there anything else in the NUT I may do to prevent this?

Thanks

Adam Pribyl

On Apr 3, 2014, at 3:40 PM, Adam Pribyl wrote:
> I have nut 2.6.4-2.3+deb7u1 on debian 7 32bit, with UPS Eaton Nova AVR 1250
connected via USB.
Which kernel version?
> It happens several times a day that I get a message about
> 
> Apr  3 16:41:49 kernel: [422581.049671] usb 5-1: usbfs: USBDEVFS_CONTROL
failed cmd usbhid-ups rqt 161 rq 1 len 4 ret -110
> Apr  3 16:41:54 kernel: [422586.041057] usb 5-1: usbfs: USBDEVFS_CONTROL
failed cmd usbhid-ups rqt 161 rq 1 len 3 ret -110
Error -110 is indeed a timeout, but it is not directly coupled to pollinterval.

NUT 2.7.1 increases most of the USB timeouts from 4000 to 5000 ms, but if this
error is after the driver initialization has completed, then the increased
timeout is not as likely to help.
> Apr  3 16:41:54 kernel: [422586.331313] hub 5-0:1.0: port 1 disabled by hub
(EMI?), re-enabling...
> Apr  3 16:41:54 kernel: [422586.331377] usb 5-1: USB disconnect, device
number 3
> Apr  3 16:41:54 kernel: [422586.515007] hub 5-0:1.0: unable to enumerate
USB device on port 1
This problem is between your USB hardware and your kernel. (The previous error
may be related.)

Without knowing your USB host controller, I'd say it might be a USB cable or
port issue. Try another USB cable (preferably shorter), and also try a different
port. If that doesn't fix it, you probably want to check with the linux-usb
list to see if there is a known issue with your kernel version.

There really isn't much that NUT can do there, besides recover gracefully.
The reconnection logic should be in usbhid-ups.

-- 
Charles Lepple
clepple at gmail

On Thu, 3 Apr 2014, Charles Lepple wrote:
> On Apr 3, 2014, at 3:40 PM, Adam Pribyl wrote:
>
>> I have nut 2.6.4-2.3+deb7u1 on debian 7 32bit, with UPS Eaton Nova AVR
1250 connected via USB.
>
> Which kernel version?
This is a "stock" 3.2.0-4-686-pae but was the same on 2.6.18 from
debian 6
squeeze.
>> It happens several times a day that I get a message about
>>
>> Apr  3 16:41:49 kernel: [422581.049671] usb 5-1: usbfs:
USBDEVFS_CONTROL failed cmd usbhid-ups rqt 161 rq 1 len 4 ret -110
>> Apr  3 16:41:54 kernel: [422586.041057] usb 5-1: usbfs:
USBDEVFS_CONTROL failed cmd usbhid-ups rqt 161 rq 1 len 3 ret -110
>
> Error -110 is indeed a timeout, but it is not directly coupled to
pollinterval.
>
> NUT 2.7.1 increases most of the USB timeouts from 4000 to 5000 ms, but 
> if this error is after the driver initialization has completed, then the 
> increased timeout is not as likely to help.
>
>> Apr  3 16:41:54 kernel: [422586.331313] hub 5-0:1.0: port 1 disabled by
hub (EMI?), re-enabling...
>> Apr  3 16:41:54 kernel: [422586.331377] usb 5-1: USB disconnect, device
number 3
>> Apr  3 16:41:54 kernel: [422586.515007] hub 5-0:1.0: unable to
enumerate USB device on port 1
>
> This problem is between your USB hardware and your kernel. (The previous
error may be related.)
>
> Without knowing your USB host controller, I'd say it might be a USB
Bus 005 Device 005: ID 0463:ffff MGE UPS Systems UPS

00:1a.0 USB controller: Intel Corporation 82801JI (ICH10 Family) USB UHCI 
Controller #4
00:1a.1 USB controller: Intel Corporation 82801JI (ICH10 Family) USB UHCI 
Controller #5
00:1a.7 USB controller: Intel Corporation 82801JI (ICH10 Family) USB2 EHCI 
Controller #2
00:1d.0 USB controller: Intel Corporation 82801JI (ICH10 Family) USB UHCI 
Controller #1
00:1d.1 USB controller: Intel Corporation 82801JI (ICH10 Family) USB UHCI 
Controller #2
00:1d.2 USB controller: Intel Corporation 82801JI (ICH10 Family) USB UHCI 
Controller #3
00:1d.3 USB controller: Intel Corporation 82801JI (ICH10 Family) USB UHCI 
Controller #6
00:1d.7 USB controller: Intel Corporation 82801JI (ICH10 Family) USB2 EHCI 
Controller #1

ls  -la /sys/bus/pci/devices/0000:00:1d.0/usb5/ | grep 5-0
drwxr-xr-x 4 root root     0 Mar 29 18:08 5-0:1.0
> cable or port issue. Try another USB cable (preferably shorter), and
> also try a different port. If that doesn't fix it, you probably want to
OK, you are right, I'll try that.
> check with the linux-usb list to see if there is a known issue with your 
> kernel version.
Understood.
> There really isn't much that NUT can do there, besides recover 
> gracefully. The reconnection logic should be in usbhid-ups.
Thanks
> -- 
> Charles Lepple
> clepple at gmail
Adam Pribyl