Nut upsuser - Jun 2020 - AVR750U Low Power not Triggering Shutdown

On Sat, Jun 27, 2020, at 23:11, Manuel Wolfshant wrote:
> On 6/28/20 5:54 AM, Scott Colby wrote:
>> 
>> I'm not convinced this is the problem; I think that pfSense has
an alternative way of running the NUT components:
# ps aux | grep ups
root    45456   0.0  0.1   6796   884  -  Is   02:22    0:00.01
/usr/local/sbin/upsmon
uucp    45751   0.0  0.1   6796   772  -  S    02:22    0:00.10
/usr/local/sbin/upsmon
uucp    46796   0.0  0.1   6888   888  -  Ss   02:22    0:00.45
/usr/local/libexec/nut/usbhid-ups -a AVR750U
root    56752   0.0  0.1   6788   832  -  Ss   02:22    0:00.13
/usr/local/sbin/upsd -u root
root    39437   0.0  0.2   6828  2464  0  S+   02:46    0:00.01 grep ups

Is there anything else that should be running?
> AFAIK, no, those 3 daemons should do the job. But just for the fun of it, I
would test changing that variable anyway. There is nothing to lose, after all.
> 
I changed to MODE=standalone and found some new behavior, see below.
> 
>> Would you expect `upsmon -c fsd` to not work as I described above
(system halting but UPS not power cycling) if MODE was set to none
but upsmon, the driver, and upsd were running?
>> 
> If it is running ( i.e. started ) -c fsd should trigger an immediate
shutdown. quote from man upsmon:
> *-c* *command*
> Send the command *command* to the existing upsmon process. Valid commands
are:
> *fsd*
> shutdown all master UPSes (use with caution)
> 
After rebooting having set MODE=standalone, I found that `upsdrvctl
shutdown` now successfully shuts down the UPS. I changed back to
MODE=none and the same command still works. I'm not sure what's
going on there other than perhaps I wasn't being patient enough on
my earlier attempts. Unfortunately, `upsmon -c fsd` still does not
power off the UPS, no matter how long I wait. It seems like this
used to be an issue earlier (https://forum.netgate.com/post/707181)--maybe
it has come back? I may reach out on the Netgate forums as well.

I also tried `upscmd AVR750U shutdown.return`, which properly shut
down the UPS but did not ever bring it back up. I tried this both
on mains power and on battery. In the latter case, I reconnected
the UPS to the mains and waited 5 minutes. It didn't turn itself
back on.

I'm now becoming suspicious of a couple of the values reported by
`upsc`:
- battery.charge.warning = 30, but there is no battery.charge.low.
  Does this mean that the low battery flag will never be raised?
- ups.timer.reboot, ups.timer.shutdown, and ups.timer.start all are
  65535. I know this is FFFF, and so there's a chance that it's just
  the default response for an unsupported variable, but could this
  mean that the UPS will wait 18 hours before turning itself back on?

It's time for me to sleep on this for a bit and come back to
troubleshooting later. Thanks for your help tonight!

On Sun, 28 Jun 2020, Scott Colby wrote:
> I'm now becoming suspicious of a couple of the values reported by
> `upsc`:
> - battery.charge.warning = 30, but there is no battery.charge.low.
>  Does this mean that the low battery flag will never be raised?
When you disconnect wall power, do you get email notifications for events [OB] 
and [LB] ?
> - ups.timer.reboot, ups.timer.shutdown, and ups.timer.start all are
>  65535. I know this is FFFF, and so there's a chance that it's just
>  the default response for an unsupported variable, but could this
>  mean that the UPS will wait 18 hours before turning itself back on?
"turning itself back on"?  Is this with or without wall power
connection? Could
you describe more precisely, including wall power dis-connections and 
re-connections, what you expect to see.

Roger

Hello again,

I had to take a hiatus from troubleshooting this issue, but I'm
back now with new information. As before, I am working with a
TrippLite AVR750U purchased earlier this year. However, I've switched
from the FreeBSD-based router to a Debian-based Raspberry Pi for
reasons that are probably not worth explaining at the moment :^)

I've included my current configuration files at the bottom of this
message.

I've run a few experiments to try to determine what's going on here.
I'll include the shell command and any output delimited by ###'s,
followed by my observation of the behavior of the Raspberry Pi and
the UPS.

First Experiment
################
$ sudo upsmon -c fsd
Network UPS Tools upsmon 2.7.4

Broadcast message from nut at raspi (somewhere) (Tue Jul 21 23:27:01

Executing automatic power-fail shutdown



Broadcast message from nut at raspi (somewhere) (Tue Jul 21 23:27:01

Auto logout and shutdown proceeding

$ Connection to pi closed by remote host.
Connection to pi closed.
################

I ran this command under two sets of conditions:

- UPS plugged in to the mains
- UPS unplugged from the mains, then plugging it back in approximately
  60 seconds after it turned off

In both cases, the Pi shut down cleanly after approximately 5 seconds
(FINALDELAY?), and the UPS turned off after approximately 25 seconds
(FINALDELAY + the default offdelay?) However, the UPS never came
back up.

Second Experiment
#################
$ sudo upsdrvctl shutdown
Network UPS Tools - UPS driver controller 2.7.4
Network UPS Tools - Generic HID driver 0.41 (2.7.4)
USB communication driver 0.33
Using subdriver: TrippLite HID 0.82
Initiating UPS shutdown
#################

Nothing happened as far as I can tell. I waited 2 minutes before
moving on.

Third Experiment
################
$ sudo /lib/nut/usbhid-ups -a AVR750U -k
Network UPS Tools - Generic HID driver 0.41 (2.7.4)
USB communication driver 0.33
Using subdriver: TrippLite HID 0.82
Initiating UPS shutdown
$ Connection to pi closed.
################

The UPS turned off after approximately 20 seconds, but there was
no clean shut down of the Pi. I think this is expected.

Fourth Experiment
#################
$ sudo upscmd -u admin -p passw0rd AVR750U shutdown.return
OK
#################

I also ran this experiment under two conditions:
- UPS plugged into the mains
- UPS unplugged then reconnected approximately 30 seconds after
  shutdown

In the first case, nothing happened. In the second case, the UPS
shut off after 20 seconds. However, it did not turn back on after
I reconnected it to power.

Fifth Experiment
################
To answer Roger's questions, I did the following:

- ran `upslog -f '{"time": "%TIME @Y- at m-@dT at
H:@M:@S%", "charge": %VAR battery.charge%, "status":
"%VAR ups.status%", "runtime": %VAR battery.runtime%}'
-i 10 -l upslog.jsonl -s AVR750U` and tailed its output
- unplugged from the mains and observed a wall message and status
  change from upslog
- reconnected to the mains and observed a wall message and status
  change
- unplugged again and observed another wall message and status
  change
- waited for the battery to run down
- here's an extract from that log:
{"time": "2020-07-22T02:20:22", "charge": 3,
"status": "OB DISCHRG", "runtime": 138}
{"time": "2020-07-22T02:20:32", "charge": 3,
"status": "OB DISCHRG", "runtime": 128}
{"time": "2020-07-22T02:20:42", "charge": 3,
"status": "OB DISCHRG", "runtime": 123}
{"time": "2020-07-22T02:20:52", "charge": 2,
"status": "OB DISCHRG", "runtime": 108}
{"time": "2020-07-22T02:21:02", "charge": 2,
"status": "OB DISCHRG", "runtime": 98}
{"time": "2020-07-22T02:21:12", "charge": 2,
"status": "OB DISCHRG", "runtime": 93}
{"time": "2020-07-22T02:21:22", "charge": 2,
"status": "OB DISCHRG", "runtime": 77}
{"time": "2020-07-22T02:21:32", "charge": 1,
"status": "OB DISCHRG", "runtime": 67}
{"time": "2020-07-22T02:21:42", "charge": 1,
"status": "OB DISCHRG", "runtime": 62}
{"time": "2020-07-22T02:21:52", "charge": 1,
"status": "OB DISCHRG", "runtime": 52}
{"time": "2020-07-22T02:22:02", "charge": 0,
"status": "OB DISCHRG", "runtime": 41}
{"time": "2020-07-22T02:22:12", "charge": 0,
"status": "OB DISCHRG", "runtime": 31}
{"time": "2020-07-22T02:22:22", "charge": 0,
"status": "OB DISCHRG", "runtime": 21}
{"time": "2020-07-22T02:22:32", "charge": 0,
"status": "OB DISCHRG", "runtime": 11}
{"time": "2020-07-22T02:22:42", "charge": 0,
"status": "OB DISCHRG", "runtime": 1}
{"time": "2020-07-22T02:22:52", "charge": 0,
"status": "OB DISCHRG", "runtime": 0}
{"time": "2020-07-22T02:23:02", "charge": 0,
"status": "OB DISCHRG", "runtime": 0}
{"time": "2020-07-22T02:23:12", "charge": 0,
"status": "OB DISCHRG", "runtime": 0}
{"time": "2020-07-22T02:23:22", "charge": 0,
"status": "OB DISCHRG", "runtime": 0}
{"time": "2020-07-22T02:23:32", "charge": 0,
"status": "OB DISCHRG", "runtime": 0}
...
{"time": "2020-07-22T03:19:52", "charge": 0,
"status": "OB DISCHRG", "runtime": 0}
{"time": "2020-07-22T03:20:02", "charge": 0,
"status": "OB DISCHRG", "runtime": 0}
{"time": "2020-07-22T03:20:12", "charge": 0,
"status": "OB DISCHRG", "runtime": 0}
{"time": "2020-07-22T03:20:22", "charge": 0,
"status": "OB DISCHRG", "runtime": 0}
{"time": "2020-07-22T03:20:32", "charge": 0,
"status": "OB DISCHRG", "runtime": 0}
{"time": "2020-07-22T03:20:42", "charge": 0,
"status": "OB DISCHRG", "runtime": 0}
{"time": "2020-07-22T03:20:52", "charge": 0,
"status": "OB DISCHRG", "runtime": 0}

- !!!!! it ran for almost an hour on charge 0 runtime 0 and never
  raised the LB flag

################

So, here are my questions:

- Have I made a configuration error?
- Why is the behavior of `upsdrvctl shutdown` different from that
  of `usbhid-ups -k`?
- Why doesn't the UPS ever turn back on on its own?
- What's going on with the LB flag never coming on and the runtime
  being badly wrong?

I'm wondering if this is related to what objecttothis is experiencing
with the AVRX500U. I'll CC them on this message. Further, I will
reach out to TrippLite support to ask what version of the USB HID
protocol my AVR750U is using.

Thanks,
Scott




My Configuration
################

# /etc/udev/rules.d/62-nut-usbups-custom.rules
# based on the 62-nut-usbups.rules that came with the package
ACTION!="add|change", GOTO="nut-usbups_rules_end"
SUBSYSTEM=="usb_device", GOTO="nut-usbups_rules_real"
SUBSYSTEM=="usb", GOTO="nut-usbups_rules_real"
SUBSYSTEM!="usb", GOTO="nut-usbups_rules_end"
LABEL="nut-usbups_rules_real"
# TrippLite
#  e.g. TrippLite AVR750U  - usbhid-ups
ATTR{idVendor}=="09ae", ATTR{idProduct}=="3024",
MODE="664", GROUP="nut"
LABEL="nut-usbups_rules_end"

# nut.conf
MODE=standalone

# ups.conf
[AVR750U]
    driver = usbhid-ups
    productid = 3042
    port = auto

# upsd.conf
# empty

# upsd.users
[admin]
    password = passw0rd
    instcmds = ALL
[upsmon]
    password = passw0rd
    upsmon master

# upsmon.conf
MONITOR AVR750U 1 upsmon passw0rd master
MINSUPPLIES 1
SHUTDOWNCMD "/sbin/shutdown -h +0"
POLLFREQ 5
POLLFREQALERT 5
HOSTSYNC 15
DEADTIME 15
POWERDOWNFLAG /etc/killpower
RBWARNTIME 43200
NOCOMMWARNTIME 300
FINALDELAY 5