During a power outage, how do the three servers in the basement react?

Over the weekend, some branches fell on a neighbor’s power service line. They still had power, but the branches had to be removed. That removal occurred this morning. I saw the trucks at about 6:45 AM as I walked past. I suspected I might lose power, and I did. This post records the shutdown and power on times/sequences. I might find this useful should I need to reevaluate the power-outage procedures.

My thought: Perhaps just shutdown the big servers, but keep the gateway, wireless access points, and switches running. The goal being: shutdown the heavy stuff, keep the light stuff going, perhaps for an hour or so. The actual time, I don’t know because I’ve never tried. I could judge that based on power consumption by those units… the information is all there in the PDU graphs…

In this post:

FreeBSD 15.0
nut-2.8.5_1

gw01

/var/log/messages shows:

Jul  6 11:09:53 gw01 upsmon[3974]: UPS heartbeat on line power
Jul  6 11:09:58 gw01 upsmon[3974]: UPS ups04 on battery
Jul  6 11:14:53 gw01 upsmon[3974]: UPS heartbeat on battery
Jul  6 11:17:38 gw01 upsmon[3974]: UPS ups04 battery is low
Jul  6 11:17:38 gw01 upsmon[3974]: Too few UPS(es) are healthy (0<1), initiating forced shutdown
Jul  6 11:17:38 gw01 upsmon[3974]: UPS ups04: forced shutdown in progress
Jul  6 11:17:38 gw01 upsmon[3974]: UPS heartbeat: forced shutdown in progress
Jul  6 11:17:38 gw01 upsmon[3974]: Shutdown initiated; primary system is waiting for secondaries to log out or time out
Jul  6 11:17:45 gw01 upsmon[3974]: Executing automatic power-fail shutdown
Jul  6 11:17:45 gw01 upsmon[3974]: Auto logout and shutdown proceeding
Jul  6 11:35:49 gw01 syslogd: kernel boot file is /boot/kernel/kernel
Jul  6 11:35:49 gw01 kernel: ---<<BOOT>>---

r730-01

Logs show:

Jul  6 11:09:35 r730-01 upsmon[2468]: UPS heartbeat on line power
Jul  6 11:10:00 r730-01 upsmon[2468]: UPS ups04@gw01.int.unixathome.org on battery
Jul  6 11:14:35 r730-01 upsmon[2468]: UPS heartbeat on battery
Jul  6 11:17:35 r730-01 upsmon[2468]: UPS ups04@gw01.int.unixathome.org battery is low
Jul  6 11:17:40 r730-01 upsmon[2468]: UPS ups04@gw01.int.unixathome.org: forced shutdown in progress
Jul  6 11:17:40 r730-01 upsmon[2468]: Too few UPS(es) are healthy (0<1), initiating forced shutdown
Jul  6 11:17:40 r730-01 upsmon[2468]: UPS heartbeat: forced shutdown in progress
Jul  6 11:17:40 r730-01 upsmon[2468]: Executing automatic power-fail shutdown
Jul  6 11:17:40 r730-01 upsmon[2468]: Auto logout and shutdown proceeding
Jul  6 11:17:45 r730-01 upsmon[2468]: doshutdown: call parent pipe for shutdown (async)
Jul  6 11:17:45 r730-01 upsmon[2468]: Exiting upsmon program after initiating shutdown
Jul  6 11:17:45 r730-01 upsmon[2466]: upsmon parent: Unable to call shutdown command: /sbin/shutdown
Jul  6 11:17:45 r730-01 upsmon[2466]: upsmon parent: Exiting after trying to call (256) shutdown command: /sbin/shutdown
Jul  6 11:42:00 r730-01 syslogd: kernel boot file is /boot/kernel/kernel
Jul  6 11:42:00 r730-01 kernel: ---<<BOOT>>---

r730-03

Logs show:

Jul  6 11:08:59 r730-03 upsmon[2142]: UPS heartbeat on line power
Jul  6 11:09:59 r730-03 upsmon[2142]: UPS ups04@gw01.int.unixathome.org on battery
Jul  6 11:13:59 r730-03 upsmon[2142]: UPS heartbeat on battery
Jul  6 11:17:39 r730-03 upsmon[2142]: UPS ups04@gw01.int.unixathome.org: forced shutdown in progress
Jul  6 11:17:39 r730-03 upsmon[2142]: UPS ups04@gw01.int.unixathome.org battery is low
Jul  6 11:17:39 r730-03 upsmon[2142]: Too few UPS(es) are healthy (0<1), initiating forced shutdown
Jul  6 11:17:39 r730-03 upsmon[2142]: UPS heartbeat: forced shutdown in progress
Jul  6 11:17:39 r730-03 upsmon[2142]: Executing automatic power-fail shutdown
Jul  6 11:17:39 r730-03 upsmon[2142]: Auto logout and shutdown proceeding
Jul  6 11:17:44 r730-03 upsmon[2142]: doshutdown: call parent pipe for shutdown (async)
Jul  6 11:17:44 r730-03 upsmon[2142]: Exiting upsmon program after initiating shutdown
Jul  6 11:17:44 r730-03 upsmon[2140]: upsmon parent: Unable to call shutdown command: /sbin/shutdown
Jul  6 11:17:44 r730-03 upsmon[2140]: upsmon parent: Exiting after trying to call (256) shutdown command: /sbin/shutdown
Jul  6 11:37:26 r730-03 syslogd: kernel boot file is /boot/kernel/kernel
Jul  6 11:37:26 r730-03 kernel: ---<<BOOT>>---

Summary

This is an overview of the shutdowns.

Host all get notice of on batter at about 11:09:59
At 11:17:38, nut on gw01 decides it’s low battery time
A forced shutdown in progress appears at the same time
r730-03 gets told that at 11:17:39
11:17:39 r730-03 upsmon[2142]: UPS heartbeat: forced shutdown in progress
r730-01 gets that message at 11:17:40
11:17:38 gw01 upsmon[3974]: UPS heartbeat: forced shutdown in progress
11:17:38 gw01 upsmon[3974]: Shutdown initiated; primary system is waiting for secondaries to log out or time out
11:17:40 r730-01 upsmon[2468]: UPS heartbeat: forced shutdown in progress
11:17:44 r730-03 upsmon[2140]: upsmon parent: Unable to call shutdown command: /sbin/shutdown
11:17:45 r730-01 upsmon[2466]: upsmon parent: Unable to call shutdown command: /sbin/shutdown
11:17:44 r730-03 upsmon[2140]: upsmon parent: Exiting after trying to call (256) shutdown command: /sbin/shutdown
11:17:45 r730-01 upsmon[2466]: upsmon parent: Exiting after trying to call (256) shutdown command: /sbin/shutdown
11:17:45 gw01 upsmon[3974]: Executing automatic power-fail shutdown
11:17:45 gw01 upsmon[3974]: Auto logout and shutdown proceeding

Elapsed time between on-battery and start-shutdown: 11:09:59 – 11:17:39 = 00:05:40

This is the order of boots. The PDU power on sequences are timed to allow gw01 to get up and running before the two main servers are powered on.

Jul 6 11:35:49 gw01 kernel: —<>—
Jul 6 11:42:00 r730-01 kernel: —<>—
Jul 6 11:37:26 r730-03 kernel: —<>—

Battery charge

This is the graph pulled created by LibreNMS:

Battery time remaining

Again, from LibreNMS:

Percentage load

From LibreNMS:

Power consumption (watts)

What can’t LibreNMS do?

Action items for me

Why does “upsmon parent: Unable to call shutdown command: /sbin/shutdown” occur?
How about shutting down r730-01 and r730-03 first, then delaying the shutdown of gw01?

I wonder…

Could it be a simple permissions issue?

[14:06 r730-03 dvl ~] % ps auwwx | grep nut
nut      2123    0.0  0.0   21920   5276  -  Ss   11:37       0:00.29 /usr/local/libexec/nut/dummy-ups -a heartbeat
nut      2125    0.0  0.0   21920   8628  -  Ss   11:37       0:04.91 /usr/local/libexec/nut/dummy-ups -a ups04
nut      2127    0.0  0.0  146760   8192  -  Ss   11:37       0:00.83 /usr/local/sbin/upsd
nut      2141    0.0  0.0   21884   8560  -  S    11:37       0:00.40 /usr/local/sbin/upsmon localhost
dvl     23237    0.0  0.0   14164   2664  0  S+   14:10       0:00.00 grep nut
[14:10 r730-03 dvl ~] % id nut
uid=316(nut) gid=316(nut) groups=316(nut),68(dialer)

The nut< user can't invoke shutdown:

[14:15 r730-03 dvl ~] % ls -l /sbin/shutdown 
-r-sr-xr--  2 root operator 16152 2026.06.29 19:16 /sbin/shutdown

I’m sure that’s it. A shutdown usually includes:

Jun 29 17:58:06 r730-01 shutdown[72325]: reboot by dvl: 
Jun 29 17:58:06 r730-01 root[72379]: shutting down jail stage-nginx01
Jun 29 17:58:07 r730-01 root[72634]: jail stage-nginx01 has shut down
Jun 29 17:58:08 r730-01 root[72679]: shutting down jail test-nginx01
Jun 29 17:58:08 r730-01 kernel:  test-nginx01
Jun 29 17:58:08 r730-01 root[72920]: jail test-nginx01 has shut down
Jun 29 17:58:10 r730-01 root[73043]: shutting down jail dvl-nginx01
Jun 29 17:58:10 r730-01 kernel:  dvl-nginx01
Jun 29 17:58:10 r730-01 root[73280]: jail dvl-nginx01 has shut down
Jun 29 17:58:11 r730-01 root[73380]: shutting down jail dev-nginx01
Jun 29 17:58:11 r730-01 kernel:  dev-nginx01
Jun 29 17:58:21 r730-01 root[73986]: jail dev-nginx01 has shut down

None of those jail shutdown messages appear during power-outage related shutdown.