October 28, 2013
By Severalnines

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`/*!*/;
SET TIMESTAMP=1382551845/*!*/;
truncate t1

 

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 by adding following line into /etc/cmon.cnf on the ClusterControl host:

enable_autorecovery=0

 

Restart cmon service on the ClusterControl host:

$ service cmon restart

 

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. 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:

Install restoration tools and start to prepare the backup set 13 by using the following commands on C1 (for more information on how to perform xtrabackup restoration, read this article):

$ s9s_backup --install -i 1
$ s9s_backup --restore -i 1 -b 13 -t /restore

 

ClusterControl will prepare the backup in the /restore/<backup_set> directory. Copy the corresponding directory to node G1 for restoration:

$ scp -r /restore 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 ~/restore/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 have 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 commenting out or removing the following line in /etc/cmon.cnf (on the ClusterControl host):

#enable_autorecovery=0

 

Restart the cmon service to apply the change:

$ service cmon restart

 

 

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. Take down the database cluster
  3. Determine the binlog file and position before the event happened.
  4. Restore to the specific timestamp using backups and binlog.
  5. Have G2 and G3 rejoin cluster.

 

Starting the procedure from step 2:

 

2. Take down the database cluster. First, disable ClusterControl auto recovery by adding following line into /etc/cmon.cnf on the ClusterControl host:

enable_autorecovery=0

 

Restart cmon service on the ClusterControl host:

$ service cmon restart

 

Then do:

$ s9s_galera --stop-cluster -i 1

 

3. 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`/*!*/;
SET TIMESTAMP=1382551845/*!*/;
truncate t1

 

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.

 

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. 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:

Install restoration tools and start to prepare the backup set 13 by using the following commands on C1 (for more information on how to perform xtrabackup restoration, read this article):

$ s9s_backup --install -i 1
$ s9s_backup --restore -i 1 -b 13 -t /restore

 

ClusterControl will prepare the backup in the /restore/<backup_set> directory. Copy the corresponding directory to node G1 for restoration:

$ scp -r /restore 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 ~/restore/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

 

Bootstrap the cluster by starting up MySQL service on G1:

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

 

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. Finally, restart G2 and G3, and have them rejoin the cluster by specifying G1 as the donor:

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

 

The cluster should now running with a complete data set. Don’t forget to re-enable ClusterControl auto recovery by commenting out or removing the following line in /etc/cmon.cnf (on the ClusterControl host):

#enable_autorecovery=0

 

Restart the cmon service to apply the change:

$ service cmon restart

 

Congratulations, you have now recovered your lost data!