Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Persistent usbhid-ups[7209]: nut_libusb_get_report: Input/Output Error #2854

Open
grainsoflight opened this issue Mar 18, 2025 · 16 comments
Open

Persistent usbhid-ups[7209]: nut_libusb_get_report: Input/Output Error #2854

grainsoflight opened this issue Mar 18, 2025 · 16 comments
Labels
CyberPower (CPS) impacts-release-2.8.0 Issues reported against NUT release 2.8.0 (maybe vanilla or with minor packaging tweaks) impacts-release-2.8.2 Issues reported against NUT release 2.8.2 (maybe vanilla or with minor packaging tweaks) unraid Integration of NUT into unraid OS USB

Comments

@grainsoflight
Copy link

grainsoflight commented Mar 18, 2025 •
edited
Loading

NUT persistently output 'usbhid-ups[7209]: nut_libusb_get_report: Input/Output Error' though it appears to be running fine.

nut-debug-20250318181700.zip
@jimklimov
Copy link
Member

Looking at logs, you seem to be running NUT v2.8.0 variant. Can you please try recent versions, or master-branch builds? Maybe @desertwitch can help about that, as it seems you're running UNRAID...

@grainsoflight
Copy link
Author

I get more errors on 2.8.2

Mar 19 00:44:56 cloud usbhid-ups[6819]: #012Reconnecting. If you saw "nut_libusb_get_interrupt: Input/Output Error" or similar message in the log above, try setting "pollonly" flag in "ups.conf" options section for this driver!
Mar 19 00:44:56 cloud usbhid-ups[6819]: nut_libusb_get_string: Input/Output Error

@grainsoflight
Copy link
Author

Using on latest (nut-2.8.2-x86_64-7master.ssl31) gives the same errors

@jimklimov jimklimov added unraid Integration of NUT into unraid OS impacts-release-2.8.0 Issues reported against NUT release 2.8.0 (maybe vanilla or with minor packaging tweaks) impacts-release-2.8.2 Issues reported against NUT release 2.8.2 (maybe vanilla or with minor packaging tweaks) USB labels Mar 19, 2025
@jimklimov
Copy link
Member

And did you set pollonly in config as it recommends? Does it have any good/bad effect?

@grainsoflight
Copy link
Author

What syntax would I use to add that to the ups.conf

@jimklimov
Copy link
Member

Reading man pages and other docs generally helps :)
https://networkupstools.org/docs/man/usbhid-ups.html

In the section for the device config, add pollonly as a standalone line (it is a flag, so presence means enabled).

@grainsoflight
Copy link
Author

Then no, it doesnt work

@grainsoflight
Copy link
Author

Nevermind, it was not saving the flag because a setting needed to be changed, now it appears to be working

@grainsoflight
Copy link
Author

Spoke too soon Mar 19 19:03:29 cloud usbhid-ups[270750]: nut_libusb_get_report: Input/Output Error

@jimklimov
Copy link
Member

jimklimov commented Mar 20, 2025 •
edited
Loading

Can you also add debug_min=6 for a while, to collect details about how it initializes the device driver and at what point it complains? (Later disable the logging, so it would not thrash your storage)

I wonder if this is related to fixes in master after 2.8.2, like #2604 (so the error is not so much of communications as of interpreting the data as usable).

@grainsoflight
Copy link
Author

Of course now that debugging is is on I dont get the error

@grainsoflight
Copy link
Author

The log is just this repeating now

Mar 19 19:26:33 cloud usbhid-ups[331365]: [D5:331365] send_to_all: SETINFO driver.state "quiet"
Mar 19 19:26:33 cloud usbhid-ups[331365]: [D6:331365] send_to_all: write 29 bytes to socket 5 succeeded (ret=29): SETINFO driver.state "quiet"
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] send_to_all: SETINFO driver.state "updateinfo"
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D6:331365] send_to_all: write 34 bytes to socket 5 succeeded (ret=34): SETINFO driver.state "updateinfo"
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D1:331365] upsdrv_updateinfo...
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D1:331365] Not using interrupt pipe...
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D1:331365] Quick update...
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D4:331365] Entering libusb_get_report
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D3:331365] Report[get]: (3 bytes) => 16 ff ff
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] PhyMax = 1966020, PhyMin = -60, LogMax = 32767, LogMin = -1
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] Unit = 00001001, UnitExp = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] Exponent = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D2:331365] Path: UPS.Output.DelayBeforeStartup, Type: Feature, ReportID: 0x16, Offset: 0, Size: 16, Value: -60
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D4:331365] Entering libusb_get_report
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D3:331365] Report[get]: (3 bytes) => 15 ff ff
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] PhyMax = 1966020, PhyMin = -60, LogMax = 32767, LogMin = -1
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] Unit = 00001001, UnitExp = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] Exponent = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D2:331365] Path: UPS.Output.DelayBeforeShutdown, Type: Feature, ReportID: 0x15, Offset: 0, Size: 16, Value: -60
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D4:331365] Entering libusb_get_report
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D3:331365] Report[get]: (2 bytes) => 0b 11
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] Unit = 00000000, UnitExp = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] Exponent = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D2:331365] Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x0b, Offset: 0, Size: 1, Value: 1
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] hu_find_infoval: found online (value: 1)
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] process_boolean_info: online
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D3:331365] Report[buf]: (2 bytes) => 0b 11
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] Unit = 00000000, UnitExp = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] Exponent = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D2:331365] Path: UPS.PowerSummary.PresentStatus.Charging, Type: Feature, ReportID: 0x0b, Offset: 1, Size: 1, Value: 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] hu_find_infoval: found !chrg (value: 0)
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] process_boolean_info: !chrg
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D3:331365] Report[buf]: (2 bytes) => 0b 11
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] Unit = 00000000, UnitExp = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] Exponent = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D2:331365] Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Feature, ReportID: 0x0b, Offset: 2, Size: 1, Value: 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] hu_find_infoval: found !dischrg (value: 0)
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] process_boolean_info: !dischrg
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D3:331365] Report[buf]: (2 bytes) => 0b 11
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] Unit = 00000000, UnitExp = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] Exponent = 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D2:331365] Path: UPS.PowerSummary.PresentStatus.BelowRemainingCapacityLimit, Type: Feature, ReportID: 0x0b, Offset: 3, Size: 1, Value: 0
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] hu_find_infoval: found !lowbatt (value: 0)
Mar 19 19:26:35 cloud usbhid-ups[331365]: [D5:331365] process_boolean_info: !lowbatt

@grainsoflight
Copy link
Author

grainsoflight commented Mar 20, 2025 •
edited
Loading

Ok, it finally errored

Mar 19 19:32:01 cloud usbhid-ups[331365]: [D5:331365] hu_find_infoval: found !lowbatt (value: 0)
Mar 19 19:32:01 cloud usbhid-ups[331365]: [D5:331365] process_boolean_info: !lowbatt
Mar 19 19:32:01 cloud usbhid-ups[331365]: [D5:331365] send_to_all: SETINFO driver.state "quiet"
Mar 19 19:32:01 cloud usbhid-ups[331365]: [D6:331365] send_to_all: write 29 bytes to socket 5 succeeded (ret=29): SETINFO driver.state "quiet"
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D5:331365] send_to_all: SETINFO driver.state "updateinfo"
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D6:331365] send_to_all: write 34 bytes to socket 5 succeeded (ret=34): SETINFO driver.state "updateinfo"
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D1:331365] upsdrv_updateinfo...
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D1:331365] Not using interrupt pipe...
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D1:331365] Quick update...
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D4:331365] Entering libusb_get_report
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D3:331365] Report[get]: (3 bytes) => 16 ff ff
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D5:331365] PhyMax = 1966020, PhyMin = -60, LogMax = 32767, LogMin = -1
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D5:331365] Unit = 00001001, UnitExp = 0
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D5:331365] Exponent = 0
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D2:331365] Path: UPS.Output.DelayBeforeStartup, Type: Feature, ReportID: 0x16, Offset: 0, Size: 16, Value: -60
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D4:331365] Entering libusb_get_report
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D3:331365] Report[get]: (3 bytes) => 15 ff ff
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D5:331365] PhyMax = 1966020, PhyMin = -60, LogMax = 32767, LogMin = -1
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D5:331365] Unit = 00001001, UnitExp = 0
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D5:331365] Exponent = 0
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D2:331365] Path: UPS.Output.DelayBeforeShutdown, Type: Feature, ReportID: 0x15, Offset: 0, Size: 16, Value: -60
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D4:331365] Entering libusb_get_report
Mar 19 19:32:03 cloud usbhid-ups[331365]: nut_libusb_get_report: Input/Output Error
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D1:331365] Can't retrieve Report 0b: Operation not permitted
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D5:331365] send_to_all: SETINFO driver.state "reconnect.trying"
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D6:331365] send_to_all: write 40 bytes to socket 5 succeeded (ret=40): SETINFO driver.state "reconnect.trying"
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D5:331365] send_to_all: SETINFO driver.state "quiet"
Mar 19 19:32:03 cloud usbhid-ups[331365]: [D6:331365] send_to_all: write 29 bytes to socket 5 succeeded (ret=29): SETINFO driver.state "quiet"
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D5:331365] send_to_all: SETINFO driver.state "updateinfo"
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D6:331365] send_to_all: write 34 bytes to socket 5 succeeded (ret=34): SETINFO driver.state "updateinfo"
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D1:331365] upsdrv_updateinfo...
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D1:331365] Got to reconnect!
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D5:331365] send_to_all: SETINFO driver.state "reconnect.trying"
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D6:331365] send_to_all: write 40 bytes to socket 5 succeeded (ret=40): SETINFO driver.state "reconnect.trying"
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D4:331365] Closing comm_driver previous handle
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D4:331365] ===================================================================
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D4:331365] device has been disconnected, try to reconnect
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D4:331365] ===================================================================
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D4:331365] Opening comm_driver ...
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] Checking device 1 of 13 (174C/3074)
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] - VendorID: 174c
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] - ProductID: 3074
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] - Manufacturer: Asmedia
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] - Product: ASM107x
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] - Serial Number: unknown
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] - Bus: 002
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] - Bus Port: 003
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] - Device: 002
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] - Device release number: 0200
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] Trying to match device
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] match_function_subdriver (non-SHUT mode): matching a device...
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] match_function_subdriver (non-SHUT mode): failed to match a subdriver to vendor and/or product ID
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] Device does not match - skipping
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] Checking device 2 of 13 (1D6B/0003)
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D1:331365] nut_libusb_open: invalid libusb bus number 0
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] - VendorID: 1d6b
Mar 19 19:32:05 cloud usbhid-ups[331365]: [D2:331365] - ProductID: 0003

@jimklimov
Copy link
Member

Aha, thanks. So the message is not all too benign - the driver reconnects afterwards.

  • The "match ... failed" that you highlighted is not a problem, or at least not that instance of it - the driver walks all (13) devices libusb sees, and quickly discards those that did not match configuration or built-in criteria like vendor and product IDs

Seeing how you have a CPS device, check these Wiki pages:

Notably, you may benefit from a more frequent USB polling so the UPS controller does not fall asleep.

Also checked, this does not seem to be what #2604 fixed after all, I think...

@grainsoflight
Copy link
Author

Unfortunately changing the polling interval didnt seem to help, unless I dont have a concept of what is should be. I tried 0.2, 0.5 and 1 second

@jimklimov
Copy link
Member

IIRC drivers' default is 30 sec, so reduced values around 5-10 sec should be good for CPS... assuming that is the issue leading to reconnects.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
CyberPower (CPS) impacts-release-2.8.0 Issues reported against NUT release 2.8.0 (maybe vanilla or with minor packaging tweaks) impacts-release-2.8.2 Issues reported against NUT release 2.8.2 (maybe vanilla or with minor packaging tweaks) unraid Integration of NUT into unraid OS USB
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@jimklimov @grainsoflight