The question in the meeting was how long it would take to recover from a total loss of the database server. Nobody knew. The backup had run every night for two years and exited zero every time, and that was the entire body of evidence — which is a much weaker position than it sounds, and it is the normal position.
The symptom
$ crontab -l | grep backup
0 2 * * * /usr/local/bin/backup.sh >> /var/log/backup.log 2>&1
$ cat /usr/local/bin/backup.sh
#!/bin/bash
mysqldump shop | gzip > /backup/shop-$(date +%F).sql.gz
$ tail -2 /var/log/backup.log
# (empty. two years of silence, which was read as success.)
$ ls -la /backup/ | tail -3
-rw-r--r-- 1 root root 412M Dec 8 02:04 shop-2019-12-08.sql.gz
-rw-r--r-- 1 root root 412M Dec 9 02:04 shop-2019-12-09.sql.gz
-rw-r--r-- 1 root root 14K Dec 10 02:00 shop-2019-12-10.sql.gz ← ?Fourteen kilobytes. The disk had filled at two in the morning, gzip had written what it could, and the pipeline’s exit code was gzip‘s rather than mysqldump‘s — so the script exited zero on a truncated backup. Without pipefail that is the documented behaviour of a shell pipeline.
Why it happens
A backup is written every day and read approximately never, so every property except “the file exists” is untested. The exit code, the completeness, the character set, the presence of stored programs, and whether the thing can actually be restored are all unverified until the day they matter.
The recovery time is unmeasured for the same reason. It is a number that only appears during a restore, and the only restores anybody does are the ones during an incident — which is the worst possible moment to discover it is four hours.
The fix
A dump that fails when it fails
#!/usr/bin/env bash
set -euo pipefail # the line that was missing
file="/backup/shop-$(date +%F).sql.gz"
mysqldump
--single-transaction
--routines --triggers --events
--hex-blob
--set-gtid-purged=OFF
shop | gzip > "$file"
# the three checks that make the exit code mean something
[ "$(stat -c%s "$file")" -gt 100000000 ] || { echo 'too small'; exit 1; }
gzip -t "$file"
zcat "$file" | tail -1 | grep -q 'Dump completed'pipefail is the fix for the specific failure above and the three checks are what catch the ones it does not. The trailing marker is the important one: a dump truncated by a disk filling restores without complaint right up to the point where the data stops, so file size alone is not sufficient evidence.
--routines --triggers --events are not defaults, and a restore missing every stored procedure is a database that looks complete and behaves differently. --single-transaction gives a consistent snapshot on InnoDB without locking, and it silently does nothing for MyISAM tables — which a legacy schema will have exactly one of, usually a session table.
A restore on a schedule, asserting on row counts
#!/usr/bin/env bash
set -euo pipefail
latest=$(ls -t /backup/shop-*.sql.gz | head -1)
start=$(date +%s)
mysql -e 'DROP DATABASE IF EXISTS restore_check; CREATE DATABASE restore_check;'
zcat "$latest" | mysql restore_check
elapsed=$(( $(date +%s) - start ))
tables=$(mysql -Nse "SELECT COUNT(*) FROM information_schema.tables
WHERE table_schema='restore_check'")
orders=$(mysql -Nse 'SELECT COUNT(*) FROM restore_check.orders')
routines=$(mysql -Nse "SELECT COUNT(*) FROM information_schema.routines
WHERE routine_schema='restore_check'")
[ "$tables" -ge 42 ] && [ "$orders" -gt 0 ] && [ "$routines" -ge 4 ]
echo "restore ok: ${elapsed}s, ${tables} tables, ${orders} orders"Asserting on counts turns the restore from a ritual into a test — a dump that restores and contains an empty orders table fails loudly. The routine count is the one that catches a mysqldump invocation somebody simplified.
The elapsed time is the number the meeting wanted, and it only exists because something measures it weekly. On this database it was 1 hour 48 minutes, which was roughly four times what anybody had assumed and immediately changed the conversation about what the backup strategy needed to be.
Point in time, and the binlogs nobody was keeping
# my.cnf
log_bin = /var/log/mysql/mysql-bin
binlog_format = ROW
binlog_expire_logs_seconds = 1209600 # 14 days
sync_binlog = 1
# and the half that matters: they must not live only on this host
# */5 * * * * rsync -a --remove-source-files /var/log/mysql/mysql-bin.[0-9]*
# backup@offsite:/binlogs/shop/A nightly dump means the worst case is losing a day, and a day of orders is not an acceptable answer to anybody outside engineering. The binlogs turn that into losing five minutes, which is the rsync interval.
# the recovery, practised on a copy
$ zcat /backup/shop-2019-12-09.sql.gz | mysql shop
$ mysqlbinlog --start-datetime='2019-12-09 02:00:00'
--stop-datetime='2019-12-09 14:22:00'
/binlogs/shop/mysql-bin.0004* | mysql shop
# and the check that the stop point was right
mysql> SELECT MAX(placed_at) FROM orders;
2019-12-09 14:21:58ROW format is larger than STATEMENT and is the only one that replays deterministically, which is the whole point. Practising the replay once, on a copy, is what converts this from a configuration setting into a procedure somebody can follow at three in the morning — and the stop-datetime is the part that needs practising, because getting it wrong replays the mistake you were recovering from.
Encryption, and where the key must not be
# encrypt to a public key. the private key is not on this machine.
mysqldump ... | gzip |
openssl enc -aes-256-cbc -pbkdf2 -pass file:/etc/backup/passphrase
> "$file.enc"
# better: asymmetric, so the backup host cannot decrypt what it wrote
mysqldump ... | gzip |
gpg --encrypt --recipient [email protected] --trust-model always
> "$file.gpg"A symmetric passphrase in a file on the same host as the backups protects against the offsite copy being read and not against the host being compromised, which is the more likely scenario. Encrypting to a public key means the machine writing backups cannot read them, and the private key lives somewhere a person has to go and get it.
The obvious risk is losing the key, and it is a real one — an encrypted backup with no key is not a backup. Whatever holds it needs to be as durable as the backups themselves and independently recoverable, which usually means a password manager the whole team can reach rather than one person’s laptop.
Verifying it worked
# the weekly restore, in the log where somebody sees it
$ journalctl -u restore-check --since '5 weeks ago' | grep 'restore ok'
restore ok: 6482s, 44 tables, 4118204 orders
restore ok: 6511s, 44 tables, 4162880 orders
restore ok: 6390s, 44 tables, 4204118 orders
# and the deliberate failure, to prove the check checks
$ truncate -s 14K /backup/shop-test.sql.gz
$ ./restore-check.sh
ERROR 2013 (HY000): Lost connection to MySQL server during query
restore-check failed (exit 1)Breaking a backup on purpose and confirming the check fails is the step that distinguishes a monitor from a decoration. It is also the only way to find out that the check was asserting on a table that happens to be empty in a truncated dump and would have passed.
The consistent 1:48 across five weeks is the number that got written down and told to people, and it is what led to a read replica being provisioned — because the answer to “how long to recover” turned out to be unacceptable, which is a thing you can only learn by measuring it.
What this costs
Storage, and an hour a week of a machine nobody sees. The restore check needs somewhere to restore to, which is either a spare host or a scheduled instance, and it is running a two-hour job weekly for a result that is almost always the same. That is genuinely a cost and it is small against the alternative, which is discovering the number during an incident.
The awkward part is that the number, once measured, usually demands a response. Two hours of recovery time is unacceptable for most businesses and the fix is a replica, which is another machine, another thing to monitor and another set of failure modes. Measuring it means owning it — which is the correct outcome and is more work than not measuring it, and that is why so few teams do.