nut spamming syslog with Input/Output Errors

[xorbug]

nut spamming syslog with Input/Output Errors

[jimklimov]

Well, it does look like those issues... could you check if a physical or software (usbreset) reconnection helps? Are there syslog or dmesg events that seem relevant just before it would start spamming?

[jimklimov]

At least this does not seem to be a spam flood that would bring the server down (by cpu load or storage), with bursts of a dozen messages every 5-7 minutes here. It is irregular, right?

[xorbug]

Well, it does look like those issues... could you check if a physical or software (usbreset) reconnection helps? Are there syslog or dmesg events that seem relevant just before it would start spamming?

I'm sure I tried this already without success, but here is a more thorough test.

• usbreset:

2023-09-21T15:08:03.243891+02:00 <hostname> kernel: [235172.062225] usb 1-3: reset low-speed USB device number 2 using xhci_hcd
2023-09-21T15:08:03.687876+02:00 <hostname> kernel: [235172.508040] hid-generic 0003:1CB0:0032.0002: hiddev0,hidraw0: USB HID v1.11 Device [Legrand   Legrand UPS  ] on usb-0000:00:14.0-3/input0
2023-09-21T15:08:03.739838+02:00 <hostname> kernel: [235172.561642] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:03.739859+02:00 <hostname> kernel: [235172.561709] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:03.739870+02:00 <hostname> kernel: [235172.561719] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:03.739874+02:00 <hostname> kernel: [235172.561727] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:03.741004+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:03.741456+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:03.741503+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:03.741546+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:05.740262+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:05.740444+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:05.740490+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:05.740533+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:05.743902+02:00 <hostname> kernel: [235174.561723] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:05.743910+02:00 <hostname> kernel: [235174.561774] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:05.743911+02:00 <hostname> kernel: [235174.561797] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:05.743912+02:00 <hostname> kernel: [235174.561805] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:07.741126+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:07.741429+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:07.741584+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:07.741734+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:07.743903+02:00 <hostname> kernel: [235176.562023] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:07.743923+02:00 <hostname> kernel: [235176.562142] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:07.743927+02:00 <hostname> kernel: [235176.562175] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:07.743929+02:00 <hostname> kernel: [235176.562203] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:09.743172+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:09.743494+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:09.743657+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:09.743849+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:09.743911+02:00 <hostname> kernel: [235178.564032] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:09.743923+02:00 <hostname> kernel: [235178.564144] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:09.743926+02:00 <hostname> kernel: [235178.564176] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:09.743928+02:00 <hostname> kernel: [235178.564203] usb 1-3: usbfs: process 11214 (usbhid-ups) did not claim interface 0 before use
2023-09-21T15:08:11.744806+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:11.745111+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:11.745271+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:11.745421+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:11.747895+02:00 <hostname> kernel: [235180.565593] usb 1-3: usbfs: process 11214 (usbhid-ups) did not clai
m interface 0 before use                                                        
2023-09-21T15:08:11.747902+02:00 <hostname> kernel: [235180.565705] usb 1-3: usbfs: process 11214 (usbhid-ups) did not clai
m interface 0 before use                                                        
2023-09-21T15:08:11.747904+02:00 <hostname> kernel: [235180.565736] usb 1-3: usbfs: process 11214 (usbhid-ups) did not clai
m interface 0 before use                                                        
2023-09-21T15:08:11.747904+02:00 <hostname> kernel: [235180.565762] usb 1-3: usbfs: process 11214 (usbhid-ups) did not clai
m interface 0 before use                                                        
2023-09-21T15:08:13.745652+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:13.746067+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:13.746322+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
2023-09-21T15:08:13.746536+02:00 <hostname> usbhid-ups[11214]: nut_libusb_get_report: Input/Output Error
...

On and on until restarting the whole nut stack.

• Hardware reset (unplug/replug right?):

...
2023-09-21T18:00:33.678918+02:00 <hostname> usbhid-ups[106304]: nut_libusb_get_report: No such device (it may have been disconnected)
...

A bunch of these messages also after re-plugging the cable, again until restarting nut. At that point the monitoring is up again and the spamming is back too.

in both cases can't see any relevant event in system logs.

At least this does not seem to be a spam flood that would bring the server down (by cpu load or storage), with bursts of a dozen messages every 5-7 minutes here. It is irregular, right?

It's irregularly constant and continuous, yes (like bursts of about 5 messages anytime between 30 sec. to 10 min. roughly, I ignore the exact values but you get the idea).

EDIT: To expand on the last point, in case it's useful for investigating the issue, I attach a file showing the bursts timestamp and the number of messages in them (obtained by journalctl --boot 0 | grep 'nut_libusb_get_report: Input/Output Error' | cut -d ' ' -f 3 | uniq -c, to which I also appended the time delta between two consecutive bursts to make that clearer). Still no apparent correlation to any triggering event tho.
nut_libusb_get_report+delta.log

[xorbug]

Turns out that as long as this condition is ongoing and the syslog is getting spammed, the automatic shutdown sequence doesn't work. In fact upsd -c fsd only shuts down the server and not the ups, and that should be because:

# upsdrvctl shutdown
Network UPS Tools - UPS driver controller 2.8.0
Network UPS Tools - Generic HID driver 0.47 (2.8.0)
USB communication driver (libusb 1.0) 0.43
interrupt pipe disabled (add 'pollonly' flag to 'ups.conf' to get rid of this message)
Can't claim USB device [1cb0:0032]@0/0: Entity not found
Driver failed to start (exit status=1)

Then it only works after a restart of the nut stack, or an usbreset, even if in the latter case the logs are then spammed by:

usb 1-3: usbfs: process 861 (usbhid-ups) did not claim interface 0 before use

So my temporary workaround for this has been setting SHUTDOWNCMD to usbreset <device> && poweroff. This should be enough to make the call to upsdrvctl shutdown succeed during the last stages of the shutdown procedure. Probably not 100% reliable (it's somewhat of a race condition anyway before the issue starts again) but seems to work... better than nothing.

(Always take this with a grain of salt as I couldn't carry out extensive tests for obvious reasons, but I could confirm all this quite a bit of times in a row yes.)