NUT is not picking up accurate and timely data from APC UPS

[ausfas]

I'm using NUT add-on and integration in Home assistant. My UPS is APC BX1200.
The integration data is delayed and doesn't update after a certain point. In this situation, the charge level is stuck at 99% while I unplugged the USB and attached the PC with Power Chute personal edition and got it as 100%. Then reconnecting is back to RPi it shows 100%.Turn off the input to UPS so it dropped to 95-96% and after a while it again stuck at 99% showing charging as not 100% despite it being 100% (confirmed from Power Chute) but the integration doesn't pick it up. Also any changes are displayed with a delay of 1-2 mins.

Not sure why it reports up to 99% fine and not after that. Yesterday it got stuck at 95% then did the same process of connecting to Power Chute and back.

The Add-on always have log entries of can't write to PID fopen issues so not sure if that is the root cause or not as others have the same PID fopen error but have not reported this data stale issue.
I raised this issue with HA home-assistant/core#125723
and after investigation advised the issue is NUT package and should raise it in here.

Logs from the UPS NUT Add-on

Using subdriver: APC HID 0.98
Network UPS Tools - UPS driver controller 2.8.0
cont-init: info: /etc/cont-init.d/nut.sh exited 0
cont-init: info: running /etc/cont-init.d/nutclient.sh
cont-init: info: /etc/cont-init.d/nutclient.sh exited 0
s6-rc: info: service legacy-cont-init successfully started
s6-rc: info: service legacy-services: starting
services-up: info: copying legacy longrun upsd (no readiness notification)
services-up: info: copying legacy longrun upsmon (no readiness notification)
s6-rc: info: service legacy-services successfully started
[17:05:25] INFO: Starting the UPS information server...
   0.000000	fopen /run/nut/upsd.pid: No such file or directory
   0.000023	Could not find PID file '/run/nut/upsd.pid' to see if previous upsd instance is already running!

   0.000239	[D1] debug level is '1'
   0.000321	listening on 0.0.0.0 port 3493
   0.000490	Connected to UPS [APC]: usbhid-ups-APC
   0.001020	Running as foreground process, not saving a PID file
[17:05:26] INFO: Starting the UPS monitor and shutdown controller...
   0.000000	fopen /run/nut/upsmon.pid: No such file or directory
   0.000023	Could not find PID file to see if previous upsmon instance is already running!

   0.000253	Using power down flag file /etc/killpower
   0.000387	UPS: APC@localhost (primary) (power value 1)
   0.000401	[D1] debug level is '1'
   0.000427	[D1] debug level is '1'
   0.000432	Warning: running as one big root process by request (upsmon -p)
   0.000489	[D1] Saving PID 451 into /run/nut/upsmon.pid
Init SSL without certificate database
   0.002375	[D1] Trying to connect to UPS [APC@localhost]
   0.509793	User [email protected] logged into UPS [APC]
   0.003079	[D1] Logged into UPS APC@localhost

more

services-up: info: copying legacy longrun upsmon (no readiness notification)
s6-rc: info: service legacy-services successfully started
[01:16:21] INFO: �[32mStarting the UPS information server...�[0m
   0.000000	fopen /run/nut/upsd.pid: No such file or directory
   0.000033	Could not find PID file '/run/nut/upsd.pid' to see if previous upsd instance is already running!

   0.000275	[D1] debug level is '1'
   0.000385	listening on 0.0.0.0 port 3493
   0.000577	Connected to UPS [APC]: usbhid-ups-APC
   0.001142	Running as foreground process, not saving a PID file
[01:16:21] INFO: �[32mStarting the UPS monitor and shutdown controller...�[0m
   0.000000	fopen /run/nut/upsmon.pid: No such file or directory
   0.000019	Could not find PID file to see if previous upsmon instance is already running!

   0.000161	Using power down flag file /etc/killpower
   0.000262	UPS: APC@localhost (primary) (power value 1)
   0.000274	[D1] debug level is '1'
   0.000295	[D1] debug level is '1'
   0.000299	Warning: running as one big root process by request (upsmon -p)
   0.000346	[D1] Saving PID 459 into /run/nut/upsmon.pid
Init SSL without certificate database
   0.001996	[D1] Trying to connect to UPS [APC@localhost]
   0.009844	User [email protected] logged into UPS [APC]
   0.002661	[D1] Logged into UPS APC@localhost
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
{"message":"Event nut.ups_event fired."}Network UPS Tools upsmon 2.8.0
s6-rc: info: service legacy-services: stopping
244437.860096	Signal 15: exiting
244437.867746	User [email protected] logged out from UPS [APC]
244437.867963	Signal 15: exiting
244437.868090	[D1] driver_free: forgetting UPS [APC] (FD 4)
Network UPS Tools upsmon 2.8.0
Network UPS Tools upsd 2.8.0
[21:10:19] INFO: �[32mupsmon stopped, restarting...�[0m
[21:10:19] INFO: �[32mupsd stopped, restarting...�[0m
s6-rc: info: service legacy-services successfully stopped
s6-rc: info: service legacy-cont-init: stopping
s6-rc: info: service legacy-cont-init successfully stopped
s6-rc: info: service fix-attrs: stopping
s6-rc: info: service base-addon-timezone: stopping
s6-rc: info: service base-addon-log-level: stopping
s6-rc: info: service fix-attrs successfully stopped
s6-rc: info: service base-addon-timezone successfully stopped
s6-rc: info: service base-addon-log-level successfully stopped
s6-rc: info: service base-addon-banner: stopping
s6-rc: info: service base-addon-banner successfully stopped
s6-rc: info: service s6rc-oneshot-runner: stopping
s6-rc: info: service s6rc-oneshot-runner successfully stopped
s6-rc: info: service s6rc-oneshot-runner: starting
s6-rc: info: service s6rc-oneshot-runner successfully started
s6-rc: info: service base-addon-banner: starting

�[34m-----------------------------------------------------------�[0m
�[34m Add-on: Network UPS Tools�[0m
�[34m Manage battery backup (UPS) devices�[0m
�[34m-----------------------------------------------------------�[0m
�[34m Add-on version: 0.14.0�[0m
�[32m You are running the latest version of this add-on.�[0m
�[34m System: Home Assistant OS 14.1  (aarch64 / raspberrypi5-64)�[0m
�[34m Home Assistant Core: 2024.12.5�[0m
�[34m Home Assistant Supervisor: 2024.12.0�[0m
�[34m-----------------------------------------------------------�[0m
�[34m Please, share the above information when looking for help�[0m
�[34m or support in, e.g., GitHub, forums or the Discord chat.�[0m
�[34m-----------------------------------------------------------�[0m
s6-rc: info: service base-addon-banner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service base-addon-timezone: starting
s6-rc: info: service base-addon-log-level: starting
s6-rc: info: service fix-attrs successfully started
[21:10:28] INFO: �[32mConfiguring timezone (Australia/Sydney)...�[0m
s6-rc: info: service base-addon-log-level successfully started
s6-rc: info: service base-addon-timezone successfully started
s6-rc: info: service legacy-cont-init: starting
cont-init: info: running /etc/cont-init.d/nut.sh
[21:10:28] INFO: �[32mSetting mode to netserver...�[0m
[21:10:29] INFO: �[32mConnected USB devices:�[0m
Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 003 Device 002: ID 051d:0002 American Power Conversion Uninterruptible Power Supply
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
[21:10:29] INFO: �[32mGenerating /etc/nut/upsd.users...�[0m
[21:10:29] INFO: �[32mConfiguring user: admin-apc�[0m
[21:10:29] INFO: �[32mConfiguring Device named APC...�[0m
[21:10:29] INFO: �[32mStarting the UPS drivers...�[0m
HIDParse: LogMax is less than LogMin. Vendor HID report descriptor may be incorrect; interpreting LogMax -1 as 255 in ReportID: 0x0c
HIDParse: LogMax is less than LogMin. Vendor HID report descriptor may be incorrect; interpreting LogMax -1 as 255 in ReportID: 0x22
HIDParse: LogMax is less than LogMin. Vendor HID report descriptor may be incorrect; interpreting LogMax -1 as 255 in ReportID: 0x40
Using subdriver: APC HID 0.98
Network UPS Tools - Generic HID driver 0.47 (2.8.0)
USB communication driver (libusb 1.0) 0.43
Network UPS Tools - UPS driver controller 2.8.0
cont-init: info: /etc/cont-init.d/nut.sh exited 0
cont-init: info: running /etc/cont-init.d/nutclient.sh
cont-init: info: /etc/cont-init.d/nutclient.sh exited 0
s6-rc: info: service legacy-cont-init successfully started
s6-rc: info: service legacy-services: starting
services-up: info: copying legacy longrun upsd (no readiness notification)
services-up: info: copying legacy longrun upsmon (no readiness notification)
s6-rc: info: service legacy-services successfully started
[21:10:30] INFO: �[32mStarting the UPS information server...�[0m
   0.000000	fopen /run/nut/upsd.pid: No such file or directory
   0.000031	Could not find PID file '/run/nut/upsd.pid' to see if previous upsd instance is already running!

   0.000230	[D1] debug level is '1'
   0.000295	listening on 0.0.0.0 port 3493
   0.000453	Connected to UPS [APC]: usbhid-ups-APC
   0.000982	Running as foreground process, not saving a PID file
[21:10:30] INFO: �[32mStarting the UPS monitor and shutdown controller...�[0m
   0.000000	fopen /run/nut/upsmon.pid: No such file or directory
   0.000019	Could not find PID file to see if previous upsmon instance is already running!

   0.000179	Using power down flag file /etc/killpower
   0.000277	UPS: APC@localhost (primary) (power value 1)
   0.000289	[D1] debug level is '1'
   0.000316	[D1] debug level is '1'
   0.000319	Warning: running as one big root process by request (upsmon -p)
   0.000371	[D1] Saving PID 459 into /run/nut/upsmon.pid
Init SSL without certificate database
   0.001910	[D1] Trying to connect to UPS [APC@localhost]
   0.009844	User [email protected] logged into UPS [APC]
   0.003694	[D1] Logged into UPS APC@localhost

Same battery value of 98% with the utility

root@a0d7b954-nut:/# upsc APC | more
Init SSL without certificate database
battery.charge: 98
battery.charge.low: 10
battery.mfr.date: 2024/08/29
battery.runtime: 1910
battery.runtime.low: 120
battery.type: PbAc
battery.voltage: 13.5
battery.voltage.nominal: 12.0
device.mfr: American Power Conversion
device.model: Back-UPS BX1200MI
device.serial: xxx
device.type: ups
driver.name: usbhid-ups
driver.parameter.pollfreq: 30
driver.parameter.pollinterval: 2
driver.parameter.port: auto
driver.parameter.synchronous: auto
driver.version: 2.8.0
driver.version.data: APC HID 0.98
driver.version.internal: 0.47
driver.version.usb: libusb-1.0.26 (API: 0x1000109)
input.sensitivity: high
input.transfer.high: 290
input.transfer.low: 150
input.voltage: 234.0
input.voltage.nominal: 230
ups.beeper.status: disabled
ups.delay.shutdown: 20
ups.load: 15
ups.mfr: American Power Conversion
ups.mfr.date: 2024/01/29
ups.model: Back-UPS BX1200MI
ups.productid: 0002
ups.realpower.nominal: 650
ups.serial: xxx
ups.status: OL
ups.test.result: Done and passed
ups.timer.reboot: 0
ups.timer.shutdown: -1
ups.vendorid: 051d

then I unplugged the USB cable (from the RPi USB port) to APC UPS and plugged back in and restarted the add-on and the integration both integration and the the utility are reporting the battery state correctly.

Init SSL without certificate database
battery.charge: 100
battery.charge.low: 10
battery.mfr.date: 2024/08/29
battery.runtime: 1802
battery.runtime.low: 120
battery.type: PbAc
battery.voltage: 13.5
battery.voltage.nominal: 12.0
device.mfr: American Power Conversion
device.model: Back-UPS BX1200MI
device.serial: xx
device.type: ups
driver.name: usbhid-ups
driver.parameter.pollfreq: 30
driver.parameter.pollinterval: 2
driver.parameter.port: auto
driver.parameter.synchronous: auto
driver.version: 2.8.0
driver.version.data: APC HID 0.98
driver.version.internal: 0.47
driver.version.usb: libusb-1.0.26 (API: 0x1000109)
input.sensitivity: high
input.transfer.high: 290
input.transfer.low: 150
input.voltage: 232.0
input.voltage.nominal: 230
ups.beeper.status: disabled
ups.delay.shutdown: 20
ups.load: 16
ups.mfr: American Power Conversion
ups.mfr.date: 2024/01/29
ups.model: Back-UPS BX1200MI
ups.productid: 0002
ups.realpower.nominal: 650
ups.serial: xx
ups.status: OL
ups.test.result: Done and passed
ups.timer.reboot: 0
ups.timer.shutdown: -1
ups.vendorid: 051d

[jimklimov]

I can only guess the driver reports what the UPS controller firmware tells it, and maybe that controller gets stuck. Probably the act of USB connection re-plug (when you switched to PC with powerchute and back, or in the later test) resets the state of that controller or even reboots it.

If that is the case, you might have some luck with software-driven reset of the USB connection without physical re-plugging, see e.g. https://github.com/networkupstools/nut/tree/master/scripts/usb_resetter

Note that this may need extra hardware (an honestly-made USB hub that honours the individual port reset commands) if your built-in ports do not implement them as required by spec, or act as whole-hub reset and mess up your other devices on other ports. Too many vendors cut corners or otherwise can not read the spec, alas...