Nut upsuser - Apr 2023 - Any suggestions why /bin/upssched-cmd isn't getting invoked?

Hello, group. I hope this works. Question from a confused newbie...

I?ve been banging my head over this. As far as I can tell I?ve done everything
as the instructions say, but one thing isn?t working. There must be something
simple and basic I?m doing wrong, but just don?t see it.

About my setup. I have a CyberPower UPS serving as battery backup for a few
?essential? things. It protects all of my internet connection boxes (fiber
interface, WiFi, a switch, our VOIP phone), a couple of Raspberry Pis, and a
Western Digital NAS (disk server).

Since the NAS is the least critical device and the biggest power drain, I?d like
to shut it down relatively soon when the UPS goes on battery.

I have a Raspberry Pi 2 running a NUT server (and client for upsmon), using a
USB connection to the UPS. The NAS happily talks to the Pi?s NUT server, and
notices when the UPS goes on battery. (Whether it actually shuts itself down on
low battery remains to be seen, but that?s for another day. I?m not even sure it
will honor a FSD.)

So, all seems to be working, EXCEPT upsmon isn?t calling my CMDSCRIPT when
expected. See the following syslog snippets. When I unplug/plug the UPS, I see
upsmon ?on battery? and ?on line power? entries (so upsmon got the events), but
none of the logs expected from the /bin/upssched-cmd script. When I manually
call the script, I do get log entries.

Note that I don?t see the expected upssched.pipe and upssched.lock in
/var/run/nut, though maybe those are transitory?

If anyone can see anything I?m missing I?d appreciate it.

Thanks!


When unplugging/plugging the UPS I see in the log:
> Apr 28 14:08:45 raspberrypi upsmon[558]: UPS usbhid at localhost on battery
> Apr 28 14:09:45 raspberrypi upsmon[558]: UPS usbhid at localhost on line
power
And if I manually invoke "/bin/upssched-cmd test? I
see:
> Apr 28 14:15:46 raspberrypi upssched-cmd: This is a test: test
> Apr 28 14:15:46 raspberrypi upssched-cmd: root
> Apr 28 14:15:46 raspberrypi upssched-cmd: Unrecognized command: test
So it's clear that upsmon is seeing events from the UPS, but isn't
invoking upssched-cmd.
Note that I also don't see a WALL message, but maybe that's a Rasbperry
thing. (The
wall command doesn't work, either.)


Versions of things:
Distributor ID:	Raspbian
Description:	Raspbian GNU/Linux 10 (buster)
Release:	10
Codename:	buster
Linux raspberrypi 5.10.63-v7+ #1496 SMP Wed Dec 1 15:58:11 GMT 2021 armv7l
GNU/Linux
ii  nut                                   2.7.4-8                               
all          network UPS tools
ii  nut-cgi                               2.7.4-8                               
armhf        network UPS tools
ii  nut-client                            2.7.4-8                               
armhf        network UPS tools
ii  nut-server                            2.7.4-8                               
armhf        network UPS tools


Content of upsmon.conf: (I probably should have called it something other than
?usbhid,? but that?s working for now.)
> RUN_AS_USER upsmon
> MONITOR usbhid at localhost 1 upsmon_master <thepassword> master
> MINSUPPLIES 1
> SHUTDOWNCMD "/sbin/shutdown -h +0"
> POLLFREQ 5
> POLLFREQALERT 5
> HOSTSYNC 15
> DEADTIME 15
> POWERDOWNFLAG /etc/killpower
> NOTIFYFLAG ONLINE	SYSLOG+WALL+EXEC
> NOTIFYFLAG ONBATT	SYSLOG+WALL+EXEC
> NOTIFYFLAG LOWBATT	SYSLOG+WALL+EXEC
> NOTIFYFLAG REPLBATT	SYSLOG+WALL+EXEC
> RBWARNTIME 43200
> NOCOMMWARNTIME 300
> FINALDELAY 5
Content of upssched.conf:
> Apr 28 14:09:45 raspberrypi upsmon[558]: UPS usbhid at localhost on line
power
> CMDSCRIPT /bin/upssched-cmd
> PIPEFN /var/run/nut/upssched.pipe
> LOCKFN /var/run/nut/upssched.lock
> AT ONBATT * START-TIMER onbatt 30
> AT ONLINE * CANCEL-TIMER onbatt online
> AT LOWBAT * EXECUTE killnas
> AT SHUTDOWN * EXECUTE powerdown
Note: I tried changing the ?AT ONBATT? to just do "EXECUTE test? to skip
the timer, to no avail.

Content of upsd.users:
> [upsmon_master]
>         password = <XXX>
>         actions = SET,FSD
>         instcmds = ALL
>         upsmon master
> [upsmon]
>         password = <XXX>
>         upsmon slave
> [admin]
>         password = <XXX>
>         actions = SET,FSD
>         instcmds = ALL
>         upsmon master
Content of nut.conf:
> MODE=netserver
/bin/upssched-cmd:
> #! /bin/sh
> 
> logger -t upssched-cmd "This is a test: $1"
> logger -t upssched-cmd `whoami`
> 
> case $1 in
> 	onbatt)
> 		logger -t upssched-cmd "UPS running on battery"
> 		;;
> 	killnas)
> 		logger -t upssched-cmd "Time to shut down NAS"
> 		/usr/sbin/upsmon -c fsd
> 		;;
> 	earlyshutdown)
> 		logger -t upssched-cmd "UPS on battery too long, early
shutdown"
> 		/usr/sbin/upsmon -c fsd
> 		;;
> 	shutdowncritical)
> 		logger -t upssched-cmd "UPS on battery critical, forced
shutdown"
> 		/usr/sbin/upsmon -c fsd
> 		;;
> 	upsgone)
> 		logger -t upssched-cmd "The UPS has been gone for awhile"
> 		;;
> 	*)
> 		logger -t upssched-cmd "Unrecognized command: $1"
> 		;;
> esac
> 

Existing directories and files:
> drwxr-xr-x 13 root root 4096 Apr 27 21:13 /var
> lrwxrwxrwx 1 root root 4 Dec  2  2020 /var/run -> /run
> drwxrwx--- 2 root nut 120 Apr 27 21:19 /run/nut
> -rw-r--r-- 1 nut  nut  4 Apr 27 21:19 /var/run/nut/upsd.pid
> -rw-r--r-- 1 root root 4 Apr 27 21:19 /var/run/nut/upsmon.pid
> srw-rw---- 1 nut  nut  0 Apr 27 21:19 /var/run/nut/usbhid-ups-usbhid
> -rw-r--r-- 1 nut  nut  4 Apr 27 21:19 /var/run/nut/usbhid-ups-usbhid.pid
> -rwxr-xr-x 1 root root 986 Apr 27 14:11 /bin/upssched-cmd
Processes running:
> root     root     upsmon          /lib/nut/upsmon
> upsmon   nut      upsmon          /lib/nut/upsmon

Status:
root at raspberrypi:/etc/nut# service nut-server status
? nut-server.service - Network UPS Tools - power devices information server
   Loaded: loaded (/lib/systemd/system/nut-server.service; enabled; vendor
preset: enabled)
   Active: active (running) since Thu 2023-04-27 21:19:44 CDT; 16h ago
  Process: 428 ExecStart=/sbin/upsd (code=exited, status=0/SUCCESS)
 Main PID: 446 (upsd)
    Tasks: 1 (limit: 1935)
   CGroup: /system.slice/nut-server.service
           ??446 /lib/nut/upsd

Apr 27 21:19:44 raspberrypi upsd[428]: fopen /var/run/nut/upsd.pid: No such file
or directory
Apr 27 21:19:44 raspberrypi upsd[428]: listening on 0.0.0.0 port 3493
Apr 27 21:19:44 raspberrypi upsd[428]: not listening on 127.0.0.1 port 3493
Apr 27 21:19:44 raspberrypi upsd[428]: listening on 0.0.0.0 port 3493
Apr 27 21:19:44 raspberrypi upsd[428]: not listening on 127.0.0.1 port 3493
Apr 27 21:19:44 raspberrypi upsd[428]: Connected to UPS [usbhid]:
usbhid-ups-usbhid
Apr 27 21:19:44 raspberrypi upsd[428]: Connected to UPS [usbhid]:
usbhid-ups-usbhid
Apr 27 21:19:44 raspberrypi upsd[446]: Startup successful
Apr 27 21:19:44 raspberrypi systemd[1]: Started Network UPS Tools - power
devices information server.
Apr 27 21:19:46 raspberrypi upsd[446]: User upsmon_master at 127.0.0.1
<mailto:upsmon_master at 127.0.0.1> logged into UPS [usbhid]
> root at raspberrypi:/etc/nut# sudo service nut-client status
> 
> Status:
> root at raspberrypi:/etc/nut# sudo service nut-client status
> ? nut-monitor.service - Network UPS Tools - power device monitor and
shutdown controller
>    Loaded: loaded (/lib/systemd/system/nut-monitor.service; enabled; vendor
preset: enabled)
>    Active: active (running) since Thu 2023-04-27 21:19:46 CDT; 13h ago
>   Process: 544 ExecStart=/sbin/upsmon (code=exited, status=0/SUCCESS)
>  Main PID: 558 (upsmon)
>     Tasks: 2 (limit: 1935)
>    CGroup: /system.slice/nut-monitor.service
>            ??556 /lib/nut/upsmon
>            ??558 /lib/nut/upsmon
> 
> Apr 27 21:19:46 raspberrypi upsmon[544]: fopen /var/run/nut/upsmon.pid: No
such file or directory
> Apr 27 21:19:46 raspberrypi upsmon[544]: UPS: usbhid at localhost (master)
(power value 1)
> Apr 27 21:19:46 raspberrypi upsmon[544]: Using power down flag file
/etc/killpower
> Apr 27 21:19:46 raspberrypi upsmon[556]: Startup successful
> Apr 27 21:19:46 raspberrypi upsmon[558]: Init SSL without certificate
database
> Apr 27 21:19:46 raspberrypi systemd[1]: nut-monitor.service: Supervising
process 558 which is not our child. We'
> Apr 27 21:19:46 raspberrypi systemd[1]: Started Network UPS Tools - power
device monitor and shutdown controller
> Apr 27 21:54:33 raspberrypi upsmon[558]: UPS usbhid at localhost on battery
> Apr 27 22:01:33 raspberrypi upsmon[558]: UPS usbhid at localhost on line
power
> Apr 28 09:41:11 raspberrypi upsmon[558]: Reloading configuration
> 
> ? nut-monitor.service - Network UPS Tools - power device monitor and
shutdown controller
>    Loaded: loaded (/lib/systemd/system/nut-monitor.service; enabled; vendor
preset: enabled)
>    Active: active (running) since Thu 2023-04-27 21:19:46 CDT; 13h ago
>   Process: 544 ExecStart=/sbin/upsmon (code=exited, status=0/SUCCESS)
>  Main PID: 558 (upsmon)
>     Tasks: 2 (limit: 1935)
>    CGroup: /system.slice/nut-monitor.service
>            ??556 /lib/nut/upsmon
>            ??558 /lib/nut/upsmon
> 
> Apr 27 21:19:46 raspberrypi upsmon[544]: fopen /var/run/nut/upsmon.pid: No
such file or directory
> Apr 27 21:19:46 raspberrypi upsmon[544]: UPS: usbhid at localhost (master)
(power value 1)
> Apr 27 21:19:46 raspberrypi upsmon[544]: Using power down flag file
/etc/killpower
> Apr 27 21:19:46 raspberrypi upsmon[556]: Startup successful
> Apr 27 21:19:46 raspberrypi upsmon[558]: Init SSL without certificate
database
> Apr 27 21:19:46 raspberrypi systemd[1]: nut-monitor.service: Supervising
process 558 which is not our child. We'
> Apr 27 21:19:46 raspberrypi systemd[1]: Started Network UPS Tools - power
device monitor and shutdown controller
> Apr 27 21:54:33 raspberrypi upsmon[558]: UPS usbhid at localhost on battery
> Apr 27 22:01:33 raspberrypi upsmon[558]: UPS usbhid at localhost on line
power
> Apr 28 09:41:11 raspberrypi upsmon[558]: Reloading configuration
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://alioth-lists.debian.net/pipermail/nut-upsuser/attachments/20230429/9bad5c35/attachment-0001.htm>

On Sat, 29 Apr 2023, Willcox David via Nut-upsuser wrote:
> Content of upsmon.conf: (I probably should have called it something other
than ?usbhid,? but that?s working for now.)
> 
> > RUN_AS_USER upsmon
> > MONITOR usbhid at localhost 1 upsmon_master <thepassword> master
> > MINSUPPLIES 1
> > SHUTDOWNCMD "/sbin/shutdown -h +0"
> > POLLFREQ 5
> > POLLFREQALERT 5
> > HOSTSYNC 15
> > DEADTIME 15
> > POWERDOWNFLAG /etc/killpower
> > NOTIFYFLAG ONLINE SYSLOG+WALL+EXEC
> > NOTIFYFLAG ONBATT SYSLOG+WALL+EXEC
> > NOTIFYFLAG LOWBATT SYSLOG+WALL+EXEC
> > NOTIFYFLAG REPLBATT SYSLOG+WALL+EXEC
> > RBWARNTIME 43200
> > NOCOMMWARNTIME 300
> > FINALDELAY 5
I don't see the ? NOTIFYCMD <path-to>/<file-name> ? line in this
file which says
which program is to be invoked when upsmon detects a NOTIFY event flagged as 
EXEC.  Could this be the culprit?

Roger