Three shutdowns, three causes

My storage box sits on a DJI Power 2000 used as a UPS. Over two days, 1 and 2 November, it went down a few times. Some of those had an obvious reason and some had none, and every time I looked, the DJI showed about 95 %. I went in looking for one fault: something that turns a full battery into a dead machine.

There were three, and only one of them was clearly the station.

The setup, for anyone arriving here first: the DJI and a second power station, a BLUETTI AC180, are read over Bluetooth by an ESP32 bridge, and an observer on my router serves them to every machine as UPSes over NUT (Network UPS Tools), three tiers per station (t1, t2, t3), each tier with its own shutdown limits. The gaming PC is on the DJI's t1, which at the time shed earliest. The storage box is on its t2. Each host runs stock upsmon, which logs what NUT tells it and shuts down on low battery.

Reading how a journal ends#

Each host's journal says how its last boot ended, if you know what an ending looks like. The commands were ordinary: journalctl --list-boots and last -x -F for the list of boots, journalctl -b -N -n 25 for the last 25 lines of each, a search for upsmon, nut-monitor and shutdown lines, and systemd-analyze for boot timing. Three kinds of ending turned up:

• A clean shutdown ends with systemd-poweroff, then "Reached target poweroff.target", then "Journal stopped".
• A shutdown I typed has the same ending, preceded by a sudo line with COMMAND=/usr/sbin/shutdown now, and before that an sshd "Accepted publickey" from the workstation.
• Power loss has no ending. The last line is whatever happened to be logging, for example nut-monitor[1026]: UPS dji2000-t2@... on battery, and the next line is the next boot.

Then each ending gets matched against the observer's log on the router, which records every on-battery and grid-back transition and every alert. And when a host died without an ending, I checked the other host on the same station.

The two days, line by line#

The gaming PC's two shutdowns were the first tier doing what it was configured to do, and the false alarm at 11:39 has its own post. That leaves three storage-box endings, and they don't share a cause.

Cause one: I shut it down#

At 11:33:48 the storage box ended cleanly, with a sudo line running /usr/sbin/shutdown now, and an ssh login from the workstation six seconds before it. That was me, for a reason unrelated to power. The observer had no part in it: tier 2 wasn't on low battery at the time.

Cause two: a journal that stops at 17:08:10#

The afternoon outage began at 16:54:05. The gaming PC left at 16:59 on its five-minute rule. The storage box logged "on battery" and kept running. Its journal ends at 17:08:10, with no shutdown in it, and the next boot is at 23:44.

The last line isn't the moment it died. The journal on disk is synced periodically: journald's SyncIntervalSec= defaults to 5 minutes, and only messages of priority CRIT, ALERT or EMERG force a sync straight away. Lines written after the last sync can be lost with the power, so the box died some time after 17:08:10, not necessarily at it. A line that repeats periodically had its next copy due around 17:13, and it is missing too, so the box was probably gone by then; by the same sync rule, even that isn't certain. The grid came back at 17:10:16, inside that window. It might have lost power while on battery or at the transfer back to the grid. The journal can't say which. Tier 2 was never on low battery, so it wasn't NUT.

Cause three: both hosts, one second apart#

On 2 November the DJI reported the grid gone at 09:01:00. The storage box logged upsmon "on battery" at 09:01:03, and the gaming PC logged the same at 09:01:04. Then both journals end.

One machine dying could be its power supply. Two machines on the same station, whose journals stop within a second of each other right after "on battery", with the storage box powering on again at 09:02:31, point at the one thing they share: the station's AC output, or its transfer to battery, failed. The outage itself was short. The observer saw the grid back at 09:02:39, and the gaming PC was still up at 09:01 because its five-minute rule never had time to fire.

The storage box then turned itself back on at 09:02:31, probably from the BIOS setting that powers on after AC loss, which I haven't checked. Firmware took 17.6 s, the loader 5.9 s, the kernel 2.5 s and the initrd 10.5 s. Why it came back on its own that morning, but stayed off until 23:44 the evening before, is something else I haven't checked.

Three traps in the evidence#

The journal's last line is not the time of death. That is the sync interval above, and it turned "died at 17:08" into a window of about five minutes, possibly longer, with the grid return inside it.

The storage box keeps its hardware clock in local time. Early-boot lines carry timestamps one to two hours off until chrony steps the clock. journalctl --list-boots showed a boot whose first entry was later than its last. And upsmon logged "It seems the system clock was changed into the past" with an offset of −3596 s, and treated the jump as a wake from sleep.

The observer's grid flag is late. It follows the bridge, which polls every 20 seconds, so a transition can show up to one poll after it happened. The wall can also be earlier than the station: on 2 November the grid canary on the AC180's side, a smart plug that measures mains voltage, saw the loss at 08:59:39, 81 seconds before the DJI reported it. That could be a sagging or flickering grid that the DJI rode through at first. I haven't confirmed it.

What NUT did and didn't do#

At neither abrupt loss did tier 2 go to low battery. upsmon logged "on battery", which was true, and nothing else, which was also correct: the battery was near full, and low battery is about an empty battery. Nothing the observer serves could have warned of an output that stops at near-full charge. A tier policy can't protect a machine from the outlet it's plugged into.

What changed, and what's still open#

The false low battery is fixed, on both the bridge and the observer, in the previous part.

Every reading is now recorded. Before this, nothing stored per-reading values. The router's observer log has transitions and alerts, the hosts' journals die with the hosts, and the 20-second readings in between were gone. A recorder container on the router now writes every MQTT message from both stations, plus the bridge's online and offline, to the router's SSD, one file per UTC day. The router stays up through outages, so the next switchover will leave the DJI's output watts and grid flag in that file, every 20 seconds, up to the last reading before the hosts die. The recorder has its own guide.

The tiers changed. My rule now is that nothing shuts down for being on battery while the charge is above 15 %: all three tiers act at 15 % or at 8 minutes of runtime, with no on-battery timer. Before, the first tier went after 5 minutes on battery, at 60 % or at 45 minutes; the second at 35 % or 20 minutes; the third at 15 % or 8 minutes. The tiers are shared by both stations, so the AC180's changed too.

Still open: why the DJI's output dropped. I don't know the combined load at 09:01, beyond the gaming PC still being on it. I don't know which UPS or energy-saving settings in the station matter. The recorder has been writing since 11:58:59 on 2 November, and it is waiting for the next outage.

Filed under: linux, systemd, ups, power, nut

Read next#

• The UPS said 2 minutes at 95 % — the 11:39 false alarm: a recharge estimate read as runtime.
• The MQTT recorder container, step by step — the recorder that will catch the next switchover.
• Wake-on-LAN for r8169 NICs under NetworkManager — for the machines that don't come back by themselves.
• Twenty-five percent is a countdown — the original tier design, before this change.

Sources#

• journald.conf(5) — SyncIntervalSec=: journal files are synced to disk every 5 minutes by default, immediately only after CRIT, ALERT or EMERG messages.