MySQL – Recover Data Using mysqlbinlog

Our company just launched a new shopping cart web application and currently is under user acceptance phase. Last night, they discovered one bug which cause the payment not synchronize with the sales order data. They thought that it is a fault transaction and proceed to delete the data to synchronize the payment back.

Now they want me to recover only the deleted data which related to the tblpayment between 9 PM to 11 PM. The worse thing about this is I do not activate any MySQL backup yet because I thought it is just for testing. Luckily, I am using InnoDB (XtraDB) and activated binary logging. This could save my day!

I am using following variables:

OS: CentOS 6.2 64bit
MySQL: Percona XtraDB Cluster version 5.5.24, wsrep_23.6.r341
Database: webshop
Tables: tblpayment

1.  Let see if we have binary log active in our server. Login into MySQL console:

mysql> SHOW BINARY logs;
+------------------+------------+
| Log_name         | File_size  |
+------------------+------------+
| mysql-bin.000022 | 12497220   |
| mysql-bin.000023 | 828371469  |
+------------------+------------+

2. Before we start recovering, it is good to flush the binlog and create a full backup:

$ mysqladmin -u root -p flush-logs
$ mysqldump  -u root -p webshop > webshop.sql

3. You should see that a new binary log has been generated as below:

mysql> SHOW BINARY logs;
+------------------+------------+
| Log_name         | File_size  |
+------------------+------------+
| mysql-bin.000022 | 12497220   |
| mysql-bin.000023 | 828371469  |
| mysql-bin.000024 | 4280       |
+------------------+------------+

4. There are several types of binlog format and I am using ROW format as refer to my global variables:

mysql> SHOW GLOBAL VARIABLES LIKE 'binlog_format';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | ROW   |
+---------------+-------+
1 row in set (0.00 sec)

5. We will use a tool in MySQL/Percona called mysqlbinlog. This application will help us retrieve our binary log. As we know that last night, the moment that we want to recover to, all database transaction will be log inside mysql-bin.000023. So we will use mysqlbinlog to read the mysql-bin.000023 between 9 PM to 11 PM as below:

$ mysqlbinlog --start-datetime="2012-07-27 21:00:00" --stop-datetime="2012-07-27 23:00:00" mysql-bin.000023 > recovery.txt

6. Since I am using ROW binlog format, mysqlbinlog will retrieve the data in encoded base64 format. I need to have something understandable to read and analyze so I can recover the data just before the time when the data deleted from database. So we need to add decoded option to the previous command:

$ mysqlbinlog --start-datetime="2012-07-27 21:00:00" --stop-datetime="2012-07-27 23:00:00" mysql-bin.000023 --base64-output=decode-rows --verbose > recover_decoded.txt

7. Now we have something understandable to read. Using text editor, open recover_decoded.txt and locate the position of the delete transaction. In my case, I found mine as below:

#120727 20:35:02 server id 1 end_log_pos 467634 Query thread_id=25395 exec_time=0 error_code=0
SET TIMESTAMP=1343392502/*!*/;
BEGIN
/*!*/;
# at 467634
# at 467711
#120727 22:35:02 server id 1 end_log_pos 467711 Table_map: `webshop`.`tblpayment` mapped to number 75
#120727 22:35:02 server id 1 end_log_pos 467972 Delete_rows: table id 75 flags: STMT_END_F
### DELETE FROM webshop.tblpayment
### WHERE
### @1=15744
### @2=0
### @3=0
### @4=1343392202
# at 467972
#120727 22:35:02 server id 1 end_log_pos 467999 Xid = 12984
COMMIT/*!*/;
# at 467999

In above log, I can translate that, the first row (@1=15744) is the paymentID which has been deleted by my developer. So I just need to find the INSERT query for this paymentID: 15744 and I found it as below:

#120727 21:12:05 server id 1 end_log_pos 458079 Query thread_id=25395 exec_time=0 error_code=0
SET TIMESTAMP=1343392502/*!*/;
BEGIN
/*!*/;
# at 458079
# at 458156
#120727 21:12:05 server id 1 end_log_pos 458156 Table_map: `webshop`.`tblpayment` mapped to number 75
#120727 21:12:05 server id 1 end_log_pos 458417 Write_rows: table id 75 flags: STMT_END_F
### INSERT INTO webshop.tblpayment
### SET
### @1=15744
### @2=0
### @3=0
### @4=1343392202
# at 458417
#120727 21:12:05 server id 1 end_log_pos 458444 Xid = 12985
COMMIT/*!*/;
# at 458444

8. Now I am able to locate where is the INSERT command position in binlog which is started from position 458079 to 458444. Now lets insert back this line into database by running following command:

$ mysqlbinlog --start-position=458079 --stop-position=458444 mysql-bin.000023 | mysql -u root -p

Done! Lets verify whether the missing payment has been inserted back into the database:

mysql > SELECT paymentID FROM webshop.tblpayment WHERE paymentID=15744;
+-----------+
| paymentID |
+-----------+
| 15744     |
+-----------+
1 row in set (0.00 sec)

What I learnt today:

  • Do backup no matter what kind of environment your application run (development, testing or production).
  • Enable binary logging. It surely increase your chance to recover the database!

Leave a comment

Leave a Reply

Your email address will not be published. Required fields are marked *