Point-in-Time Recovery for MySQL Galera Cluster

**Update: 6th May, 2016 – This blog post has been updated to reflect ClusterControl v1.3.0

Data protection is vital for DB admins, especially when it involves data that is accessed and updated 24 hours a day. Clustering and replication are techniques that provide protection against failures, but what if a user or DBA issues a detrimental command against one of the databases? A user might erroneously delete or update the contents of one or more tables, drop database objects that are still needed during an update to an application, or run a large batch update that fails midway. How do we recover lost data? 

In a previous post, we showed you how to do a full restore from backup. Great, now you’ve restored up to the last incremental backup that was done at 6am this morning. But how about the rest of the data?

This is where you’d do a point-in-time recovery, to recover your data prior to the transaction that caused the problem. The procedure involves restoring the database from backups prior to the target time for recovery, then uses a redo log to roll the database forward to the target time. This procedure is a noteworthy practice that every DBA or sysadmin should be familiar with.

In this blog, we will show you how to do a point-in-time recovery of your Galera Cluster. An important component here is the  MySQL binary log, which contains events that describe all database changes. After the latest backup has been restored, the events in the binary log that were recorded after the backup was taken will be re-executed. Thus, it is possible to replay transactions up to the last consistent state of the database, right before the erroneous command was issued.

Binary Logging in MySQL Galera Cluster

By default, binary logs (if enabled) will be located under the MySQL data directory. Binary logs are not synced when a Galera node performs SST or IST during node initialization, or when using XtraBackup to backup the datadir. It is mandatory to enable log_slave_updates on a Galera node so events originating from other nodes in the cluster will be captured when local slave threads apply writesets.

To enable MySQL binary log on the cluster nodes, add the following lines to the [mysqld] section of MySQL configuration file (for ClusterControl users, use the Manage Configurations tab) on the database node(s) that you want to write binary logs (you can enable on all nodes since Galera is as fast as the slowest node). Thus, in any case, binary logging will come with a performance penalty:

log-bin=<binlog name>
log-slave-updates

Perform a stop/start node or rolling restart of the cluster to apply changes. For ClusterControl users, use the Manage >> Upgrades >> Rolling Restart.

Another way of doing this is to start each Galera node with –log-bin and –log-slave-updates options:

$ service mysql start --wsrep-cluster-address=gcomm://<donor node> --log-bin=<binlog name> --log-slave-updates

As of the time of writing, only backups taken using xtrabackup can be used to perform point-in-time recovery since it saves the binary log file and position for the snapshot inside xtrabackup_binlog_info under the backup directory. 

Starting from ClusterControl v1.2.4, mysqldump can also be used since it will mark the binary log file and position inside the dump files, provided binary logging is enabled. ClusterControl generates two mysqldump files in compressed gzip format. To retrieve the binary log file and position you may need to decompress the data dump file beforehand and look for MASTER_LOG_POS:

$ gunzip mysqldump_2013-010-25_035555_data.sql.gz
$ grep "MASTER_LOG_POS" mysqldump_2013-010-25_035555_data.sql
-- CHANGE MASTER TO MASTER_LOG_FILE='binlog.000016', MASTER_LOG_POS=78506

Scenario #1 - Recover Partially Lost Data

Let’s look at an example where a user accidentally truncated a table, and needs to recover the data. We pretend that the application and cluster still can serve requests, despite the wrongly truncated table. Fortunately, the database is frequently backed up using xtrabackup, and there is also a binary log of all changes. The Galera Cluster setup is illustrated as below:

We are going to restore our database to the point before a table (db1.t1) was truncated. We are going to recover the missing data and restore it back to the running Galera cluster.

From Backup Reports, we can see which backups are available:

Here is what we’re going to do:

1. Install garbd on C1 to maintain quorum for primary component.
2. Determine the binlog file and position before the event happened.
3. Borrow G1 by taking it out of the cluster for restoration purposes.
4. Restore to the specific timestamp using backups and binlog.
5. Export the restored data from G1 and import it to the running cluster (G2 and G3).
6. Have G1 rejoin the cluster.

1. Since we are going to take out G1, the cluster membership will decrease by one. Should something happen to one of the remaining two members, Galera will not be able to elect the primary component as there would not be any quorum. So we will install garbd on C1:

2. Let’s determine the binary log file and position before the TRUNCATE command. We suspect it happened between 17:30 and 18:30 on October 23rd. List out all binary log files:

mysql> SHOW BINARY LOGS
+---------------+-----------+
| Log_name      | File_size |
+---------------+-----------+
| binlog.000001 |       126 |
| binlog.000002 |      1197 |
| binlog.000003 |       126 |
| binlog.000004 |   6932594 |
+---------------+-----------+
4 rows in set (0.00 sec)

We can determine which binlog file recorded the event by verifying the modified time of the file. In this case, the event should be stored inside binlog.000004.

$ ls -al /var/lib/mysql
-rw-rw---- 1 mysql mysql       126 Oct 22 05:18 binlog.000001
-rw-rw---- 1 mysql mysql      1197 Oct 22 14:46 binlog.000002
-rw-rw---- 1 mysql mysql       126 Oct 22 14:46 binlog.000003
-rw-rw---- 1 mysql mysql   6943553 Oct 23 18:38 binlog.000004

Let’s find the binlog position before the TRUNCATE was executed. Use the mysqlbinlog tool with --base64-output=decode-rows to decode the binlog and send the output to a file called decoded.txt:

$ mysqlbinlog --start-datetime="2013-10-23 17:30:00" --stop-datetime="2013-10-23 18:30:00" /var/lib/mysql/binlog.000004 --base64-output=decode-rows --verbose > decoded.txt

Find the line number of the TRUNCATE event:

$ grep -n truncate decoded.txt
45375:truncate t1

Look up the position number before the TRUNCATE event. In this case, the binlog should be replayed up until position 6494999 because position 6495077 indicates the unwanted TRUNCATE event:

$ head -45375 decoded.txt | tail -15
### INSERT INTO `db1`.`t1`
### SET
###   @1=8875
###   @2='781673564aa9885eeea148ebc6a58b98'
###   @3='r7LdRPhMa4kUpOLQKy033KufSw9CGYsnpInwfT8TWRo='
###   @4=5645
###   @5='06:10:45 PM'
# at 6494972
#131023 18:10:45 server id 1  end_log_pos 6494999       Xid = 8978
COMMIT/*!*/# at 6494999
#131023 18:10:45 server id 1  end_log_pos 6495077       Query   thread_id=15487 exec_time=0     error_code=0
use `db1`/*!*/TIMESTAMP=1382551845/*!*/

We can conclude that after restoring the backups, we should replay the binlog from the recorded binlog file and position of the backup set, up until binlog.000004 on position 6494999.

3. We are going to perform the restore on one of the Galera nodes. Firstly, disable ClusterControl auto recovery temporarily by clicking on the power icons so they become red for Cluster and Node recovery, similar to screenshot below:

Then, take G1 out of the cluster. Make sure the server has the right binary log. Shutdown the server by using Nodes >> Shutdown Nodes >> Execute.

4. Start the recovery process by restoring the last backup set before the TRUNCATE happened (131023 18:10:45).

You will notice that the backup set contains one full backup and two incremental backups. Since we are going to restore up until backup ID 14, we need to exclude backup ID 15 from the set.

On ClusterControl node, you will find the backup under [backup_directory]/BACKUP-[id]. We have to perform manual extraction and preparation on the ClusterControl node, before copy the prepared data to the target node (G1).

a) Install Percona xtrabackup on ClusterControl node:

$ yum install http://www.percona.com/downloads/percona-release/redhat/0.1-3/percona-release-0.1-3.noarch.rpm
$ yum install epel-release
$ yum install percona-xtrabackup -y

b) Create a restoration directory, copy the full backup (under BACKUP-13) to that directory and extract it:

$ mkdir -p /restore/base
$ cp /home/ubuntu/backups/BACKUP-13/backup-full-2016-05-06_211000.xbstream.gz /restore/base
$ cd /restore/base
$ gunzip backup-full-2016-05-06_211000.xbstream.gz
$ xbstream -x < backup-full-2016-05-06_211000.xbstream
$ rm backup-full-2016-05-06_211000.xbstream

c) You should now have the base backup extracted under /restore/base directory.

d) Create another restoration directory for the incremental backup, copy the incremental backup from BACKUP-14 and extract it:

$ mkdir -p /restore/incremental1
$ cp /home/ubuntu/backups/BACKUP-14/backup-incr-2016-05-06_214507.xbstream.gz /restore/incremental1
$ cd /restore/incremental1
$ gunzip backup-incr-2016-05-06_214507.xbstream.gz
$ xbstream -x < backup-incr-2016-05-06_214507.xbstream
$ rm backup-incr-2016-05-06_214507.xbstream

e) Now we have the backups extracted. Next we have to prepare the base and incremental backups:

$ innobackupex --apply-log --redo-only /restore/base
$ innobackupex --apply-log --redo-only /restore/base --incremental-dir=/restore/incremental1

Ensure you got "completed OK!" at the end of the lines. Now our backup is ready to be copied over to the target node.

Copy the corresponding directory to node G1 for restoration:

$ scp -r /restore/base G1:~

Now log into G1, rename the older MySQL datadir (we want to preserve the binlog), copy the prepared data and apply correct ownership:

$ mv /var/lib/mysql /var/lib/mysql2
$ mkdir /var/lib/mysql
$ innobackupex --copy-back ~/base/13
$ chown -R mysql.mysql /var/lib/mysql

Take note of the binary log file and position for the restored data:

$ cat /var/lib/mysql/xtrabackup_binlog_info
binlog.000004   5840269

Start the mysql service with a dummy address:

$ service mysql start --wsrep-cluster-address=dummy://

Replay the binary log up until the determined position and send the output to the MySQL Server on G1:

$ mysqlbinlog /var/lib/mysql2/binlog.000004 --start-position=5840269 --stop-position=6494999 | mysql -uroot -p

5. Export the data for the table so we can load it into the running cluster. We will export all columns except the primary key column because the AUTO_INCREMENT values have been repeated since the truncate happened. This will avoid DUPLICATE ENTRY errors:

mysql> SELECT data,extra,value,time INTO OUTFILE '/tmp/truncated_data.sql' FIELDS TERMINATED BY ',' OPTIONALLY ENCLOSED BY '"' LINES TERMINATED BY 'n' FROM db1.t1
Query OK, 2725 rows affected (0.00 sec)

Now you can import the data into the running cluster. Log into one of the nodes in the cluster (e.g G2) and start the import process:

LOAD DATA LOCAL INFILE 'truncated_data.sql' INTO TABLE db1.t1 FIELDS TERMINATED BY ',' OPTIONALLY ENCLOSED BY '"' LINES TERMINATED BY 'n' (@col1,@col2,@col3,@col4) SET data=@col1, extra=@col2, value=@col3, time=@col4
Query OK, 2725 rows affected (0.26 sec)
Records: 2725  Deleted: 0  Skipped: 0  Warnings: 0

6. Finally, restart G1 and let it rejoin the cluster by specifying G2 as the donor:

$ service mysql restart --wsrep-cluster-address=gcomm://10.128.77.117

The cluster should now running with a complete data set. You may remove garbd on C1 as it is not needed anymore. Don’t forget to re-enable ClusterControl auto recovery by by clicking on the power icons so they become green for Cluster and Node recovery, similar to screenshot below:

Scenario #2 - Recover the Entire Database Cluster

In some (most) situations a wrongly truncated table may cause the entire database useless because it is in an important part of the application. In this example, we will look at how to recover the entire database up to the point when the truncate table happened. The setup and pre-conditions are the same as in the previous scenario.

We are going to restore our database to the point before a table (db1.t1) was truncated. We are going to recover the missing data and restore it back to the running Galera cluster.

From "Backup Reports", we can see which backups are available:

Here is what we’re going to do:

1. Take the application servers offline (the site is now offline). This step is not shown here.
2. Determine the binlog file and position before the event happened.
3. Restore the Xtrabackup (full and incremental backups) using ClusterControl.
4. Restore to the specific timestamp using backups and binlog.

Starting the procedure from step 2:

2. Let’s determine the binary log file and position before the TRUNCATE command. We suspect it happened between 17:30 and 18:30 on October 23rd. List out all binary log files:

mysql> SHOW BINARY LOGS
+---------------+-----------+
| Log_name      | File_size |
+---------------+-----------+
| binlog.000001 |       126 |
| binlog.000002 |      1197 |
| binlog.000003 |       126 |
| binlog.000004 |   6932594 |
+---------------+-----------+
4 rows in set (0.00 sec)

We can determine which binlog file recorded the event by verifying the modified time of the file. In this case, the event should be stored inside binlog.000004. On one of the nodes writing binary logs do (in this example we use the node G1)

$ ls -al /var/lib/mysql
-rw-rw---- 1 mysql mysql       126 Oct 22 05:18 binlog.000001
-rw-rw---- 1 mysql mysql      1197 Oct 22 14:46 binlog.000002
-rw-rw---- 1 mysql mysql       126 Oct 22 14:46 binlog.000003
-rw-rw---- 1 mysql mysql   6943553 Oct 23 18:38 binlog.000004

Let’s find the binlog position before the TRUNCATE was executed. Use the mysqlbinlog tool with --base64-output=decode-rows to decode the binlog and send the output to a file called decoded.txt:

$ mysqlbinlog --start-datetime="2013-10-23 17:30:00" --stop-datetime="2013-10-23 18:30:00" /var/lib/mysql/binlog.000004 --base64-output=decode-rows --verbose > decoded.txt

Find the line number of the TRUNCATE event:

$ grep -n truncate decoded.txt
45375:truncate t1

Look up the position number before the TRUNCATE event. In this case, the binlog should be replayed up until position 6494999 because position 6495077 indicates the unwanted TRUNCATE event:

$ head -45375 decoded.txt | tail -15
### INSERT INTO `db1`.`t1`
### SET
###   @1=8875
###   @2='781673564aa9885eeea148ebc6a58b98'
###   @3='r7LdRPhMa4kUpOLQKy033KufSw9CGYsnpInwfT8TWRo='
###   @4=5645
###   @5='06:10:45 PM'
# at 6494972
#131023 18:10:45 server id 1  end_log_pos 6494999       Xid = 8978
COMMIT/*!*/# at 6494999
#131023 18:10:45 server id 1  end_log_pos 6495077       Query   thread_id=15487 exec_time=0     error_code=0
use `db1`/*!*/TIMESTAMP=1382551845/*!*/

We can conclude that after restoring the backups, we should replay the binlog from the recorded binlog file and position of the backup set, up until binlog.000004 on position 6494999.

3. Start the recovery process by restoring the last backup set before the TRUNCATE happened (131023 18:10:45).

You will notice that the backup set contains one full backup and two incremental backups. Since we are going to restore up until backup ID 14, we need to exclude backup ID 15 from the set. To achieve this, we will do the following:

Login into cmon DB and set apart the parentid of backup that we want to exclude:

mysql> UPDATE cmon.mysql_backup SET parentid=1000 WHERE backupid=15

Now ClusterControl should report the backup set as below:

Before we start the restoration, we have to preserve the existing binary logs so we can perform point-in-time recovery later after Xtrabackup restoration completes. On G1:

$ mkdir ~/binary_logs
$ cp -pfR /var/lib/mysql/binary* ~/binary_logs

Click on the "Restore Backup" for backup set 13, and specify the target DB node (G1):

Take note that ClusterControl will restore the backup on the target DB node and bootstrap the cluster based on this node. The other nodes will then rejoin and grab the newly restored data from G1. You can monitor the restoration process under ClusterControl > Logs > Jobs:

Once the restoration is completed, your cluster should be up and running with a freshly restored data. 

4. Take note of the binary log file and position for the restored data on G1:

$ cat /var/lib/mysql/xtrabackup_binlog_info
binlog.000004   5840269

5. Replay the binary log up until the determined position and send the output to the MySQL Server on G1:

$ mysqlbinlog ~/binary_logs/binlog.000004 --start-position=5840269 --stop-position=6494999 | mysql -uroot -p

The cluster will start to replay the log and catch up until the determined point. Congratulations, you have now recovered your lost data!