DB-유

Point-in-Time Recovery with MySQL Binary Logs

· mysql, backup, recovery

A nightly mysqldump gets you back to 02:30. If someone runs DELETE FROM orders without a WHERE at 14:12, restoring that dump throws away almost twelve hours of business. I dread that scenario, and point-in-time recovery (PITR) is how I sleep anyway: restore the last full backup, then replay the binary logs up to the second before the bad statement.

Here is the whole procedure on MySQL 5.7. Before the incident you need binary logging turned on, a full backup with its binlog coordinates recorded (mysqldump --master-data=2 or XtraBackup's xtrabackup_binlog_info), every binlog since then, and a scratch server to restore into. Never replay logs blindly on production.

Keep the binary logs

In /etc/my.cnf (CentOS 7) or /etc/mysql/mysql.conf.d/mysqld.cnf (Ubuntu 16.04):

[mysqld]
server-id        = 1
log_bin          = /var/lib/mysql/mysql-bin
binlog_format    = ROW
expire_logs_days = 14
sync_binlog      = 1
max_binlog_size  = 512M

expire_logs_days must be longer than your backup interval with a safety margin. ROW format replays exactly what changed, which avoids surprises with non-deterministic statements. Restart the service and confirm with SHOW MASTER STATUS;.

I also copy finished binlog files off the server every hour, because a disk failure that takes the data usually takes the binlogs too:

rsync -a --exclude='mysql-bin.index' /var/lib/mysql/mysql-bin.* backup-host:/backup/binlogs/db1/

A backup that records the position

mysqldump --defaults-extra-file=/root/.my.cnf --all-databases --single-transaction \
  --routines --triggers --events --master-data=2 --flush-logs | gzip > /backup/full-$(date +%F).sql.gz

--flush-logs rotates the binlog at backup time, so replay starts cleanly at the beginning of a new file. The coordinates land in the dump as a comment:

zcat /backup/full-2018-01-28.sql.gz | grep -m1 'CHANGE MASTER'
-- CHANGE MASTER TO MASTER_LOG_FILE='mysql-bin.000042', MASTER_LOG_POS=154;

Find the bad statement

When the incident happens, stop writing to the affected tables if you can, then find the event. With ROW format the statement text is not in the log, so decode rows verbosely and search for the table:

mysqlbinlog --no-defaults --base64-output=DECODE-ROWS --verbose \
  --start-datetime='2018-01-29 14:00:00' --stop-datetime='2018-01-29 14:20:00' \
  /var/lib/mysql/mysql-bin.000043 | grep -n -B5 'DELETE FROM `shop`.`orders`' | head -30

Above the first ### DELETE FROM block you will find a header like:

# at 88231
#180129 14:12:07 server id 1  end_log_pos 88302 CRC32 0x1f2a3b4c    Query   thread_id=5121  exec_time=0 error_code=0
BEGIN

The # at 88231 line is the start position of the transaction that contains the damage. That is where replay must stop.

Restore the full backup on the recovery host

zcat /backup/full-2018-01-28.sql.gz | mysql --defaults-extra-file=/root/.my.cnf

Do this with sql_log_bin off if the recovery host has binary logging enabled, otherwise you double the disk usage for nothing: mysql -e 'SET sql_log_bin=0; SOURCE /path/dump.sql' or simply disable log_bin on the scratch instance.

Replay up to the bad transaction

Feed all files from the backup position to the stop position through mysqlbinlog in one invocation so that transactions spanning file boundaries are handled correctly:

mysqlbinlog --no-defaults --start-position=154 --stop-position=88231 \
  /backup/binlogs/db1/mysql-bin.000042 /backup/binlogs/db1/mysql-bin.000043 \
  | mysql --defaults-extra-file=/root/.my.cnf

--start-position applies to the first file and --stop-position to the last one, which is what you want. If you also need the transactions after the mistake (everything the application wrote after 14:12 that is still valid), run a second pass with --start-position set to the end_log_pos of the bad transaction's COMMIT and no stop position.

Check the result before touching production

SELECT COUNT(*), MAX(created_at) FROM shop.orders;

The count should match what you expect just before 14:12 and MAX(created_at) should be a few seconds before the incident. Compare a handful of known rows with the application team before copying the table back to production, typically with mysqldump shop orders | mysql -h prod shop or by swapping in the table with RENAME TABLE.

Errors I have hit

  • ERROR: Error in Log_event::read_log_event(): 'Sanity check failed', data_len: ..., event_type: ...: the binlog is truncated or corrupt, usually the file that was being written when the server crashed. Recover as far as the last complete event with --stop-position just before the corruption.
  • mysqlbinlog: unknown variable 'default-character-set=utf8mb4': the [client] section of your my.cnf contains an option mysqlbinlog does not understand. That is why the examples use --no-defaults.
  • ERROR 1062 (23000) at line ...: Duplicate entry during replay: you started at the wrong position and are re-applying transactions already in the backup. Recheck the CHANGE MASTER TO comment; note that XtraBackup's position points after the last applied event, exactly like the dump.
  • Replay is very slow: pipe through mysql --init-command='SET sql_log_bin=0, foreign_key_checks=0, unique_checks=0' and set innodb_flush_log_at_trx_commit=2 on the scratch server for the duration.

Binlogs on, retained long enough, backup position recorded. Check all three on every server today, because you can't fix any of them after the DELETE.