UPSSCHED doesn't work correct with multiple UPSs

[shgubar]

HI,
My configuration consists of two UPS.

System: Debian Buster
NUT: 2.8.0.1 (installed from source)

upsmon.conf

MONITOR riello1000@localhost 1 user pass primary
MONITOR rps1000@localhost 0 user pass secondary

upssched.conf

AT ONLINE riello1000@localhost START-TIMER upsgone 60
AT ONBATT riello1000@localhost CANCEL-TIMER upsgone

With this configuration UPSSCHED doesn't work, if I change to:

AT ONLINE * START-TIMER upsgone 60
AT ONBATT * CANCEL-TIMER upsgone

working perfectly.

Why I can't use specific UPS for this task?

[jimklimov]

Hi, looked through code and it boiled down to upssched.c::parse_at() expecting exactly the upsname from local configuration.

• https://github.com/networkupstools/nut/blob/master/clients/upssched.c#L1173

Try dropping the @localhost in AT lines. It is a bit inconsistent with upsmon sort of requiring a hostname (since it does talk TCP) and guessing a @localhost if there is no hostname part like upsc does; actually the upscli_splitname() library method does that. On the other hand, upssched supposedly only manages operations on local UPSes, so this makes sense.

[jimklimov]

Are you in position to build NUT locally and test if PR #1861 fixes the original issue (allows to use e.g. AT riello1000@localhost ...)? Would be nice to know it works and does not crash before merging it ;) Thanks.

[shgubar]

Hi, looked through code and it boiled down to upssched.c::parse_at() expecting exactly the upsname from local configuration.

• https://github.com/networkupstools/nut/blob/master/clients/upssched.c#L1173

Try dropping the @localhost in AT lines. It is a bit inconsistent with upsmon sort of requiring a hostname (since it does talk TCP) and guessing a @localhost if there is no hostname part like upsc does; actually the upscli_splitname() library method does that. On the other hand, upssched supposedly only manages operations on local UPSes, so this makes sense.

I tried as you said:
AT ONLINE riello1000 START-TIMER upsgone 60
but the command was not executed. It didn't help.

Are you in position to build NUT locally .....

What do you mean download branch again and install?
Because I already have NUT installed locally, where the UPSs is connected.

[jimklimov]

Hm, I must have read not all of the code initially to trace the logic correctly, too much on the run between dayjob tasks :(

So the upsname which parse_at() checks against is whatever string upsmon exports as UPSNAME envvar, and that probably should match the setting of upsmon.conf MONITOR line including hostname if used.

So that PR is probably not needed after all, or at worst - should be changed to try adding @localhost if a host part is missing in requested envvar or matched AT command, but that would probably muddy waters even more.

Did you try bumping debug level of upsmon -DDDDDD to see if maybe it reveals what value it passes to upssched?

OT: Git has "brAnches". People have "brUnches", if they mix breakfast and lunch.

[jimklimov]

Also, since you have a locally built NUT, you can add an upsdebugx(1, ...) message in parse_at to report the strings it compares for upsname and un...

[shgubar]

Also, I would like to add one more problem related to the fact that the command is not executed - a new status is set:
ups.status: FSD OL BYPASS CHRG

This causes all clients to simply shut down with error - power fail

Syslog:

Feb 28 17:40:30 raspserv nut-monitor[20087]: UPS riello1000@localhost: forced shutdown in progress
Feb 28 17:40:30 raspserv nut-server[20086]: Client [email protected] set FSD on UPS [riello1000]
Feb 28 17:40:30 raspserv upsd[20086]: Client [email protected] set FSD on UPS [riello1000]
Feb 28 17:40:30 raspserv nut-monitor[20087]: wall: cannot get tty name: Inappropriate ioctl for device
Feb 28 17:40:30 raspserv nut-monitor[20087]: Network UPS Tools upsmon 2.8.0.1
Feb 28 17:40:46 raspserv nut-monitor[20087]: Host sync timer expired, forcing shutdown
Feb 28 17:40:46 raspserv nut-monitor[20087]: Executing automatic power-fail shutdown
Feb 28 17:40:46 raspserv nut-monitor[20087]: wall: cannot get tty name: Inappropriate ioctl for device
Feb 28 17:40:46 raspserv nut-monitor[20087]: Auto logout and shutdown proceeding
Feb 28 17:40:46 raspserv nut-monitor[20087]: wall: cannot get tty name: Inappropriate ioctl for device
Feb 28 17:40:46 raspserv nut-monitor[20087]: Network UPS Tools upsmon 2.8.0.1
Feb 28 17:40:51 raspserv nut-monitor[20087]: Failed to create power down flag!
Feb 28 17:40:51 raspserv nut-monitor[20087]: Network UPS Tools upsmon 2.8.0.1
Feb 28 17:40:51 raspserv nut-monitor[20087]: Failed to set wall message, ignoring: Interactive authentication required.
Feb 28 17:40:51 raspserv nut-monitor[20087]: Failed to call ScheduleShutdown in logind, proceeding with immediate shutdown: Interactive authentication required.
Feb 28 17:40:51 raspserv nut-monitor[20087]: Failed to set wall message, ignoring: Interactive authentication required.
Feb 28 17:40:51 raspserv nut-monitor[20087]: Failed to power off system via logind: Interactive authentication required.
Feb 28 17:40:51 raspserv nut-monitor[20087]: Failed to open initctl fifo: Access denied
Feb 28 17:40:51 raspserv nut-monitor[20087]: Failed to talk to init daemon.
Feb 28 17:40:51 raspserv nut-monitor[20087]: parent: Unable to call shutdown command: /sbin/shutdown -h +0
Feb 28 17:40:51 raspserv nut-monitor[20087]: Network UPS Tools upsmon 2.8.0.1

[shgubar]

OT: Git has "brAnches". People have "brUnches", if they mix breakfast and lunch.

Thanks for pointing out my mistake, it's just a typo.

[shgubar]

Also, since you have a locally built NUT, you can add an upsdebugx(1, ...) message in parse_at to report the strings it compares for upsname and un...

This is a very good idea, but I did not understand exactly where to add upsdebugx(1, ...) and how to write this command correctly?

[jimklimov]

Regarding the status, is it set after a real power outage? Was it long enough to deplete the battery and begin shutdown rituals (raise the FSD flag)?

If yes, that flag can not be removed from the running NUT data server (at best, you can restart upsd for the effect) since it is assumed that some monitoring clients began shutting down and the whole rack (generally) or the current server (usually) must complete its reboot even if wall-power returned.

Some UPSes (typically enterprise networked ones) also have a concept of alarming their clients that it is not safe to be powered on (even if charging, the UPS does not have batteries full enough to let clients shut down in emergency), and that status can be relayed as NUT FSD as well. So you press the buttons to force a boot-up after an outage (rather than wait for UPS to charge and power on the load), then NUT starts, finds the alarm on expensive UPS, raises FSD and your system shuts down ASAP.

[shgubar]

Regarding the status, is it set after a real power outage? Was it long enough to deplete the battery and begin shutdown rituals (raise the FSD flag)?

Perhaps it is necessary to explain why I use upssched.
There is a main server to which all UPSs are connected, and there is also a servers (more powerful, system: FreeBSD 12.3, nut: 2.8.0) on which only upsmon is configured. So when the power goes out, all servers (except the main one, it should turn off only after the critical battery level) should turn off after 10 minutes to reduce battery consumption. When the power comes back on again, all servers should be up (using wakeonlan) after 10 minutes.

So on the main server:
upssched.conf

AT ONLINE riello1000@localhost START-TIMER upsgone 600
AT ONBATT riello1000@localhost CANCEL-TIMER upsgone

On all other servers:
upssched.conf

AT ONBATT [email protected] START-TIMER upsgone 600
AT ONLINE [email protected] CANCEL-TIMER upsgone

For the test, I turn off the power plug of the riello1000 and with this configuration I see the following in the logs (at this moment) of the main server:

Feb 28 17:28:51 raspserv nut-monitor[7346]: UPS riello1000@localhost on battery
Feb 28 17:28:51 raspserv nut-monitor[7346]: Network UPS Tools upsmon 2.8.0.1
Feb 28 17:29:02 raspserv nut-server[7345]: Client [email protected] set FSD on UPS [riello1000]
Feb 28 17:29:02 raspserv upsd[7345]: Client [email protected] set FSD on UPS [riello1000]
Feb 28 17:29:06 raspserv nut-monitor[7346]: UPS riello1000@localhost: forced shutdown in progress
Feb 28 17:29:06 raspserv nut-server[7345]: Client [email protected] set FSD on UPS [riello1000]
Feb 28 17:29:06 raspserv upsd[7345]: Client [email protected] set FSD on UPS [riello1000]
Feb 28 17:29:06 raspserv nut-monitor[7346]: wall: cannot get tty name: Inappropriate ioctl for device
Feb 28 17:29:06 raspserv nut-monitor[7346]: Network UPS Tools upsmon 2.8.0.1
Feb 28 17:29:22 raspserv nut-monitor[7346]: Host sync timer expired, forcing shutdown
Feb 28 17:29:22 raspserv nut-monitor[7346]: Executing automatic power-fail shutdown
Feb 28 17:29:22 raspserv nut-monitor[7346]: wall: cannot get tty name: Inappropriate ioctl for device
Feb 28 17:29:22 raspserv nut-monitor[7346]: Auto logout and shutdown proceeding
Feb 28 17:29:22 raspserv nut-monitor[7346]: wall: cannot get tty name: Inappropriate ioctl for device
Feb 28 17:29:22 raspserv nut-monitor[7346]: Network UPS Tools upsmon 2.8.0.1
Feb 28 17:29:27 raspserv nut-monitor[7346]: Failed to create power down flag!
Feb 28 17:29:27 raspserv nut-monitor[7346]: Network UPS Tools upsmon 2.8.0.1
Feb 28 17:29:27 raspserv nut-monitor[7346]: Failed to set wall message, ignoring: Interactive authentication required.
Feb 28 17:29:27 raspserv nut-monitor[7346]: Failed to call ScheduleShutdown in logind, proceeding with immediate shutdown: Interactive authentication required.
Feb 28 17:29:27 raspserv nut-monitor[7346]: Failed to set wall message, ignoring: Interactive authentication required.
Feb 28 17:29:27 raspserv nut-monitor[7346]: Failed to power off system via logind: Interactive authentication required.
Feb 28 17:29:27 raspserv nut-monitor[7346]: Failed to open initctl fifo: Access denied
Feb 28 17:29:27 raspserv nut-monitor[7346]: Failed to talk to init daemon.
Feb 28 17:29:27 raspserv nut-monitor[7346]: parent: Unable to call shutdown command: /sbin/shutdown -h +0
Feb 28 17:29:27 raspserv nut-monitor[7346]: Network UPS Tools upsmon 2.8.0.1

It seems to me that the problem is not only that the AT command is transferred - some permissions are interfering.

Then the powerful server shuts down.

After a few minutes I turned the power back on the riello1000 and waited 10 minutes. The wakeonlan command did not work. Nothing just happened.

Only if I do the following on the main server:
upssched.conf

AT ONLINE * START-TIMER upsgone 600
AT ONBATT * CANCEL-TIMER upsgone

Then the entire scenario is performed properly.

[jimklimov]

FWIW, the https://github.com/jimklimov/nut/tree/issue-1858-debug branch (source of newer PR above) should help troubleshooting the parse_at() handling (e.g. why upssched processes or discards a run), as long as you launch if with -D options from upsmon.conf (testing welcome).

It looks strange that two of your upsmon clients (from separate IP addresses) set the FSD flag...
Is the UPS connected by local media (e.g. USB/Serial)? - then the setting in one of the upsmon.conf files is wrong, it would not be a primary for the device. A networked (SNMP/...) UPS can technically be managed by several NUT clients, but it can be a source of confusion who commands what and when, especially for the final shutdown and poweroff part.

[jimklimov]

Can you start the upsmon primary instances with a higher debug level, to see why they decide to set the FSD nearly right away? Maybe the UPS says "OB LB" early on?

As for permissions, check what user your copies of upsmon start and run with? Is it nobody or a dedicated user (either via configure --user=... or a RUN_AS_USER setting)? Especially the "starts" part - it should go as root first, then forks to run the unprivileged monitor and keeps the root part capable of shutdown...

[shgubar]

Can you start the upsmon primary instances with a higher debug level, to see why they decide to set the FSD nearly right away? Maybe the UPS says "OB LB" early on?

Apparently, this is due to the fact that on the secondary server it was specified in upsched-cmd for shutdown:
/usr/local/sbin/upsmon -c fsd
Chenged to:
shutdown -h now
But not tested. I will check a little later.

As for permissions, check what user your copies of upsmon start and run with? Is it nobody or a dedicated user (either via configure --user=... or a RUN_AS_USER setting)? Especially the "starts" part - it should go as root first, then forks to run the unprivileged monitor and keeps the root part capable of shutdown...

Everything was done according to the instructions that I wrote earlier in another issue - #1754.

I mean what:
./configure --with-user=ups --with-group=nut ... (and more other options)

I will add more (main server):

[raspserv:~] [2023-03-01 12:51] root # ls -la /etc/nut/
total 160
-rw-r--r-- 1 ups nut  1172 Jan  3 20:36 hosts.conf
-rw-r--r-- 1 ups nut  1071 Jan  7 15:08 hosts.conf.sample
-rw-r----- 1 ups nut  1916 Jan  3 20:37 nut.conf
-rw-r--r-- 1 ups nut  1911 Jan  7 15:08 nut.conf.sample
-rw-r----- 1 ups nut  9651 Jan  9 21:22 ups.conf
-rw-r--r-- 1 ups nut  9269 Jan  7 15:08 ups.conf.sample
-rw-r----- 1 ups nut  7555 Jan  7 15:27 upsd.conf
-rw-r--r-- 1 ups nut  7498 Jan  7 15:08 upsd.conf.sample
-rw-r----- 1 ups nut  2525 Jan  7 15:34 upsd.users
-rw-r--r-- 1 ups nut  2349 Jan  7 15:08 upsd.users.sample
-rw-r----- 1 ups nut 20701 Feb 24 12:13 upsmon.conf
-rw-r--r-- 1 ups nut 20458 Jan  7 15:08 upsmon.conf.sample
-rw-r----- 1 ups nut  4335 Feb 28 18:19 upssched.conf
-rw-r--r-- 1 ups nut  4213 Jan  7 15:08 upssched.conf.sample
-rw-r--r-- 1 ups nut  1428 Jan  5 21:51 upsset.conf
-rw-r--r-- 1 ups nut  1432 Jan  7 15:08 upsset.conf.sample
-rw-r--r-- 1 ups nut  4402 Jan 18 12:01 upsstats.html
-rw-r--r-- 1 ups nut  4096 Jan  7 15:08 upsstats.html.sample
-rw-r--r-- 1 ups nut  7284 Jan  7 16:02 upsstats-single.html
-rw-r--r-- 1 ups nut  6861 Jan  7 15:08 upsstats-single.html.sample

[jimklimov]

By now I guess we have two or more problems to address separately here :)

• upssched AT commands not accepting the UPS identifier you expect it to - should be better debuggable with PR Add debug verbosity setting for upssched, add upsdebugx for parse_at(), and add help lines for -h/-V in many tools #1864
• Unexpected FSD - maybe found and addressed in previous post
• upsmon (on raspserv) seemingly lacking permissions to wall, shutdown etc. - that should be better debuggable with DEBUG_MIN 6 setting so it would post max verbosity into the log, which should help pinpoint where the problems happened, and early in startup - which accounts it actually used, whether it forked leaving a root-owned parent running, etc.
  • BTW, is this running on the actual Raspberry Linux system, or in a container which might have no shutdown implementation?
• possibly different behaviors on the FreeBSD servers that were not screenshot'ed above

[jimklimov]

Wondering now if you constrained User=... in the systemd unit files for NUT? They should normally be left alone (undefined or root) and daemons would drop privileges per configuration or built-in default user when needed (after early init and accessing whatever needs the higher privileges).

[shgubar]

Wondering now if you constrained User=... in the systemd unit files for NUT? They should normally be left alone (undefined or root) and daemons would drop privileges per configuration or built-in default user when needed (after early init and accessing whatever needs the higher privileges).

No. Just create user and group.

cat /etc/passwd | grep ups
ups:x:998:993::/var/lib/nut:/sbin/nologin
cat /etc/group | grep nut
nut:x:993:

[shgubar]

• upsmon (on raspserv) seemingly lacking permissions to wall, shutdown etc. - that should be better debuggable with DEBUG_MIN 6 setting so it would post max verbosity into the log, which should help pinpoint where the problems happened, and early in startup - which accounts it actually used, whether it forked leaving a root-owned parent running, etc.

I will try later and show output.

• BTW, is this running on the actual Raspberry Linux system, or in a container which might have no shutdown implementation?

Running on the actual system

• possibly different behaviors on the FreeBSD servers that were not screenshot'ed above

What specifically interests you? Just tell me - I will provide any configs.

[jimklimov]

Regarding FreeBSD - just a generic curiosity. You mentioned that everyone shuts down "wrongly" (which you might have fixed now), and mentioned FreeBSD, but did not provide any screenshots so I have little idea if it also misbehaves in some special manner, or just followed FSD commands "honestly".

[shgubar]

When I changed on FreeBSD file upssched-cmd:

case $1 in
     upsgone)
          logger -t upssched-cmd "Shutdown timer reached, calling SHServer power OFF."
          #/usr/local/sbin/upsmon -c fsd

to

          /sbin/shutdown -p now
          ;;
     *)
          logger -t upssched-cmd "Unrecognized command: $1"
          ;;
esac

On main server nothing errors but FreeBSD server doesn't shutdown. Maybe permissions issue but in logs - nothing.

How to correctly shutdown NOT main server?

[shgubar]

FreeBSD setup:

rc.conf

nut_enable="NO"
nut_upsshut="NO"
nut_upsmon_enable="YES"
nut_upslog_enable="NO"

nut.conf
MODE=netclient

upsmon.conf

MONITOR [email protected] 1 user **** primary
MONITOR [email protected] 0 user **** secondary
MINSUPPLIES 1
SHUTDOWNCMD "/sbin/shutdown -p +0"
NOTIFYCMD /usr/local/sbin/upssched
POLLFREQ 5
POLLFREQALERT 5
HOSTSYNC 15
DEADTIME 15
POWERDOWNFLAG /etc/killpower
NOTIFYFLAG ONLINE       SYSLOG+EXEC
NOTIFYFLAG ONBATT       SYSLOG+EXEC
NOTIFYFLAG COMMOK       SYSLOG
NOTIFYFLAG COMMBAD      SYSLOG
NOTIFYFLAG SHUTDOWN     SYSLOG
RBWARNTIME 43200
NOCOMMWARNTIME 300
FINALDELAY 5

upssched.conf

CMDSCRIPT /usr/local/bin/upssched-cmd
PIPEFN /var/db/nut/upssched/upssched.pipe
LOCKFN /var/db/nut/upssched/upssched.lock
AT ONBATT [email protected] START-TIMER upsgone 10
AT ONLINE [email protected] CANCEL-TIMER upsgone

[jimklimov]

One difference that pops out is /sbin/shutdown -p +0 vs. /sbin/shutdown -p now, which one is right? Or both are?

Another is that if the system is not connected to the UPS signalling (does not/can not run a driver for it), it should not be upsmon primary as the BSD seems to be.

• "primary" means "can command the UPS" (got USB/serial/... cable to do so)
• power-source count (in your case 0 or 1) means how many PSUs of this system are powered by that monitored UPS; the MINSUPPLIES then says how many PSUs are needed for stable work (e.g. a 2-PSU server may run on one PSU indefinitely, so one dead and one healthy UPS are okay and no shutdown needed).

These do not always intersect, depending on how your monitoring is set up (e.g. if it is not powered by any of these UPSes it watches, it might have 0 PSU counts on all of them).

[jimklimov]

Also with the AT upsname in FreeBSD config above, one suspect could be if this is properly handled (what strings are recognized from config and what comes as envvars), something that may be debugged with an updated custom build... The less-questionable PRs that appeared around this and some other recent issues were merged today, so you can try the master branch.

[shgubar]

Please tell me what exactly should be on all other servers to which the UPS is not directly connected (in other words, net clients)?

• "primary" means "can command the UPS" (got USB/serial/... cable to do so)

Something like this:

MONITOR [email protected] 2 user ***** secondary
MONITOR [email protected] 0 user ***** secondary

?

Next what has already been done:

1. A new master branch build was installed on the main server.
2. On the server with the FreeBSD system:

• in the configuration file upsmon.conf it is written - RUN_AS_USER root
• in the upssched-cmd file - /sbin/shutdown -p now (/sbin/shutdown -p +0 is the same).

3. The test was conducted as follows:

• on riello1000@localhost turned off the power
• a timer has started on the FreeBSD system
• on the FreeBSD system, the timer was reached and the server shutdown command was activated
• server with FreeBSD system turned off
• on riello1000@localhost turned on the power
• a timer has started on the main server (it can be seen in the logs)
• timer reached - wakeonlan command executed
• the server with the FreeBSD system has started

Everything works as expected.

For a more accurate test, the following steps were also performed:

• on rps1000@localhost turned off the power
• only a message is visible in the logs on the main server that the UPS is running on batteries
• on rps1000@localhost power is back
• only a message is visible in the logs on the main server that the UPS is running with status online and charge.

At the moment, I have not found any other problems related with UPSSCHED.

But there are false indicators specifically on rps1000@localhost (on riello1000 this was not observed).
Here is an example:

output.L1.current: 52432
output.L1.power: 4291611856
output.L1.realpower: 4291611856
output.L2.current: 52432
output.L2.power: 4291611856
output.L2.realpower: 4291611856
output.L3.current: 52432
output.L3.power: 4291611856
output.L3.realpower: 4291611856

And that is probably a completely different story ;) (later I will create a new issue).

[jimklimov]

"secondAry" in the keyword from your latest example.

As for "what exactly" - pretty much as you wrote. That example however says two power sources are fed by riello1000 and zero by rps1000. I assume it has at least MINSUPPLIES 2 and could benefit from each PSU fed by a separate UPS.

[jimklimov]

Hello, how did this progress with the upsmon and upssched parts of the problem? do they work for you now after all the config changes above? (also there was some progress merged on the master branch, you might want to update your custom build of NUT to check if that addressed your issues too...)

[shgubar]

First of all, thank you for your concern.
After all the changes that were written earlier, it fixed the situation, but periodically problems arise and it is more related to the loss of connection with the second (rps1000), while the first (riello1000) works stably.
I won't be able to check the latest builds in the near future. But when such an opportunity arises, I will immediately inform you.

[jimklimov]

Thanks! Drivers should be able to reconnect in case of USB port resets and other causes of dis- and re-connection on the HW/OS level, although the maturity of this ability may vary between drivers (e.g. more popular ones like usbhid-ups might evolve faster, while others catch up, eventually...)

Note also in the NUT GitHub Wiki and various docs in code, there are notes on actively causing USB port resets with (OS-dependent) third-party tools, if the device goes AWOL - usually based on a regular (cron?) upsc query for ups.status saying the device is not connected at the moment, or service unit (SMF, systemd) is failed, etc.

FWIW, try also different cables and/or ports, that can do wonders :)

Finally, on the "duplicate" device support: recently master branch got the ability to set and match (via ups.conf) the busport value, as well as bus and device earlier. This allows for configurations tied to the physical topology (as much as the OS allows, at least) - and so unique and stable, hopefully.