[Nut-upsdev] Syslog flooding

Thu Apr 22 14:45:33 UTC 2010

On Tue, Apr 20, 2010 at 03:13:07PM +0200, Arjen de Korte wrote:
> Citeren Kelvin Ku <kelvin at telemetry-investments.com>:
>
>> Note that the problematic unit, upsserv7, exhibits the USB disconnect 
>> behavior even when it's the only UPS connected to the host.
>
> If possible, run it in debug mode
>
>     /path/to/usbhid-ups -DD -a upsserv7
>
> and watch the output when it (re)connects. Chances are that the device  
> is reporting different serial numbers (or none at all) depending whether 
> this is the first connection made or a later one. We've seen such erratic 
> behavior before on other devices. This will make it impossible for the 
> driver to reconnect. You'll be specifically interested in lines with 
> "Serial Number" in them (and a few lines of context before and after it).

I swapped the USB cable on upsserv7 for a new one and the connection was stable
for a day. It started flaking out again today, though, so I tried what you
suggested. Here's the syslog before I stopped the NUT service:

Apr 22 10:11:11 kernel: hub 1-0:1.0: port 2 disabled by hub (EMI?), re-enabling...
Apr 22 10:11:11 kernel: usb 1-2: USB disconnect, address 8
Apr 22 10:11:11 kernel: usb 1-2: new low speed USB device using ohci_hcd and address 9
Apr 22 10:11:11 kernel: usb 1-2: configuration #1 chosen from 1 choice
Apr 22 10:11:12 kernel: hiddev96: USB HID v1.11 Device [Tripp Lite       TRIPP LITE UPS  ] on usb-0000:00:0f.2-2
Apr 22 10:11:13 usbhid-ups[10103]: Got disconnected by another driver: Device or resource busy
Apr 22 10:11:15 usbhid-ups[10103]: Got disconnected by another driver: Device or resource busy
Apr 22 10:11:17 usbhid-ups[10103]: Got disconnected by another driver: Device or resource busy
Apr 22 10:11:19 usbhid-ups[10103]: Got disconnected by another driver: Device or resource busy
Apr 22 10:11:21 usbhid-ups[10103]: Got disconnected by another driver: Device or resource busy
Apr 22 10:11:23 usbhid-ups[10103]: Got disconnected by another driver: Device or resource busy
Apr 22 10:11:25 usbhid-ups[10103]: Got disconnected by another driver: Device or resource busy
Apr 22 10:11:27 usbhid-ups[10103]: Got disconnected by another driver: Device or resource busy
Apr 22 10:11:29 usbhid-ups[10103]: Got disconnected by another driver: Device or resource busy
Apr 22 10:11:30 upsmon[10112]: Signal 15: exiting

Any idea what the following output indicates and whether I can work around it?

$ sudo /sbin/usbhid-ups -DD -a upsserv7
Network UPS Tools - Generic HID driver 0.34 (2.4.3)
USB communication driver 0.31
   0.000000     debug level is '2'
   0.001283     upsdrv_initups...
   0.002078     Checking device (09AE/4004) (001/009)
   0.022760     - VendorID: 09ae
   0.022945     - ProductID: 4004
   0.023120     - Manufacturer: Tripp Lite      
   0.023291     - Product: TRIPP LITE UPS  
   0.023472     - Serial Number: 9824ALCPS720000282  
   0.023656     - Bus: 001
   0.023866     Trying to match device
   0.024196     Device matches
   0.033806     HID descriptor length 1082
   0.070756     Report Descriptor size = 1082
   0.071949     Using subdriver: TrippLite HID 0.4
   0.073754     libusb_get_report: No error
   0.073949     Can't retrieve Report 28: Inappropriate ioctl for device
   0.074145     Path: UPS.PowerSummary.iProduct, Type: Feature, ReportID: 0x28, Offset: 0, Size: 8
   0.076750     libusb_get_report: No error
   0.076926     Can't retrieve Report 29: Inappropriate ioctl for device
   0.077112     Path: UPS.PowerSummary.iSerialNumber, Type: Feature, ReportID: 0x29, Offset: 0, Size: 8
...
   0.223729     libusb_get_report: No error
   0.223835     Can't retrieve Report 02: Inappropriate ioctl for device
   0.223943     Path: UPS.Flow.ConfigFrequency, Type: Feature, ReportID: 0x02, Offset: 0, Size: 8
   0.226746     Can't retrieve Report 55: Broken pipe
   0.226907     Path: UPS.Flow.ffff0097, Type: Feature, ReportID: 0x55, Offset: 0, Size: 8
   0.229728     libusb_get_report: error sending control message: Broken pipe
   0.229837     Can't retrieve Report 03: Broken pipe
   0.229945     Path: UPS.Flow.ConfigApparentPower, Type: Feature, ReportID: 0x03, Offset: 0, Size: 16
...
   0.386706     libusb_get_report: error sending control message: Broken pipe
   0.386912     Can't retrieve Report 6c: Broken pipe
   0.387049     Path: UPS.ffff0010.[1].ffff007d, Type: Feature, ReportID: 0x6c, Offset: 0, Size: 16
   0.387221     Report descriptor retrieved (Reportlen = 1082)
   0.387347     Found HID device
   0.387474     Detected a UPS: Tripp Lite      /TRIPP LITE UPS  
   0.389706     libusb_get_report: error sending control message: Broken pipe
   0.389843     Can't retrieve Report 34: Broken pipe
   0.392705     libusb_get_report: error sending control message: Broken pipe
   0.392839     Can't retrieve Report 21: Broken pipe
...
   0.593678     libusb_get_report: error sending control message: Broken pipe
   0.593719     Can't retrieve Report 11: Broken pipe
   0.593892     upsdrv_initinfo...
   0.593927     upsdrv_updateinfo...
   0.844688     libusb_get_interrupt: Connection timed out
   0.844967     Got 0 HID objects...
   0.845146     Quick update...
   0.846645     libusb_get_report: error sending control message: Broken pipe
   0.846875     Can't retrieve Report 61: Resource temporarily unavailable
   0.849641     libusb_get_report: error sending control message: Broken pipe
   0.849800     Can't retrieve Report 15: Resource temporarily unavailable
...
   0.870637     libusb_get_report: error sending control message: Broken pipe
   0.870797     Can't retrieve Report 32: Resource temporarily unavailable
   0.871359     dstate_init: sock /var/run/nut/usbhid-ups-upsserv7 open on fd 5
   0.871577     upsdrv_updateinfo...
   1.025495     Got 9 HID objects...
   1.025789     Path: UPS.PowerSummary.PresentStatus.InternalFailure, Type: Input, ReportID: 0x32, Offset: 7, Size: 1, Value: 0.000000
   1.025972     Path: UPS.PowerSummary.PresentStatus.ShutdownImminent, Type: Input, ReportID: 0x32, Offset: 9, Size: 1, Value: 0.000000
   1.026151     Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Input, ReportID: 0x32, Offset: 16, Size: 1, Value: 1.000000
   1.026326     Path: UPS.PowerSummary.PresentStatus.BelowRemainingCapacityLimit, Type: Input, ReportID: 0x32, Offset: 18, Size: 1, Value: 0.000000
   1.026500     Path: UPS.PowerSummary.PresentStatus.FullyCharged, Type: Input, ReportID: 0x32, Offset: 19, Size: 1, Value: 1.000000
   1.026649     Path: UPS.PowerSummary.PresentStatus.Charging, Type: Input, ReportID: 0x32, Offset: 20, Size: 1, Value: 0.000000
   1.026849     Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Input, ReportID: 0x32, Offset: 21, Size: 1, Value: 0.000000
   1.026999     Path: UPS.PowerSummary.PresentStatus.FullyDischarged, Type: Input, ReportID: 0x32, Offset: 22, Size: 1, Value: 0.000000
   1.027193     Path: UPS.PowerSummary.PresentStatus.NeedReplacement, Type: Input, ReportID: 0x32, Offset: 23, Size: 1, Value: 0.000000
   1.027326     Quick update...
   1.028619     libusb_get_report: error sending control message: Broken pipe
   1.028764     Can't retrieve Report 61: Resource temporarily unavailable
   1.031614     libusb_get_report: error sending control message: Broken pipe
   1.031793     Can't retrieve Report 15: Resource temporarily unavailable
   1.034614     libusb_get_report: error sending control message: Broken pipe
   1.034792     Can't retrieve Report 17: Resource temporarily unavailable
   1.034931     Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x32, Offset: 16, Size: 1, Value: 1.000000
...

- Kelvin