Oops! - That SQL Query was not intended... Flashback

It is Saturday night at 23:19. Time to go to bed after a hard migration day. Just a last clean-up query before finishing: Tap tap tap. Enter! - Oops!

SQL> UPDATE prospect_lists_prospects SET prospect_list_id = '73ae6cca-7b34-c4a3-5500-5d0e2674dbb6';
Query OK, 4686 rows affected (0.21 sec)
Rows matched: 5666  Changed: 4686  Warnings: 0

A verification query to make sure I am in the mess:

SQL> SELECT prospect_list_id, COUNT(*) FROM prospect_lists_prospects GROUP BY prospect_list_id;
+--------------------------------------+----------+
| prospect_list_id                     | count(*) |
+--------------------------------------+----------+
| 73ae6cca-7b34-c4a3-5500-5d0e2674dbb6 |     5666 |
+--------------------------------------+----------+

And certainly I did not enter the START TRANSACTION; command before. So no ROLLBACK!

Next look at the backup:

# ll backup/daily/bck_schema_crm_2019-06*
-rw-rw-r-- 1 mysql mysql  7900060 Jun  1 02:13 backup/daily/bck_schema_crm_2019-06-01_02-13-01.sql.gz
-rw-rw-r-- 1 mysql mysql  7900061 Jun  2 02:13 backup/daily/bck_schema_crm_2019-06-02_02-13-01.sql.gz
-rw-rw-r-- 1 mysql mysql  7900091 Jun  3 02:13 backup/daily/bck_schema_crm_2019-06-03_02-13-01.sql.gz
-rw-rw-r-- 1 mysql mysql  7903126 Jun  4 02:13 backup/daily/bck_schema_crm_2019-06-04_02-13-01.sql.gz
-rw-rw-r-- 1 mysql mysql  7903192 Jun  5 02:13 backup/daily/bck_schema_crm_2019-06-05_02-13-02.sql.gz
-rw-rw-r-- 1 mysql mysql  7903128 Jun  6 02:13 backup/daily/bck_schema_crm_2019-06-06_02-13-01.sql.gz
-rw-rw-r-- 1 mysql mysql  7912886 Jun 21 02:13 backup/daily/bck_schema_crm_2019-06-21_02-13-01.sql.gz
-rw-rw-r-- 1 mysql mysql  7920566 Jun 22 02:13 backup/daily/bck_schema_crm_2019-06-22_02-13-01.sql.gz

Yes! Backup is there and was done with the FromDual Backup Manager. So I am confident Restore and Point-in-Time-Recovery will work... But the Point-in-Time-Recovery with the Binary Logs for just one schema is a bit tricky and officially not so really supported.

So basically what I want to do is just to undo this UPDATE command. But unfortunately this UPDATE was not a reversible UPDATE command. Then I remembered a presentation about MariaDB 10.2 New Features (p. 41) where the speaker was talking about the flashback functionality in the mysqlbinlog utility.

Undo MySQL Binary Log Events with MariaDB mysqlbinlog utility

First of all I analysed the MySQL Binary Log to find the Binary Log Events to undo:

# mysqlbinlog --start-position=348622898 --verbose mysql-bin.000080 | less
# at 348622898
#190622 23:19:43 server id 7  end_log_pos 348622969 CRC32 0xd358d264    Query   thread_id=791264        exec_time=0     error_code=0
SET TIMESTAMP=1561238383/*!*/;
BEGIN
/*!*/;
# at 348622969
#190622 23:19:43 server id 7  end_log_pos 348623049 CRC32 0x71340183    Table_map: `crm`.`prospect_lists_prospects` mapped to number 2857
# at 348623049
#190622 23:19:43 server id 7  end_log_pos 348631021 CRC32 0x53d65c9b    Update_rows: table id 2857
...
### UPDATE `crm`.`prospect_lists_prospects`
### WHERE
###   @1='ff700497-41cc-e530-a690-5d0e606cd942'
###   @2='b851169d-5e94-5c43-3593-5d0e2825d848'
###   @3='2078d1ae-f7b4-a082-38a5-5d0e581584fc'
###   @4='Prospects'
###   @5='2019-06-22 17:07:41'
###   @6=0
### SET
###   @1='ff700497-41cc-e530-a690-5d0e606cd942'
###   @2='73ae6cca-7b34-c4a3-5500-5d0e2674dbb6'
###   @3='2078d1ae-f7b4-a082-38a5-5d0e581584fc'
###   @4='Prospects'
###   @5='2019-06-22 17:07:41'
###   @6=0
# at 349828089
#190622 23:19:43 server id 7  end_log_pos 349828120 CRC32 0x83f41493    Xid = 8361402
COMMIT/*!*/;

So the relevant part in the MySQL Binary Log is between position 348622898 and 349828120.

Now let us try the reverse operation. But for this we have to solve a little problem. The database is a MySQL 5.7. But the feature --flashback is only available in MariaDB 10.2 and newer. So we have to bring either the MySQL 5.7 Binary Logs to the MariaDB mysqlbinlog utility or the MariaDB mysqlbinlog utility to the MySQL 5.7 Binary Logs.

For a first attempt I moved the MySQL 5.7 Binary Logs to a MariaDB 10.3 testing system and gave it a try if mixing Binary Logs and Utility is working at all:

# mysqlbinlog --start-position=348622898 --stop-position=349828120 -v mysql-bin.000080 | grep -c 'UPDATE `crm`.`prospect_lists_prospects`'
4686

Looks good! Exactly the number of Row changes expected. Then let us look at the statement with --flashback:

# mysqlbinlog --flashback --start-position=348622898 --stop-position=349828120 mysql-bin.000080 -v | less
'/*!*/;
### UPDATE `crm`.`prospect_lists_prospects`
### WHERE
###   @1='ff700497-41cc-e530-a690-5d0e606cd942'
###   @2='73ae6cca-7b34-c4a3-5500-5d0e2674dbb6'
###   @3='2078d1ae-f7b4-a082-38a5-5d0e581584fc'
###   @4='Prospects'
###   @5='2019-06-22 17:07:41'
###   @6=0
### SET
###   @1='ff700497-41cc-e530-a690-5d0e606cd942'
###   @2='b851169d-5e94-5c43-3593-5d0e2825d848'
###   @3='2078d1ae-f7b4-a082-38a5-5d0e581584fc'
###   @4='Prospects'
###   @5='2019-06-22 17:07:41'
###   @6=0

Looks good! Seems to be the reverse query. And now let us do the final repair job:

# /home/mysql/product/mariadb-10.3/mysqlbinlog --flashback --start-position=348622898 --stop-position=349828120 mysql-bin.000080 \
| /home/mysql/product/mysql-5.7/bin/mysql --user=root --port=3320 --host=127.0.0.1 crm --force
ERROR 1193 (HY000) at line 21339: Unknown system variable 'check_constraint_checks'

The --force option was used to motivate mysql utility to continue even if an error occurs. Which was the case in our scenario. This option should usually not be used. We had tried out this step before on a testing system so I was aware what is happening and why this error occurs...

Now the final test on the repaired system shows the situation as it was before the accident:

SQL> SELECT IFNULL(prospect_list_id, 'Total:'), COUNT(*)
  FROM prospect_lists_prospects GROUP BY prospect_list_id
  WITH ROLLUP;
+--------------------------------------+----------+
| IFNULL(prospect_list_id, 'Total:')   | count(*) |
+--------------------------------------+----------+
| 1178ec2b-6aa9-43e4-a27e-5d0e264cac4c |       91 |
| 1bd03c4e-b3f3-b3eb-f237-5d0e26413ae9 |      946 |
| 1c0901f1-41b2-cf42-074d-5d0cdc12b47d |        5 |
| 21d9a74f-73af-9a5d-84ba-5d0e280772ef |      107 |
| 37230208-a431-f6d8-a428-5d0e28d9ec77 |      264 |
| 4b48da8a-33d9-4896-5000-5d0e287ffe39 |        3 |
| 5d06f6cc-3fe9-f501-b680-5d0ccfd19033 |        2 |
| 5e39a569-3213-cc64-496f-5d0e28e851c9 |        5 |
| 680a879c-ff3c-b955-c3b8-5d0e28c833c5 |      315 |
| 73ae6cca-7b34-c4a3-5500-5d0e2674dbb6 |      980 |
| 756c4803-dc73-dc09-b301-5d0e28e69546 |        2 |
| 8eb0ec25-6bbb-68de-d44f-5d0e262cd93d |      833 |
| 913861f0-a865-7c94-8109-5d0e28d714b6 |       12 |
| 96a10d6a-c10e-c945-eaeb-5d0e280aa16c |       74 |
| a43147a8-90f2-a5b3-5bcf-5d0e2862248a |       15 |
| ae869fb1-dd88-19c0-b0d6-538f7b7e329a |       20 |
| b57eb9ba-5a93-8570-5914-5d0e28d975a9 |       25 |
| b851169d-5e94-5c43-3593-5d0e2825d848 |      978 |
| be320e31-1a5b-fe86-09d7-5d0e28a0fd2e |        7 |
| c762abde-bc63-2383-ba30-5d0e28a714c9 |      160 |
| cbbd0ba7-dc25-f29f-36f4-5d0e287c3006 |       99 |
| d23490c8-99eb-f298-6aad-5d0e28e7fd4f |       52 |
| d5000593-836c-3679-ecb5-5d0e28dd076c |       57 |
| d81e9aae-ef60-fca2-7d99-5d0e269de1c0 |      421 |
| df768570-f9b8-2333-66c4-5a6768e34ed3 |        3 |
| e155d58a-19e8-5163-f846-5d0e282ba4b8 |       66 |
| f139b6a0-9598-0cd4-a204-5d0e28c2eccd |      120 |
| f165c48b-4fc1-b081-eee3-5d0cdd7947d5 |        4 |
| Total:                               |     5666 |
+--------------------------------------+----------+

Flashback of MySQL 5.7 Binary Logs with MariaDB 10.3 mysqlbinlog utility was successful!

If you want to learn more about Backup and Recovery strategies contact our MariaDB/MySQL consulting team or book one of our MariaDB/MySQL training classes.