search

networkupstools / nut

The Network UPS Tools repository. UPS management protocol Informational RFC 9271 published by IETF at https://www.rfc-editor.org/info/rfc9271 Please star NUT on GitHub, this helps with sponsorships!
https://networkupstools.org/
Other
2.09k stars 351 forks source link

UPS equipment offline due to unknown reasons #2599

Open comozen opened 2 months ago

comozen commented 2 months ago 
Aug 22 08:48:51 mimozone usbhid-ups[562945]: nut_libusb_get_report: Input/Output Error
Aug 22 08:48:53 mimozone usbhid-ups[562945]: device->Product is NULL so it is not possible to determine whether to activate max_report_size workaround
Aug 22 08:48:53 mimozone usbhid-ups[562945]: libusb1: Could not open any HID devices: insufficient permissions on everything
Aug 22 08:48:53 mimozone nut-server[563918]: Data for UPS [ups] is stale - check driver
Aug 22 08:48:53 mimozone upsd[563918]: Data for UPS [ups] is stale - check driver
Aug 22 08:48:55 mimozone usbhid-ups[562945]: device->Product is NULL so it is not possible to determine whether to activate max_report_size workaround
Aug 22 08:48:55 mimozone usbhid-ups[562945]: libusb1: Could not open any HID devices: insufficient permissions on everything
Aug 22 08:48:57 mimozone nut-monitor[563325]: Poll UPS [ups@localhost] failed - Data stale
Aug 22 08:48:57 mimozone nut-monitor[563325]: Communications with UPS ups@localhost lost
Aug 22 08:48:57 mimozone usbhid-ups[562945]: device->Product is NULL so it is not possible to determine whether to activate max_report_size workaround
Aug 22 08:48:57 mimozone usbhid-ups[562945]: libusb1: Could not open any HID devices: insufficient permissions on everything
Aug 22 08:48:59 mimozone usbhid-ups[562945]: device->Product is NULL so it is not possible to determine whether to activate max_report_size workaround
Aug 22 08:48:59 mimozone usbhid-ups[562945]: libusb1: Could not open any HID devices: insufficient permissions on everything
Aug 22 08:49:01 mimozone usbhid-ups[562945]: device->Product is NULL so it is not possible to determine whether to activate max_report_size workaround
Aug 22 08:49:01 mimozone usbhid-ups[562945]: libusb1: Could not open any HID devices: insufficient permissions on everything

version:2.8.2 sataus:The device will go offline after a period of time, causing the driver to be unable to find the UPS device. Re plugging and unplugging the USB cable will allow the device to be found again Suspected to be caused by the automatic change of Bus 003 Device 007: ID 051d: 0002. Is there any way to avoid this problem

jimklimov commented 2 months ago

How is the device configured? The bus/device/port numbers indeed do depend on enumeration, so if the OS decided to change it (bus reset, something plugged/unplugged) we may be out of luck with fixed numbers. Do you have those options in ups.conf?

Another idea is that this UPS controller chip may be going to sleep - increasing the polling frequency might help.

This ID looks APC, but as they bought out a lot of companies, OEMs under the brand may differ in quality and ability. Which model is that, which country?

jimklimov commented 2 months ago

I think usbhid-ups should be smart enough by now to reconnect in case of some detected failures. Maybe it tit not recognize this one, although I/O Error should have triggered the attempt.

Can you please run the driver with higher verbosity, and post more debug context around such events? https://github.com/networkupstools/nut/wiki/Changing-NUT-daemon-debug-verbosity

Recent APC BX...MI models were also implicated in some unruly behavior that seems like calibration, issuing many scary reports, recently addressed on NUT master branch. But those cases did not report connection losses...

comozen commented 2 months ago

Thank you for your response. My ups.conf is as follows:

maxretry = 3
[ups]
  driver = usbhid-ups
  port = auto
  vendorid = 051d
  productid = 0002
  product = "BK650M2-CH"
  serial = "9B2015A09166"
  vendor = "American Power Conversion"
  pollonly = yes

My UPS model is APC BK650M2-CH

The current polling frequency is set to 5 seconds POLLFREQ 5

comozen commented 2 months ago

I think usbhid-ups should be smart enough by now to reconnect in case of some detected failures. Maybe it tit not recognize this one, although I/O Error should have triggered the attempt.我认为usbhid-ups现在应该足够聪明，可以在检测到某些故障时重新连接。也许它无法识别这一点，尽管 I/O 错误应该触发了该尝试。

Can you please run the driver with higher verbosity, and post more debug context around such events? https://github.com/networkupstools/nut/wiki/Changing-NUT-daemon-debug-verbosity您能否以更详细的方式运行驱动程序，并围绕此类事件发布更多调试上下文？ https://github.com/networkupstools/nut/wiki/Changing-NUT-daemon-debug-verbosity

Recent APC BX...MI models were also implicated in some unruly behavior that seems like calibration, issuing many scary reports, recently addressed on NUT master branch. But those cases did not report connection losses...最近的 APC BX...MI 模型也涉及一些看似校准的不守规矩的行为，发布了许多可怕的报告，最近在 NUT 主分支上得到了解决。但这些案例并没有报告连接丢失......

I have recorded the logs in the way you described, and the partial logs after reconnection are as follows. I am not sure if it is helpful to you.

If missing log information is needed, I will supplement it when the loss occurs,About ten hours later. Thanks again

Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] send_to_all: SETINFO driver.state "updateinfo"
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D6] send_to_all: write 34 bytes to socket 10 succeeded (ret=34): SETINFO driver.state "updateinfo"
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D1] upsdrv_updateinfo...
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D1] Not using interrupt pipe...
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D1] Quick update...
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D4] Entering libusb_get_report
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D3] Report[get]: (3 bytes) => 15 ff ff
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] PhyMax = 0, PhyMin = 0, LogMax = 32767, LogMin = -1
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] Unit = 00001001, UnitExp = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] Exponent = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D2] Path: UPS.PowerSummary.DelayBeforeShutdown, Type: Feature, ReportID: 0x15, Offset: 0, Size: 16, Value: -1
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D4] Entering libusb_get_report
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D2] refresh_report_buffer: expected 24 bytes, but got 2 instead
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D3] Report[err]: (2 bytes) => 40 00
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] Unit = 00f0d121, UnitExp = 7
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] Exponent = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D2] Path: UPS.APCGeneralCollection.APCDelayBeforeReboot, Type: Feature, ReportID: 0x40, Offset: 0, Size: 8, Value: 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D4] Entering libusb_get_report
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D2] refresh_report_buffer: expected 5 bytes, but got 3 instead
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D3] Report[err]: (3 bytes) => 16 0e 00
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] Unit = 00000000, UnitExp = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] Exponent = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D2] Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x16, Offset: 2, Size: 1, Value: 1
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] hu_find_infoval: found online (value: 1)
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] process_boolean_info: online
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D3] Report[buf]: (5 bytes) => 16 0e 00 00 00
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] Unit = 00000000, UnitExp = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] Exponent = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D2] Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Feature, ReportID: 0x16, Offset: 1, Size: 1, Value: 1
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] hu_find_infoval: found dischrg (value: 1)
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] process_boolean_info: dischrg
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D3] Report[buf]: (5 bytes) => 16 0e 00 00 00
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] Unit = 00000000, UnitExp = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] Exponent = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D2] Path: UPS.PowerSummary.PresentStatus.Charging, Type: Feature, ReportID: 0x16, Offset: 0, Size: 1, Value: 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] hu_find_infoval: found !chrg (value: 0)
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] process_boolean_info: !chrg
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D4] Entering libusb_get_report
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D3] Report[get]: (2 bytes) => 13 01
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] Unit = 00001001, UnitExp = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] Exponent = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D2] Path: UPS.PowerSummary.ACPresent, Type: Feature, ReportID: 0x13, Offset: 0, Size: 8, Value: 1
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] hu_find_infoval: found online (value: 1)
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] process_boolean_info: online
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D4] Entering libusb_get_report
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D3] Report[get]: (2 bytes) => 14 00
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] Unit = 00001001, UnitExp = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] Exponent = 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D2] Path: UPS.PowerSummary.BelowRemainingCapacityLimit, Type: Feature, ReportID: 0x14, Offset: 0, Size: 8, Value: 0
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] hu_find_infoval: found !lowbatt (value: 0)
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] process_boolean_info: !lowbatt
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] ups_status_set: current battery.charge=100 is okay compared to onlinedischarge_log_throttle_hovercharge=100 (previous onlinedischarge_log_throttle_charge=-1): charging
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D5] send_to_all: SETINFO driver.state "quiet"
Aug 23 10:37:03 mimozone usbhid-ups[1599682]: [D6] send_to_all: write 29 bytes to socket 10 succeeded (ret=29): SETINFO driver.state "quiet"
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] send_to_all: SETINFO driver.state "updateinfo"
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D6] send_to_all: write 34 bytes to socket 10 succeeded (ret=34): SETINFO driver.state "updateinfo"
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D1] upsdrv_updateinfo...
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D1] Not using interrupt pipe...
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D1] Quick update...
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D4] Entering libusb_get_report
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D3] Report[get]: (3 bytes) => 15 ff ff
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] PhyMax = 0, PhyMin = 0, LogMax = 32767, LogMin = -1
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] Unit = 00001001, UnitExp = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] Exponent = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D2] Path: UPS.PowerSummary.DelayBeforeShutdown, Type: Feature, ReportID: 0x15, Offset: 0, Size: 16, Value: -1
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D4] Entering libusb_get_report
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D2] refresh_report_buffer: expected 24 bytes, but got 2 instead
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D3] Report[err]: (2 bytes) => 40 00
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] PhyMax = 0, PhyMin = 0, LogMax = 255, LogMin = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] Unit = 00f0d121, UnitExp = 7
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] Exponent = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D2] Path: UPS.APCGeneralCollection.APCDelayBeforeReboot, Type: Feature, ReportID: 0x40, Offset: 0, Size: 8, Value: 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D4] Entering libusb_get_report
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D2] refresh_report_buffer: expected 5 bytes, but got 3 instead
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D3] Report[err]: (3 bytes) => 16 0e 00
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] Unit = 00000000, UnitExp = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] Exponent = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D2] Path: UPS.PowerSummary.PresentStatus.ACPresent, Type: Feature, ReportID: 0x16, Offset: 2, Size: 1, Value: 1
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] hu_find_infoval: found online (value: 1)
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] process_boolean_info: online
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D3] Report[buf]: (5 bytes) => 16 0e 00 00 00
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] Unit = 00000000, UnitExp = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] Exponent = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D2] Path: UPS.PowerSummary.PresentStatus.Discharging, Type: Feature, ReportID: 0x16, Offset: 1, Size: 1, Value: 1
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] hu_find_infoval: found dischrg (value: 1)
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] process_boolean_info: dischrg
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D3] Report[buf]: (5 bytes) => 16 0e 00 00 00
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] Unit = 00000000, UnitExp = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] Exponent = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D2] Path: UPS.PowerSummary.PresentStatus.Charging, Type: Feature, ReportID: 0x16, Offset: 0, Size: 1, Value: 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] hu_find_infoval: found !chrg (value: 0)
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] process_boolean_info: !chrg
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D4] Entering libusb_get_report
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D3] Report[get]: (2 bytes) => 13 01
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] Unit = 00001001, UnitExp = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] Exponent = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D2] Path: UPS.PowerSummary.ACPresent, Type: Feature, ReportID: 0x13, Offset: 0, Size: 8, Value: 1
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] hu_find_infoval: found online (value: 1)
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] process_boolean_info: online
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D4] Entering libusb_get_report
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D3] Report[get]: (2 bytes) => 14 00
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] PhyMax = 0, PhyMin = 0, LogMax = 1, LogMin = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] Unit = 00001001, UnitExp = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] Exponent = 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D2] Path: UPS.PowerSummary.BelowRemainingCapacityLimit, Type: Feature, ReportID: 0x14, Offset: 0, Size: 8, Value: 0
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] hu_find_infoval: found !lowbatt (value: 0)
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] process_boolean_info: !lowbatt
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] ups_status_set: current battery.charge=100 is okay compared to onlinedischarge_log_throttle_hovercharge=100 (previous onlinedischarge_log_throttle_charge=-1): charging
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D5] send_to_all: SETINFO driver.state "quiet"
Aug 23 10:37:05 mimozone usbhid-ups[1599682]: [D6] send_to_all: write 29 bytes to socket 10 succeeded (ret=29): SETINFO driver.state "quiet"
comozen commented 2 months ago

Also, provide my compilation parameters to see if there are any issues ./configure --with-user=ups --with-group=nut --prefix=/usr/local --with-nut-scanner --with-usb

comozen commented 2 months ago

This is the log from the time of the loss of contact

Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D5] send_to_all: SETINFO driver.state "updateinfo"
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D6] send_to_all: write 34 bytes to socket 10 succeeded (ret=34): SETINFO driver.state "updateinfo"
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] upsdrv_updateinfo...
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] Got to reconnect!
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D5] send_to_all: SETINFO driver.state "reconnect.trying"
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D6] send_to_all: write 40 bytes to socket 10 succeeded (ret=40): SETINFO driver.state "reconnect.trying"
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D4] Closing comm_driver previous handle
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D4] ===================================================================
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D4]  device has been disconnected, try to reconnect
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D4] ===================================================================
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D4] Opening comm_driver ...
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] Checking device 1 of 7 (1D6B/0003)
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] Failed to open device (1D6B/0003), skipping: Access denied (insufficient permissions)
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] Checking device 2 of 7 (05E3/0751)
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] Failed to open device (05E3/0751), skipping: Access denied (insufficient permissions)
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] Checking device 3 of 7 (067B/2586)
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] Failed to open device (067B/2586), skipping: Access denied (insufficient permissions)
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] Checking device 4 of 7 (051D/0002)
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iManufacturer failed, retrying...
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iManufacturer failed, retrying...
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iManufacturer failed, retrying...
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iProduct failed, retrying...
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iProduct failed, retrying...
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iProduct failed, retrying...
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iSerialNumber failed, retrying...
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iSerialNumber failed, retrying...
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iSerialNumber failed, retrying...
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] - VendorID: 051d
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] - ProductID: 0002
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] - Manufacturer: unknown
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] - Product: unknown
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] - Serial Number: unknown
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] - Bus: 003
Aug 23 14:41:31 mimozone nut-server[1573511]: Data for UPS [ups] is stale - check driver
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] - Bus Port: 004
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] - Device: 008
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] - Device release number: 0106
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] Trying to match device
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] match_function_subdriver (non-SHUT mode): matching a device...
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: device->Product is NULL so it is not possible to determine whether to activate max_report_size workaround
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D3] match_function_regex: matching a device...
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] match_function_regex: failed match of Vendor: (null)
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] Device does not match - skipping
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] Checking device 5 of 7 (1D6B/0002)
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] Failed to open device (1D6B/0002), skipping: Access denied (insufficient permissions)
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] Checking device 6 of 7 (1D6B/0003)
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] Failed to open device (1D6B/0003), skipping: Access denied (insufficient permissions)
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] Checking device 7 of 7 (1D6B/0002)
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D1] Failed to open device (1D6B/0002), skipping: Access denied (insufficient permissions)
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D2] libusb1: No appropriate HID device found
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: libusb1: Could not open any HID devices: insufficient permissions on everything
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D4] Opening comm_driver returns ret=-1
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D5] send_to_all: SETINFO driver.state "quiet"
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D6] send_to_all: write 29 bytes to socket 10 succeeded (ret=29): SETINFO driver.state "quiet"
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D5] send_to_all: DATASTALE
Aug 23 14:41:31 mimozone usbhid-ups[1599682]: [D6] send_to_all: write 10 bytes to socket 10 succeeded (ret=10): DATASTALE
Aug 23 14:41:31 mimozone upsd[1573511]: Data for UPS [ups] is stale - check driver
Aug 23 14:41:33 mimozone nut-monitor[1573561]: Poll UPS [ups@localhost] failed - Data stale
Aug 23 14:41:33 mimozone nut-monitor[1573561]: Communications with UPS ups@localhost lost
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D5] send_to_all: SETINFO driver.state "updateinfo"
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D6] send_to_all: write 34 bytes to socket 10 succeeded (ret=34): SETINFO driver.state "updateinfo"
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] upsdrv_updateinfo...
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] Got to reconnect!
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D5] send_to_all: SETINFO driver.state "reconnect.trying"
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D6] send_to_all: write 40 bytes to socket 10 succeeded (ret=40): SETINFO driver.state "reconnect.trying"
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D4] Not closing comm_driver previous handle: already closed
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D4] ===================================================================
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D4]  device has been disconnected, try to reconnect
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D4] ===================================================================
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D4] Opening comm_driver ...
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] Checking device 1 of 7 (1D6B/0003)
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] Failed to open device (1D6B/0003), skipping: Access denied (insufficient permissions)
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] Checking device 2 of 7 (05E3/0751)
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] Failed to open device (05E3/0751), skipping: Access denied (insufficient permissions)
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] Checking device 3 of 7 (067B/2586)
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] Failed to open device (067B/2586), skipping: Access denied (insufficient permissions)
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] Checking device 4 of 7 (051D/0002)
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iManufacturer failed, retrying...
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iManufacturer failed, retrying...
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iManufacturer failed, retrying...
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iProduct failed, retrying...
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iProduct failed, retrying...
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iProduct failed, retrying...
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iSerialNumber failed, retrying...
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iSerialNumber failed, retrying...
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] nut_libusb_open get iSerialNumber failed, retrying...
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] - VendorID: 051d
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] - ProductID: 0002
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] - Manufacturer: unknown
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] - Product: unknown
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] - Serial Number: unknown
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] - Bus: 003
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] - Bus Port: 004
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] - Device: 008
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] - Device release number: 0106
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] Trying to match device
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] match_function_subdriver (non-SHUT mode): matching a device...
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: device->Product is NULL so it is not possible to determine whether to activate max_report_size workaround
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D3] match_function_regex: matching a device...
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] match_function_regex: failed match of Vendor: (null)
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] Device does not match - skipping
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] Checking device 5 of 7 (1D6B/0002)
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] Failed to open device (1D6B/0002), skipping: Access denied (insufficient permissions)
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] Checking device 6 of 7 (1D6B/0003)
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] Failed to open device (1D6B/0003), skipping: Access denied (insufficient permissions)
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] Checking device 7 of 7 (1D6B/0002)
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D1] Failed to open device (1D6B/0002), skipping: Access denied (insufficient permissions)
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D2] libusb1: No appropriate HID device found
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: libusb1: Could not open any HID devices: insufficient permissions on everything
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D4] Opening comm_driver returns ret=-1
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D5] send_to_all: SETINFO driver.state "quiet"
Aug 23 14:41:33 mimozone usbhid-ups[1599682]: [D6] send_to_all: write 29 bytes to socket 10 succeeded (ret=29): SETINFO driver.state "quiet"
comozen commented 2 months ago

This is a log that has just returned to normal

usbhid-ups[1599682]: ups_status_set: seems that UPS [ups] is in OL+DISCHRG state now. Battery charge is currently 95. Is it calibrating (perhaps you want to set 'onlinedischarge_calibration' option)? Note that some UPS models (e.g. CyberPower UT series) emit OL+DISCHRG when in fact offline/on-battery (perhaps you want to set 'onlinedischarge_onbattery' option).
jimklimov commented 2 months ago

Thanks! So here it apparently did match the device-reported identification the first time around, but failed to read it during a reconnection attempt (which it did diligently start too, good). As a result, the "newly" located device lacked an "iManufacturer" string (NULL) to match the requested "Vendor" option ("American Power Conversion") in your config, so the device was not accepted as a match during reconnection.

As a quick fix, not matching by these strings (vendor, product, serial) where they can not be reliably read can help - if that is the only piece info that is not available. Try to comment those config lines away.

In practice, the bigger question is why it is not available - e.g. if the driver's hold on the device did not let the kernel/libusb re-read those strings, or if reconnection logic did not take some steps that the driver stop and initial connection does (e.g. fully close the device, let kernel report on it, then if it matches - take it from kernel), that I can not quickly say.

Given that your device later returned to be seen, maybe just its controller was restarting and was really not responsive for some time?..

But this part sounds reminiscent of an ongoing discussion in https://github.com/libusb/libusb/issues/1548 and #2571 / #1925 and maybe your situation would provide clues to re-producing or understanding that problem?.. :)

comozen commented 2 months ago

Thanks! So here it apparently did match the device-reported identification the first time around, but failed to read it during a reconnection attempt (which it did diligently start too, good). As a result, the "newly" located device lacked an "iManufacturer" string (NULL) to match the requested "Vendor" option ("American Power Conversion") in your config, so the device was not accepted as a match during reconnection.谢谢！因此，它显然在第一次时确实与设备报告的标识相匹配，但在重新连接尝试期间未能读取它（它也确实努力启动了，很好）。因此，“新”定位的设备缺少“iManufacturer”字符串（NULL）来匹配配置中请求的“供应商”选项（“American Power Conversion”），因此在重新连接期间该设备未被接受为匹配项。

As a quick fix, not matching by these strings (vendor, product, serial) where they can not be reliably read can help - if that is the only piece info that is not available. Try to comment those config lines away.作为一个快速解决方案，如果这些字符串（供应商、产品、序列号）无法可靠地读取，则不进行匹配可能会有所帮助 - 如果这是唯一不可用的信息。尝试注释掉这些配置行。

In practice, the bigger question is why it is not available - e.g. if the driver's hold on the device did not let the kernel/libusb re-read those strings, or if reconnection logic did not take some steps that the driver stop and initial connection does (e.g. fully close the device, let kernel report on it, then if it matches - take it from kernel), that I can not quickly say.实际上，更大的问题是为什么它不可用 - 例如，如果驱动程序对设备的持有不允许内核/libusb 重新读取这些字符串，或者重新连接逻辑没有采取驱动程序停止和初始连接的某些步骤确实（例如完全关闭设备，让内核报告它，然后如果它匹配 - 从内核获取它），我不能很快说。

Given that your device later returned to be seen, maybe just its controller was restarting and was really not responsive for some time?..鉴于您的设备后来又恢复可见，也许只是其控制器正在重新启动并且确实有一段时间没有响应？..

But this part sounds reminiscent of an ongoing discussion in libusb/libusb#1548 and #2571 / #1925 and maybe your situation would provide clues to re-producing or understanding that problem?.. :)但这部分听起来让人想起正在进行的讨论 libusb/libusb#1548 和 #2571 / #1925 也许您的情况会提供重现或理解该问题的线索？..:)

No, if the USB cable is not unplugged, it will keep reporting errors, at least for now. Additionally, I did not encounter this issue with 2.8.0 installed from apt, as it continuously reported the "OL+DISCHRG" status. It was only after compiling that I updated it to 2.8.2. Of course, this is another problem

I have tried to comment out these fields, and if there are any new developments, I will continue to report. Thank you for your guidance.

jimklimov commented 2 months ago

For an APC config, try setting onlinedischarge_calibration