A migration normalised a currency column and got the conversion factor wrong for one of the three currencies. It ran in ninety seconds, the deploy went green, and forty-one thousand order totals were wrong by a factor of a hundred. The rollback took ninety seconds and restored the code, which fixed nothing.
The symptom
mysql> SELECT currency, COUNT(*), AVG(total_cents)
-> FROM orders GROUP BY currency;
| GBP | 388104 | 4912 |
| EUR | 41208 | 512044 | ← 100x
| USD | 22104 | 5188 |
-- the migration converted EUR from a decimal column to
-- cents, and the source column was already in cents.
-- and the rollback:
$ ./bin/release "$(./bin/previous-digest)"
released in 14s
-- the code is back. the rows are not.A rollback is a code operation and the damage was a data operation, which is a distinction nobody makes until the first time it matters. The deploy pipeline had a rehearsed ninety-second rollback and no rehearsed recovery for this.
Why it happens
Migrations are tested against a development dataset where the wrong branch may not be exercised — this one had no EUR orders in the fixtures. The migration was correct for the case it was tested against and the case it was not tested against was forty-one thousand rows.
The fix
Establishing the blast radius
-- the audit log was the thing that made this tractable
SELECT COUNT(DISTINCT subject_id) FROM audit_log
WHERE action = 'migration.2022_06_14_normalise_currency'
AND occurred_at BETWEEN ? AND ?;
-- 41,208
-- and the before values, because the migration recorded
-- them:
SELECT subject_id, before->>'$.total_cents' AS was
FROM audit_log
WHERE action = 'migration.2022_06_14_normalise_currency';A migration that records what it changed is the difference between a targeted repair and a full restore, and it is four lines added to a migration that nobody writes because migrations are assumed to be correct. This one had them because a previous incident had produced the rule.
Without them the recovery is a restore of the whole database to the moment before, which loses every legitimate write since — ninety minutes of orders in this case, which is a second incident caused by fixing the first.
Point-in-time recovery, and the settings that must already be right
$ mysqlbinlog --start-datetime='2022-06-14 00:00:00'
--stop-datetime='2022-06-14 09:40:00'
/var/log/mysql/binlog.000412 | mysql scratch
# and the settings that decide whether this is possible,
# all of which have to be right BEFORE you need them:
# log_bin ON
# binlog_format ROW
# binlog_expire_logs_seconds 604800 (7 days)
# server_id set
# the binlogs on separate storage from the dataThe retention setting is the one that decides whether a Monday morning problem can be recovered to Friday, and the default in several managed configurations is short enough that it cannot. Row format is required for a reliable replay and is also what makes the logs large, which is the trade made by whoever configured the server and rarely revisited.
Putting the binary logs on different storage from the data directory is the detail that matters during a disk failure — the recovery mechanism sharing a failure domain with the thing it recovers is a common and expensive arrangement.
Restoring one table rather than the database
# 180 GB restored to fix one table is hours of downtime
# for a problem affecting 41,000 rows.
# into a scratch schema, from the nightly backup
$ mysql scratch < /backup/2022-06-14-0200.sql
# replay the binlog up to the moment before the migration
$ mysqlbinlog --stop-datetime='2022-06-14 09:39:00'
binlog.000412 | mysql scratch
# and copy back only what is needed
$ mysqldump scratch orders --where='currency="EUR"'
| mysql shop_recoveryRestoring into a scratch schema rather than over the live one is what makes this recoverable if the recovery is wrong, which it will be on the first attempt. The copy-back is the step with its own hazards — foreign key ordering, triggers firing, and a table that has been written to since the backup — and doing it as a targeted update rather than a table replacement avoids most of them.
-- what actually ran: a targeted update, from the audit log
UPDATE orders o
JOIN audit_log a ON a.subject_id = o.id
SET o.total_cents = CAST(a.before->>'$.total_cents' AS UNSIGNED)
WHERE a.action = 'migration.2022_06_14_normalise_currency'
AND o.currency = 'EUR'
AND o.total_cents = CAST(a.after->>'$.total_cents' AS UNSIGNED);
-- the last condition is the safety: only revert rows that
-- still hold the value the migration wrote. anything
-- changed since is left alone.The final condition is what makes this safe to run ninety minutes later: a row edited by a customer service agent in the meantime is not reverted, because its current value no longer matches what the migration wrote. Without it the repair overwrites legitimate work and produces a third incident.
The ninety minutes of legitimate writes
The reason a full restore was unacceptable is the ninety minutes between the migration and the decision, during which the application kept working — four hundred and eleven new orders, sixty-two customer service edits and a payment reconciliation run.
-- what a restore-to-09:39 would have discarded:
SELECT 'orders', COUNT(*) FROM orders WHERE created_at > '09:39'
UNION ALL
SELECT 'payments', COUNT(*) FROM payments WHERE created_at > '09:39'
UNION ALL
SELECT 'edits', COUNT(*) FROM audit_log
WHERE occurred_at > '09:39' AND actor_type = 'user';
| orders | 411 |
| payments | 388 |
| edits | 62 |
-- 411 orders that customers had paid for.Restoring to before the migration and replaying the binlog forward is the alternative, and it replays the migration too — so the replay has to stop, skip the migration’s transactions and continue, which is a manual edit of a binlog position under time pressure. That is a procedure with a very low success rate at ten in the morning.
The targeted update avoids all of it, and the reason it was available is entirely that the migration recorded its before values. Without them the choice is between losing four hundred orders and reconstructing forty-one thousand totals from a currency conversion nobody can now verify.
The decision, and who made it
09:41 the migration completes. deploy green.
10:04 a customer service agent reports an order total
that looks wrong.
10:11 the shape is identified: EUR only, factor of 100.
10:14 the code is rolled back. this fixes nothing and
takes 90 seconds, so it is done first.
10:18 the decision point:
a) full restore to 09:39 — loses 411 orders
b) targeted repair — needs the audit log
c) do nothing until we understand it fully
(b), on condition that (a) stays available.
10:22 EUR checkout disabled. new orders in EUR stop.
10:51 the repair runs on a restored copy, verified.
11:09 the repair runs on production. 41,208 rows.
11:14 EUR checkout re-enabled.Disabling EUR checkout at 10:22 is the step that made the rest calm: it stopped the affected set growing, which turned a moving target into a fixed one. It also cost thirty minutes of European sales, which is a trade somebody had to be authorised to make and was — because the incident policy said who.
Running the repair against a restored copy first, and diffing the result, is the twenty minutes that prevented a second incident. The first version of the UPDATE was missing the final guard condition and would have reverted eleven rows that an agent had corrected by hand.
The rehearsal, and the objective that was four times the estimate
$ ./bin/restore-drill --latest --into=scratch
download backup 4m 12s
mysql < backup.sql 38m 44s
replay binlog 6m 08s
verify 2m 21s
----------------------------
total 51m 25s
# the documented RTO was 15 minutes.
# nobody had measured it since 2019, when the database
# was 12 GB.A recovery time objective that has not been measured since the data was a fifth of its current size is a number in a document rather than a commitment. Measuring it turned a reliability conversation into a capacity one, which is the more useful conversation and would not have happened otherwise.
The thirty-eight minutes of loading a logical dump is the dominant cost, and it is the reason a physical backup — a filesystem snapshot or a block-level copy — is worth the extra machinery on a database this size. That is a change with its own project attached and was scheduled rather than done in the moment.
A backup that is verified rather than taken
# weekly, automated, against the most recent backup
./bin/restore-drill --latest --into=scratch
# and the verification, which is the half that is skipped
./bin/restore-verify scratch <<'SQL'
SELECT 'orders', COUNT(*) FROM orders
UNION ALL SELECT 'customers', COUNT(*) FROM customers;
SQL
# checked against the same query on production, allowing
# for the backup's age. a count that is 0 or wildly wrong
# is a backup that succeeded and contains nothing.A backup job reporting success proves a file was written, which is a different claim from the data being recoverable — and a mysqldump that fails partway produces a valid SQL file containing part of the database. Row counts per table, compared against production, is a crude check that catches exactly that.
The migration practice that came out of it
written down afterwards, and enforced in review:
a migration that UPDATEs rows must:
record before and after in the audit log
be reversible, or say in a comment why not
have a test with a fixture for every branch —
every currency, every status, every null case
report a row count on completion, so an unexpected
count is visible in the deploy log
and the one that would have caught this specific bug:
a dry-run mode that prints the first 20 changes
without applying themThe dry-run mode is the cheapest of the five and is the one that would have caught it — printing twenty proposed changes would have shown a EUR total going from 4,900 to 490,000 on a screen somebody was looking at. It costs a conditional in the migration and an extra minute in the deploy.
Verifying it worked
$ mysql -Nse "SELECT currency, AVG(total_cents) FROM orders
GROUP BY currency"
GBP 4912
EUR 5120 # was 512044
USD 5188
$ mysql -Nse "SELECT COUNT(*) FROM orders o
JOIN audit_log a ON a.subject_id = o.id
WHERE a.action LIKE 'migration.2022_06_14%'
AND o.total_cents <> CAST(a.before->>'$.total_cents' AS UNSIGNED)"
0 # every affected row is back to its prior value
# and the drill, now weekly:
$ ./bin/restore-drill --latest --into=scratch
total 49m 02s (target: 60m, revised from 15m)Revising the objective upwards to something achievable is the honest outcome of the drill, and it is a better position than a fifteen-minute target nobody could meet. The number is now measured weekly and any drift is visible before it matters.
What this costs
Storage for seven days of binary logs, a weekly drill that occupies a machine for an hour, and a scratch environment large enough to hold a full restore. That is a real ongoing cost for a capability used once and it is the cost of the capability existing at all — a restore procedure first attempted during an incident is a procedure that does not work.
The audit log requirement on migrations is the other cost and it is friction on every schema change. Four lines and a test fixture per branch is not much and it is enough that somebody will skip it under deadline pressure, which is why it is a review checklist item rather than a convention — and a review checklist is only as good as the reviewer.
It is also worth saying plainly that none of this prevents the bug. A migration with a wrong conversion factor will still write wrong data; what changed is that the damage is bounded, identifiable and reversible in an hour rather than being a full restore that loses ninety minutes of legitimate work. That is the whole claim.