[Nut-upsuser] $UPSNAME inconsistent in upssched behavior

[Jim Shank]

OS name and version: Ubuntu 22.04.3 LTS
NUT version: 2.7.4-14ubuntu2
NUT installation method: sudo apt install nut
Exact device name: unrelated but is a Cyberpower CST1500SUC

I've noticed that the $UPSNAME environment variable isn't predictable when
running the CMDSCRIPT. I have 1 real UPS and a dummy-ups configured for
heartbeat. When the actual UPS goes onbatt, upssched-cmd reads the $USPNAME
variable to craft the message and gets "heartbeat at localhost" instead of
"shanknas_ups at localhost". This causes the script to get errors when polling
the status and battery.charge via upsc for messages. Could it be that the
longest running timer (heartbeat) is somehow "locking" the UPSNAME variable
and the latest event (onbatt from shanknas_ups at localhost) isn't able to be
override it?

*ups.conf*
pollinterval = 1
maxretry = 3

[shanknas_ups]
        driver = "usbhid-ups"
        port = "auto"
        vendorid = "0764"
        productid = "0601"
        product = "CST1500SUC"
        serial = "REDACTED"
        vendor = "CPS"
        desc = "CyberPower CST1500SUC - Jim's Office"

[heartbeat]
        driver = "dummy-ups"
        port = "heartbeat.seq"
        desc = "Watch over NUT"

*heartbeat.seq*
# heartbeat.seq -- 10 minute heartbeat
ups.status: OL
TIMER 300
ups.status: OB
TIMER 300

*upssched-cmd *(current, MSG was slightly modified)
#!/bin/bash -u

logger -i -t upssched-cmd Calling upssched-cmd $1 $UPSNAME

#UPSNAME=shanknas_ups


STATUS=$( upsc $UPSNAME ups.status > /dev/stdout 2> /dev/null)
CHARGE=$( upsc $UPSNAME battery.charge > /dev/stdout 2> /dev/null )
CHMSG="[$STATUS]:$CHARGE%"

case $1 in
online) MSG="$UPSNAME, $CHMSG - power supply has been restored." ;;
onbatt) MSG="$UPSNAME, $CHMSG - power failure!" ;;
lowbatt) MSG="$UPSNAME, $CHMSG - we have reached a low battery threshold!"
;;
powerdown) MSG="ShankNAS is shutting down!" ;;
commbad) MSG="$UPSNAME, $CHMSG - we've lost comms with the UPS!" ;;
commok) MSG="$UPSNAME, $CHMSG - comms restored" ;;
heartbeat-failure-timer) MSG="NUT heartbeat failure!" ;;
replacebatt) MSG="$UPSNAME, $CHMSG - please replace the battery" ;;
*) logger -i -t upssched-cmd "Bad arg: \"$1\", $CHMSG"
exit 1 ;;
esac

# Log what happened
logger -t upssched-cmd $MSG

# Send via PushOver
curl -s \
--form-string "token=$PUSHOVER_TOKEN" \
--form-string "user=$PUSHOVER_USER" \
--form-string "message=$MSG" \
https://api.pushover.net/1/messages.json


*upssched.conf*
CMDSCRIPT /bin/upssched-cmd
PIPEFN /run/nut/upssched.pipe
LOCKFN /run/nut/upssched.lock

AT ONBATT shanknas_ups at localhost START-TIMER onbatt 30
AT ONLINE shanknas_ups at localhost CANCEL-TIMER onbatt online
AT LOWBATT * EXECUTE lowbatt
AT COMMBAD * START-TIMER commbad 30
AT COMMOK * CANCEL-TIMER commbad commok
AT NOCOMM * EXECUTE commbad
AT SHUTDOWN * EXECUTE powerdown
AT SHUTDOWN * EXECUTE powerdown
AT REPLBATT * EXECUTE replacebatt

# Restart timer which completes only if the dummy-ups heart beat
# has stopped. See timer values in heartbeat.conf
AT ONBATT heartbeat at localhost CANCEL-TIMER heartbeat-failure-timer
AT ONBATT heartbeat at localhost START-TIMER heartbeat-failure-timer 660

*Logs for nut-* after plug pull*
Oct 20 14:07:02 shanknas upssched[542596]: Cancelling timer:
heartbeat-failure-timer
Oct 20 14:07:02 shanknas upssched[542596]: New timer:
heartbeat-failure-timer (660 seconds)
Oct 20 14:14:17 shanknas upssched[542596]: New timer: onbatt (30 seconds)
Oct 20 14:14:47 shanknas upssched[542596]: Event: onbatt
Oct 20 14:14:47 shanknas upssched-cmd[696002]: Calling upssched-cmd onbatt
heartbeat at localhost
Oct 20 14:14:47 shanknas upssched-cmd[696008]: heartbeat at localhost, [OL]:%
- power failure!
Oct 20 14:17:02 shanknas upssched[542596]: Cancelling timer:
heartbeat-failure-timer
Oct 20 14:17:02 shanknas upssched[542596]: New timer:
heartbeat-failure-timer (660 seconds)
Oct 20 14:27:02 shanknas upssched[542596]: Cancelling timer:
heartbeat-failure-timer
Oct 20 14:27:02 shanknas upssched[542596]: New timer:
heartbeat-failure-timer (660 seconds)
Oct 20 14:34:01 shanknas usbhid-ups[3319430]: libusb_get_string: error
sending control message: Broken pipe
Oct 20 14:37:02 shanknas upssched[542596]: Cancelling timer:
heartbeat-failure-timer
Oct 20 14:37:02 shanknas upssched[542596]: New timer:
heartbeat-failure-timer (660 seconds)
Oct 20 14:37:47 shanknas upsmon[3319457]: UPS shanknas_ups at localhost
battery is low
Oct 20 14:38:07 shanknas upsmon[3319457]: Giving up on the master for UPS
[shanknas_ups at localhost]
Oct 20 14:38:07 shanknas upsmon[3319457]: Executing automatic power-fail
shutdown
Oct 20 14:38:07 shanknas upsmon[3319457]: Auto logout and shutdown
proceeding
Oct 20 14:38:07 shanknas upssched[713933]: Executing command: powerdown
Oct 20 14:38:07 shanknas upssched-cmd[713936]: Calling upssched-cmd
powerdown
Oct 20 14:38:07 shanknas upssched-cmd[713941]: , []:% - we're shutting down!
Oct 20 14:38:09 shanknas upssched[713933]: Executing command: powerdown
Oct 20 14:38:09 shanknas upssched-cmd[713978]: Calling upssched-cmd
powerdown
Oct 20 14:38:09 shanknas upssched-cmd[713983]: , []:% - we're shutting down!
Oct 20 14:38:12 shanknas systemd[1]: nut-monitor.service: Deactivated
successfully.
Oct 20 14:38:12 shanknas systemd[1]: nut-monitor.service: Consumed 53.935s
CPU time.
Oct 20 14:38:12 shanknas systemd[1]: Stopping Network UPS Tools - power
devices information server...
Oct 20 14:38:12 shanknas upsd[3319463]: mainloop: Interrupted system call
Oct 20 14:38:12 shanknas upsd[3319463]: Signal 15: exiting
Oct 20 14:38:12 shanknas systemd[1]: nut-server.service: Deactivated
successfully.
Oct 20 14:38:12 shanknas systemd[1]: Stopped Network UPS Tools - power
devices information server.
Oct 20 14:38:12 shanknas systemd[1]: nut-server.service: Consumed 57.132s
CPU time.
Oct 20 14:38:12 shanknas upsdrvctl[714253]: Network UPS Tools - UPS driver
controller 2.7.4
Oct 20 14:38:12 shanknas systemd[1]: Stopping Network UPS Tools - power
device driver controller...
Oct 20 14:38:12 shanknas usbhid-ups[3319430]: Signal 15: exiting
Oct 20 14:38:12 shanknas systemd[1]: nut-driver.service: Deactivated
successfully.
Oct 20 14:38:12 shanknas systemd[1]: Stopped Network UPS Tools - power
device driver controller.
Oct 20 14:38:12 shanknas systemd[1]: nut-driver.service: Consumed 1min
32.813s CPU time.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://alioth-lists.debian.net/pipermail/nut-upsuser/attachments/20231021/e61fc8e8/attachment.htm>