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.
