APC Smart-UPS 1000 USB - ups.test.result: No test initiated and missing TIMELEFT

[nikolaysu]

APC Smart-UPS 1000 USB - ups.test.result: No test initiated and missing TIMELEFT

[desertwitch]

apcupsd TIMELEFT : 22.0 Minutes => NUT battery.runtime: 1380 (seconds = 23 minutes)
Not sure about last test, will take a look...

Can you provide us with the upsc output from the latest master build (or release 2.8.2) in the meantime?
Version 2.7.4 is extremely old at this point, just to be sure we're not missing something... 😄

[jimklimov]

I believe upscmd and upsrw by default send a command and return success quickly (if there were no NUT protocol errors). Since NUT v2.8.0 "tracking" is available (the -w flag) so these commands send a random-ish cookie and can wait for a driver-dictated result attached to that cookie - and discern that reply to their specific request from whatever other traffic passes on the bus.

Using -w -t NUM with a short timeout value (default 10) can be counter-productive if the device interaction takes long. Not sure OTOH what happens for calibration with this driver and hardware, but if theoretically the driver accepts the request, passes it to the device, and returns a verdict only when the device is done - the needed upscmd timeout may be in hours range to receive the ultimate answer to that original request to run a self-test.

Now that you've dug into the logic and comparisons for all of this, and have a device to test with, you may be in fact better positioned than myself to iterate with a custom driver - see https://github.com/networkupstools/nut/wiki/Building-NUT-for-in%E2%80%90place-upgrades-or-non%E2%80%90disruptive-tests

For starters, try adding different diagnostic print-outs into the driver with upsdebugx() to make sense of where it sets or clears the calibration verdict (per your "Done and passed" example that was seen for a while). Maybe it is the driver forgetting it after some loops (e.g. a major vs. minor update... or is that only in snmp-ups?..) or the device itself clearing that status in its reports e.g. after some time has passed or after the battery charge or other internal state has changed and the calibration verdict is no longer deemed trustworthy for whatever reasons the vendor thought of.

Regarding the other question, with synthetic variables - they have their place (e.g. when we do not know the battery charge from the device itself, but "guesstimate" it from known voltage and assumed high/low limits and some assumption about the discharge function over time). I don't think the NUT protocol (see docs/net-protocol.txt) has a way to discern synthetic values from those reported by the device (I certainly never saw any use of that in driver/client code even if it existed); at best there is a higher-level TYPE to tell apart numbers, strings, enums, etc. So as long as there is a suitable name for the concept in docs/nut-names.txt (or one gets negotiated on ups-dev mailing list to appear in the document), feel free to populate it meaningfully.

[nikolaysu]

Thanks for the detailed answer

For now, I hope that it is the UPS that is preventing this value from being obtained due to the fact that the test occurs too often.
I'll wait a week and check it out.
Debugging the driver looks quite difficult to me and will probably take a lot of time. But I will try to do this if the information is not collected in a week.

[jimklimov]

For the initial test, NUT is v2.7.4 or older, right?

As for missing values, CC @aquette @clepple @desertwitch : any ideas?

[nikolaysu]

For the initial test, NUT is v2.7.4 or older, right?

root@cell06:/usr/lib/nut# upsc -V
Network UPS Tools upscmd 2.7.4

root@cell06:/usr/lib/nut# /usr/lib/nut/usbhid-ups -V
Network UPS Tools - Generic HID driver 0.41 (2.7.4)
USB communication driver 0.33

[nikolaysu]

root@cell06:~/nut/clients# ./upsc -V
Network UPS Tools upsc 2.8.2-215-gc342e63a2

upsc [email protected]

root@cell06:~/nut/clients# ./upsc [email protected]
battery.charge: 100
battery.charge.low: 10
battery.charge.warning: 50
battery.mfr.date: 2020/03/01
battery.runtime: 1500
battery.runtime.low: 120
battery.temperature: 27.9
battery.type: PbAc
battery.voltage: 27.5
battery.voltage.nominal: 24.0
device.mfr: American Power Conversion
device.model: Smart-UPS 1000
device.serial: AS0451230660
device.type: ups
driver.name: usbhid-ups
driver.parameter.pollfreq: 30
driver.parameter.pollinterval: 2
driver.parameter.port: auto
driver.parameter.productid: 0002
driver.parameter.synchronous: no
driver.parameter.vendorid: 051d
driver.version: 2.7.4
driver.version.data: APC HID 0.96
driver.version.internal: 0.41
input.sensitivity: medium
input.transfer.high: 253
input.transfer.low: 204
input.voltage: 226.0
output.frequency: 50.0
output.voltage: 226.0
output.voltage.nominal: 230.0
ups.beeper.status: enabled
ups.delay.shutdown: 20
ups.delay.start: 30
ups.firmware: 600.3.I
ups.firmware.aux: 1.5
ups.load: 39.0
ups.mfr: American Power Conversion
ups.mfr.date: 2004/12/14
ups.model: Smart-UPS 1000
ups.productid: 0002
ups.serial: AS0451230660
ups.status: OL
ups.test.result: No test initiated
ups.timer.reboot: -1
ups.timer.shutdown: -1
ups.timer.start: -1
ups.vendorid: 051d
root@cell06:~/nut/clients#

[desertwitch]

driver.version: 2.7.4

You're still on NUT 2.7.4. on the machine where the UPS is physically connected.
It would be great if you could try it with NUT 2.8.2 or the current master (both driver + upsc for output). 😉

[nikolaysu]

i need

driver.version: 2.7.4

You're still on NUT 2.7.4. on the machine where the UPS is physically connected. It would be great if you could try it with NUT 2.8.2 or the current master (both driver + upsc for output). 😉

I need 10-15 minutes

[nikolaysu]

completely removed the NUT that I installed from the packages
installed from master branch

upsc [email protected]

root@cell06:/usr/local/ups/bin# /usr/local/ups/bin/upsc [email protected]
battery.charge: 100
battery.charge.low: 10
battery.charge.warning: 50
battery.mfr.date: 2020/03/01
battery.runtime: 1320
battery.runtime.low: 120
battery.temperature: 27.9
battery.type: PbAc
battery.voltage: 27.5
battery.voltage.nominal: 24.0
device.mfr: American Power Conversion
device.model: Smart-UPS 1000
device.serial: AS0451230660
device.type: ups
driver.debug: 0
driver.flag.allow_killpower: 0
driver.name: usbhid-ups
driver.parameter.pollfreq: 30
driver.parameter.pollinterval: 2
driver.parameter.port: auto
driver.parameter.productid: 0002
driver.parameter.synchronous: auto
driver.parameter.vendorid: 051d
driver.state: quiet
driver.version: 2.8.2-215-gc342e63a2
driver.version.data: APC HID 0.100
driver.version.internal: 0.53
driver.version.usb: libusb-1.0.22 (API: 0x1000106)
input.sensitivity: medium
input.transfer.high: 253
input.transfer.low: 204
input.voltage: 226.0
output.frequency: 50.0
output.voltage: 224.6
output.voltage.nominal: 230.0
ups.beeper.status: enabled
ups.delay.shutdown: 20
ups.delay.start: 30
ups.firmware: 600.3.I
ups.firmware.aux: 1.5
ups.load: 37.7
ups.mfr: American Power Conversion
ups.mfr.date: 2004/12/14
ups.model: Smart-UPS 1000
ups.productid: 0002
ups.serial: AS0451230660
ups.status: OL
ups.test.result: No test initiated
ups.timer.reboot: -1
ups.timer.shutdown: -1
ups.timer.start: -1
ups.vendorid: 051d

[desertwitch]

I've just looked into this and LASTSTEST is not a value actually reported through the HID (and read from the UPS), but rather a date/time variable that apcupsd calculates and stores itself. So there is some programmatic logic behind it, rather than being read "as is" from the UPS. It seems that when apcupsd sees the UPS in or exiting a self-testing state (although that detection does seem a bit fuzzy in the code), it stores that date in a variable and displays it as LASTSTEST. Not sure what NUT's stance on such (pseudo-)variables is, as opposed to actual readable/reported variables, and if that would be something worth looking into. On the one hand I could see it being a useful metric, but then again a hit-and-miss CAL detection (reporting a successful self test when there was in fact maybe none) may also lead users into a false sense of security... so not sure, @jimklimov ?

In any case, the runtime variable is there as it should be, it just has a different name in NUT. 😎
So this is more of a feature request now than missing readings after further investigations...

[nikolaysu]

First, thanks for the clarification about battery.runtime, this already in my Zabbix 👍
Second, i was experimenting with yesterday ups.test.result
If send command to test
/bin/upscmd -u admin -p admin [email protected] test.battery.start.quick
return
SUCCESS
And in the variable ups.test.result there was a value Done and passed which lasted for several minutes, then again became No test initiated
After the battery is charged, about 10 minutes. I repeated the experiment, but ups.test.result was No test initiated and did not change. I repeated the experiment today(10 hour left) and again ups.test.result was No test initiated from the beginning.
I also tried running Self-test with the -w parameter
/bin/upscmd -t 60 -w -u admin -p admin [email protected] test.battery.start.quick
The result is the same

There may be a reason in the self test period - in apcaccess parameter STESTI: 7 days.

I still don’t understand how I can get the result of a self-test:

• Does the output of the SUCCESS command /bin/upscmd matter or does it only mean that the command is complete?
• does the -w parameter have an effect on the usbhid-ups driver?

There is complete confusion with ups.test.result, but I will check it again after a week

I understand that this is apparently not the work of NUT. But maybe this will help someone in the future

[nikolaysu]

I would like to continue this discussion

At the moment I keep getting a value No test initiated

The first thing I noticed was when running the driver in debug mode
I compare with powercom(works via usbhid) connected on different host,

   0.013145	[D3] HID descriptor, method 1: (9 bytes) => 09 21 10 01 21 01 22 f3 f1
   0.013147	[D3] HID descriptor length (method 1) 61939
   0.013148	[D4] i=0, extra[i]=09, extra[i+1]=21
   0.013149	[D3] HID descriptor, method 2: (9 bytes) => 09 21 10 01 21 01 22 10 04
   0.013151	[D3] HID descriptor length (method 2) 1040
   0.013152	[D2] Warning: two different HID descriptors retrieved (Reportlen = 61939 vs. 1040)

Perhaps this is some kind of problem?

If you need to do some fine debugging of the code, I’m ready to do it, but I still don’t understand why I need to add a diagnostic output.
For now, if I look at the code, I see that the function receives the value

void upsdrv_updateinfo(void)
....

		if (HIDGetDataValue(udev, event[i], &value, poll_interval) != 1)
			continue;

HIDGetDataValue(libhid.c)-> get_item_buffered(libhid.c)->GetValue(hidparser.c)