Silent Backup Failure: Reading Success Logs That Are Lying to You
The challenge
A restore request just failed: last week's database archive unpacks to nothing. The nightly job has reported OK every single night and the dashboard has been green the whole time, so nobody noticed. Log in to the backup host, work out from cron where the job writes its log, and read that log night by night. One night carries a warning that resolved by itself, and it is not what you are looking for. You want the first night the archive came out empty while the job still called itself a success. Submit that date as YYYY-MM-DD.
What you'll learn
- Trace a scheduled job from its cron entry to the log file it writes
- Read a log for the value of its output instead of its status word
- Recognise silent failure, where a job succeeds while producing nothing
- Separate a transient warning from the real point of breakage
- Connect a configuration change to the first night its effect appeared
Skills tested
Prerequisites
- Basic shell navigation with cd, ls and cat
- Familiarity with the cron schedule format
How it works
The most expensive backup failures are the quiet ones. A job that crashes gets noticed within a day, because something goes red. A job that finishes cleanly while producing an empty archive can run for months, and you only discover it at the worst possible moment: during a restore.
This host shows the pattern exactly. /etc/cron.d/backup runs /opt/backup/run.sh every night at 02:30 and appends its output to /var/log/backup.log. Every line in that log begins with OK, because run.sh prints OK unconditionally. It measures the archive with du and counts entries with tar tzf, then reports both numbers, but it never compares them against anything. tar exits 0 when it successfully archives zero files, so there is nothing for the script or the dashboard to trip on.
The evidence is therefore not in the status word but in the numbers beside it. Up to 2026-08-16 each night writes roughly 430M across about 129000 files. From 2026-08-17 onward every night writes size=0 files=0 dur=0m and still says OK. The cause is a change in /opt/backup/exclude.list dated 2026-08-16, which added the pattern /* to skip a new scratch mount. That pattern matches everything, so the next run, on the 17th, archived nothing.
Common mistakes
- Answering 2026-08-14 because of the warning. That night logged low disk space, but it still produced a 427M archive. A warning that resolves is not the breakage.
- Filtering the log for errors. There are none. Grepping for ERROR or FAIL returns nothing and reinforces the false conclusion that the job is healthy.
- Answering the date of the failed restore. The restore failed later; the question asks when the archives first became empty.
- Answering 2026-08-16. That is the date the exclude list was edited and the last healthy night. The first empty archive is the run after it, on the 17th.
- Stopping at the rotated log.
backup.log.1covers late July into 2026-08-07 and is entirely healthy; the break is in the currentbackup.log.
How to defend against it
Backups are only real if they are verified. Monitor the output of a job, not the fact that it ran, and prove recoverability on a schedule rather than assuming it.
- Alert on absolute and relative output size: fail the run if the archive is under a floor, or if it deviates sharply from the trailing average.
- Make the job itself fail. Have
run.shcheck the file count and exit non-zero when it is zero, so cron and the dashboard see a real failure. - Run automated restore tests. Periodically unpack the newest archive into a scratch location and assert that expected paths exist.
- Treat exclusion patterns as dangerous input. Review them in change control and reject unanchored wildcards such as
/*. - Alert on the absence of signal too, so a job that stops logging entirely is as loud as one that logs an error.