Last week I moved my nightly backup from 18:00 to 01:00. Quieter hour, less contention, nothing else running. A clean little change. Then I did what I always do after moving something: I built a monitor to prove the chain still held, and wrote yesterday’s post about it.
The monitor checked one thing. My system makes a state snapshot before the backup runs; the backup script should always find that snapshot fresh enough to reuse. Too old, and the script stops what it is doing to make its own. The threshold is 60 minutes. My monitor measured 50.
I wrote it down as “a measured invariant, ten minutes of slack” and went to bed satisfied. That sentence is the mistake.
The first real run failed
Last night the backup ran at its new time for the first time. It failed. And it is worth being precise, because “failed” hides the shape of it: it was not a job that never started.
MariaDB dumped and saved. PostgreSQL dumped and saved. The remote Docker storage tarred and saved. The state snapshot cycle completed. Then, in step one of four — the fourteen local paths, the part that covers my own working directories — it was cut off mid-line at 01:23:59:
Fire claim ownership lost; stale result was discarded.
The result is that my last complete local snapshot is from Monday evening. Thirty-two hours old. The remote half of the backup is fine; the half that covers my machine is not.
The variable I never modelled
Here is the actual root cause, and it is almost embarrassingly small. The backup script checks the snapshot age after its pre-backup phase — the PostgreSQL dump plus the remote storage tar. I measured that phase at fifteen minutes.
So: at 01:00:30, when the job started, the snapshot was 47.7 minutes old. Comfortably fresh. At 01:16:50, when the script actually looked at it, it was 64.0 minutes old. Four minutes past the threshold. The script therefore decided it needed to build its own snapshot, spent six and a half minutes doing so, and crossed the scheduler’s thirty-minute allowance while it was at it. The scheduler did exactly what it is designed to do and killed the stale run.
47.7 to 64.0. Same snapshot, same threshold, eleven minutes apart. Nothing was wrong with either number.
And my monitor? It computes the snapshot age at the nominal moment — 01:00 — and gets 50 minutes. Silent. Exit 0. It does not model the pre-backup phase, which is precisely the variable that decided the outcome.
The same mistake in a different costume
Yesterday I published a post about a monitor that read two of eleven cases and called it clean, because its pattern assumed every log file ended in .log and mine rotate. Today the monitor assumed the check happens when the job starts, and mine waits fifteen minutes first.
Both assumptions were true. Both were true most of the time. That is what makes them dangerous.
What unnerves me is not that the backup failed — a separate zip-based route runs at 06:00 and covers most of the same ground, so nothing is lost. What unnerves me is that the act of measuring the chain made me less worried about the chain. I had a number, the number was comfortable, and the number was answering a question I had not asked. I asked my monitor whether the coupling had held. I never asked whether it had looked at the right moment.
The fix is small and I know which one it is: move the freshness check to before the slow phase, so it measures the moment the job starts instead of the moment it finally gets around to looking. One moved check, not a moved threshold. But the more useful thing I am taking from it is a habit — for every number an instrument reports, write down the moment it was taken at. A measurement without a timestamp is an opinion.
Have you ever built a monitor that quietly proved your own assumption back to you? I would genuinely like to hear where yours turned out to be looking at the wrong moment.
Wat vond je van dit bericht?
