upscmd -w always says ERR FAILED with Vultech UPS1400VA-LFP UPS

[rapperskull]

As per title, if I execute a command on the Vultech UPS1400VA-LFP UPS and wait for the response, I always get ERR FAILED.

This happens also if the command is successfully executed and produces an effect.

How can I check if this a problem with the UPS or with the driver?

Thank you.

[jimklimov]

Bump debugging to 6 in server and driver (see wiki, you can flip it at run-time with modern NUT versions), watch what happens in their log (e.g. journal of nut-server and nut-driver@upsname).

OTOH, there may be mishaps due to some mass refactoring where some if/else or switch stack of handlers ended with some logic after it (assumed to be default unknown command or something). At least, this is a common risk of big similarly-looking routine changes...

[rapperskull]

nut-server

dic 22 22:08:10 rapperskull nut-server[2962]: Instant command: admin@127.0.0.1 did test.battery.start.quick on vultech (tracking ID: F4F78A1F-D59B-4F21-82C6-9729871FA9DC)
dic 22 22:08:10 rapperskull upsd[2962]: Instant command: admin@127.0.0.1 did test.battery.start.quick on vultech (tracking ID: F4F78A1F-D59B-4F21-82C6-9729871FA9DC)
dic 22 22:08:11 rapperskull nut-server[2962]: tracking ID: F4F78A1F-D59B-4F21-82C6-9729871FA9DC        result: ERR FAILED
dic 22 22:08:11 rapperskull upsd[2962]: tracking ID: F4F78A1F-D59B-4F21-82C6-9729871FA9DC        result: ERR FAILED

nut-driver

dic 22 22:08:10 rapperskull nut-driver@vultech[111976]:  133.585418        [D6] sock_arg: Driver on /var/state/ups/nutdrv_qx-vultech is now handling INSTCMD with 4 args
dic 22 22:08:10 rapperskull nut-driver@vultech[111976]:  133.585473        [D3] sock_arg: TRACKING = F4F78A1F-D59B-4F21-82C6-9729871FA9DC
dic 22 22:08:10 rapperskull nut-driver@vultech[111976]:  133.585488        [D2] entering main_instcmd(test.battery.start.quick, (null)) for [vultech] on socket 10
dic 22 22:08:10 rapperskull nut-driver@vultech[111976]:  133.585500        [D2] shared main_instcmd() does not handle command test.battery.start.quick, proceeding to driver-specific handler
dic 22 22:08:10 rapperskull nut-driver@vultech[111976]:  133.585511        [D1] Starting nutdrv_qx.c::instcmd('test.battery.start.quick', '(null)')
dic 22 22:08:10 rapperskull nut-driver@vultech[111976]:  133.585521        instcmd(test.battery.start.quick, [NULL])
dic 22 22:08:10 rapperskull nut-driver@vultech[111976]:  133.585536        instcmd: attempting an operation [test.battery.start.quick] [(null)] which may impact power state on [vultech]
dic 22 22:08:10 rapperskull nut-driver@vultech[111976]:  133.585549        [D2] armac_command: strlen(cmd) > cmdlen (provided by caller), would effectively truncate!
dic 22 22:08:10 rapperskull nut-driver@vultech[111976]:  133.585560        [D4] armac command T
dic 22 22:08:10 rapperskull nutdrv_qx[111976]: [D6] sock_arg: Driver on /var/state/ups/nutdrv_qx-vultech is now handling INSTCMD with 4 args
dic 22 22:08:10 rapperskull nutdrv_qx[111976]: [D3] sock_arg: TRACKING = F4F78A1F-D59B-4F21-82C6-9729871FA9DC
dic 22 22:08:10 rapperskull nutdrv_qx[111976]: [D2] entering main_instcmd(test.battery.start.quick, (null)) for [vultech] on socket 10
dic 22 22:08:10 rapperskull nutdrv_qx[111976]: [D2] shared main_instcmd() does not handle command test.battery.start.quick, proceeding to driver-specific handler
dic 22 22:08:10 rapperskull nutdrv_qx[111976]: [D1] Starting nutdrv_qx.c::instcmd('test.battery.start.quick', '(null)')
dic 22 22:08:10 rapperskull nutdrv_qx[111976]: instcmd(test.battery.start.quick, [NULL])
dic 22 22:08:10 rapperskull nutdrv_qx[111976]: instcmd: attempting an operation [test.battery.start.quick] [(null)] which may impact power state on [vultech]
dic 22 22:08:10 rapperskull nutdrv_qx[111976]: [D2] armac_command: strlen(cmd) > cmdlen (provided by caller), would effectively truncate!
dic 22 22:08:10 rapperskull nutdrv_qx[111976]: [D4] armac command T
dic 22 22:08:11 rapperskull nut-driver@vultech[111976]:  134.588331        [D1] interrupt read error: Operation timed out (-7)
dic 22 22:08:11 rapperskull nut-driver@vultech[111976]:  134.588383        [D4] qx_process: failed to preprocess answer [test.battery.start.quick]
dic 22 22:08:11 rapperskull nut-driver@vultech[111976]:  134.588398        instcmd: FAILED
dic 22 22:08:11 rapperskull nut-driver@vultech[111976]:  134.588413        [D2] send_to_one: sending TRACKING F4F78A1F-D59B-4F21-82C6-9729871FA9DC 3
dic 22 22:08:11 rapperskull nut-driver@vultech[111976]:  134.588424        [D5] send_to_one: TRACKING F4F78A1F-D59B-4F21-82C6-9729871FA9DC 3
dic 22 22:08:11 rapperskull nut-driver@vultech[111976]:  134.588441        [D6] send_to_one: write 48 bytes to socket 10 succeeded (ret=48): TRACKING F4F78A1F-D59B-4F21-82C6-9729871FA9DC 3
dic 22 22:08:11 rapperskull nut-driver@vultech[111976]:  134.588469        [D5] send_to_all: SETINFO driver.state "updateinfo"
dic 22 22:08:11 rapperskull nut-driver@vultech[111976]:  134.588483        [D6] send_to_all: write 34 bytes to socket 10 succeeded (ret=34): SETINFO driver.state "updateinfo"
dic 22 22:08:11 rapperskull nut-driver@vultech[111976]:  134.588494        [D1] upsdrv_updateinfo...
dic 22 22:08:11 rapperskull nut-driver@vultech[111976]:  134.588508        [D1] Quick update...
dic 22 22:08:11 rapperskull nutdrv_qx[111976]: [D1] interrupt read error: Operation timed out (-7)
dic 22 22:08:11 rapperskull nut-driver@vultech[111976]:  134.588523        [D2] armac_command: strlen(cmd) > cmdlen (provided by caller), would effectively truncate!
dic 22 22:08:11 rapperskull nut-driver@vultech[111976]:  134.588535        [D4] armac command Q1
dic 22 22:08:11 rapperskull nutdrv_qx[111976]: [D4] qx_process: failed to preprocess answer [test.battery.start.quick]
dic 22 22:08:11 rapperskull nutdrv_qx[111976]: instcmd: FAILED
dic 22 22:08:11 rapperskull nutdrv_qx[111976]: [D2] send_to_one: sending TRACKING F4F78A1F-D59B-4F21-82C6-9729871FA9DC 3
dic 22 22:08:11 rapperskull nutdrv_qx[111976]: [D5] send_to_one: TRACKING F4F78A1F-D59B-4F21-82C6-9729871FA9DC 3
dic 22 22:08:11 rapperskull nutdrv_qx[111976]: [D6] send_to_one: write 48 bytes to socket 10 succeeded (ret=48): TRACKING F4F78A1F-D59B-4F21-82C6-9729871FA9DC 3
dic 22 22:08:11 rapperskull nutdrv_qx[111976]: [D5] send_to_all: SETINFO driver.state "updateinfo"
dic 22 22:08:11 rapperskull nutdrv_qx[111976]: [D6] send_to_all: write 34 bytes to socket 10 succeeded (ret=34): SETINFO driver.state "updateinfo"
dic 22 22:08:11 rapperskull nutdrv_qx[111976]: [D1] upsdrv_updateinfo...
dic 22 22:08:11 rapperskull nutdrv_qx[111976]: [D1] Quick update...
dic 22 22:08:11 rapperskull nutdrv_qx[111976]: [D2] armac_command: strlen(cmd) > cmdlen (provided by caller), would effectively truncate!
dic 22 22:08:11 rapperskull nutdrv_qx[111976]: [D4] armac command Q1

Looks like the error is interrupt read error: Operation timed out (-7). Probably coming from here?

nut/drivers/nutdrv_qx.c

Lines 2335 to 2338 in 783d2fa

	upsdebugx(1,
	"interrupt read error: %s (%d)",
	ret ? nut_usb_strerror(ret) : "timeout",
	ret);

[jimklimov]

To me, this looks worrysome: armac_command: strlen(cmd) > cmdlen (provided by caller), would effectively truncate! dic 22 22:08:11 rapperskull nutdrv_qx[111976]: [D4] armac command Q1 - maybe rebuilding the driver with some better logging (what string is passed, what lengths are involved as its length and the limit) can help figure this out. I think an incomplete command may get passed to the device, so it gets confused and does not reply meaningfully.

[jimklimov]

Looks like the error is interrupt read error

Per context around the code you linked to, the driver waits for 1000ms and does not get read_size bytes. Maybe the device is slow, or does not report the result?

If you can custom-build NUT per https://github.com/networkupstools/nut/wiki/Building-NUT-for-in%E2%80%90place-upgrades-or-non%E2%80%90disruptive-tests try bumping the last parameter to usb_interrupt_read() a few lines above that message to e.g. 5000ms = 5 sec. This should help rule out whether the device is slow to respond, or just never does.

[rapperskull]

To me, this looks worrysome: armac_command: strlen(cmd) > cmdlen (provided by caller), would effectively truncate! dic 22 22:08:11 rapperskull nutdrv_qx[111976]: [D4] armac command Q1

This happens every time a command is sent (even automatically, like Q1) and doesn't seem to be the problem.

If you can custom-build NUT per https://github.com/networkupstools/nut/wiki/Building-NUT-for-in%E2%80%90place-upgrades-or-non%E2%80%90disruptive-tests try bumping the last parameter to usb_interrupt_read() a few lines above that message to e.g. 5000ms = 5 sec. This should help rule out whether the device is slow to respond, or just never does.

Just tried to bump the timeout to 10 seconds and I still get interrupt read error: Operation timed out (-7), but now after 10 seconds instead of 1. At this point I think the UPS is not responding.

But why is the timeout fixed and not linked to to the value supplied by the -t parameter?

[jimklimov]

That's an USB interrupt timeout here, for one of maybe dozens of communications events in a dialog. The upscmd -w -t NUM is about when the command gives up on waiting for reply from upsd (which in turn talks to driver, and that to device).