{"id":919,"date":"2018-07-20T11:07:23","date_gmt":"2018-07-20T10:07:23","guid":{"rendered":"http:\/\/it.tuxie.eu\/?p=919"},"modified":"2018-07-20T11:16:35","modified_gmt":"2018-07-20T10:16:35","slug":"flashback-mariadb-10-3-8","status":"publish","type":"post","link":"http:\/\/it.tuxie.eu\/?p=919","title":{"rendered":"Flashback @MariaDB 10.3.8"},"content":{"rendered":"<p>Neverending story. Commited changes need to be rollback. Some vendors are not resolving this situation at all (stupidity of user is not their problem, indeed), some are providing solutions (Oracle). One of the latest news from MariaDB (10.2) was adding this feature into mysqlbinlog utility.<\/p>\n<p><!--more--><\/p>\n<p>Let&#8217;s create data with faulty DELETE command inside \ud83d\ude42 :<\/p>\n<p>[crayon lang=&#8220;shell&#8220;]<\/p>\n<p>MariaDB [test]> create table t1(id int);<br \/>\nQuery OK, 0 rows affected (0.008 sec)<\/p>\n<p>MariaDB [test]> insert into t1 values(1),(2),(3),(4),(5);<br \/>\nQuery OK, 5 rows affected (0.003 sec)<br \/>\nRecords: 5 Duplicates: 0 Warnings: 0<\/p>\n<p>MariaDB [test]> insert into t1 values(6);<br \/>\nQuery OK, 1 row affected (0.004 sec)<\/p>\n<p>MariaDB [test]> insert into t1 values(7);<br \/>\nQuery OK, 1 row affected (0.001 sec)<\/p>\n<p>MariaDB [test]> delete from test.t1;<br \/>\nQuery OK, 7 rows affected (0.002 sec)<\/p>\n<p>MariaDB [test]> create table t2(id int); insert into t2 values(10),(11),(12);<br \/>\nQuery OK, 0 rows affected (0.034 sec)<\/p>\n<p>Query OK, 3 rows affected (0.001 sec)<br \/>\nRecords: 3 Duplicates: 0 Warnings: 0<\/p>\n<p>MariaDB [test]> exit<\/p>\n<p>[\/crayon]<\/p>\n<p>Situation is pretty clear &#8211; in table t1 there are 1-7 numbers, inserted in 3 transactions (AUTOCOMMIT is on) and after accidentaly deleting this table (beware for TRUNCATE TABLE, it is not written into binary log at all!) I created table t2 with just 3 values.<\/p>\n<p><strong>1) Locating where is our DELETE command residing.<\/strong><\/p>\n<p>As long as we are storing binary (transactional) logs,we\u00a0 are able to flashback any transaction. Going through hundreds of gigabytes is a bit boring -> it is good to know when this transaction happened (~hours precision). After extracting binary log into human-readable format we will grep DELETE command. Enough of theory:<\/p>\n<p>[crayon lang=&#8220;shell&#8220;]<\/p>\n<p>mysqlbinlog -v &#8211;base64-output=DECODE-ROWS localhost-bin.000002 > mysql-bin.000002.sql<\/p>\n<p>[\/crayon]<\/p>\n<p>On fresh MariDB installation it&#8217;s not a big deal to detect proper binary log file (in case you are having tons of these files, just extract suspicious ones). Target file looks like this:<\/p>\n<p>[crayon lang=&#8220;shell&#8220;]<\/p>\n<p>[root@localhost mysql]# tail -15 mysql-bin.000002.sql<br \/>\n### INSERT INTO `test`.`t2`<br \/>\n### SET<br \/>\n### @1=11<br \/>\n### INSERT INTO `test`.`t2`<br \/>\n### SET<br \/>\n### @1=12<br \/>\n# Number of rows: 3<br \/>\n# at 1723<br \/>\n#180720 10:11:44 server id 1 end_log_pos 1754 CRC32 0x9238cb53 Xid = 26<br \/>\nCOMMIT\/*!*\/;<br \/>\nDELIMITER ;<br \/>\n# End of log file<br \/>\nROLLBACK \/* added by mysqlbinlog *\/;<br \/>\n\/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*\/;<br \/>\n\/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*\/;<\/p>\n<p>[\/crayon]<\/p>\n<p>We can grab string &#8222;DELETE&#8220; or just annotated &#8222;Delete_rows&#8220; into grep command to find out what range of lines will be in our interest:<\/p>\n<p>[crayon lang=&#8220;shell&#8220;]<\/p>\n<p>[root@localhost mysql]# grep -nr -B 10 -A 30 Delete_rows mysql-bin.000002.sql<br \/>\n104-#180720 10:06:09 server id 1 end_log_pos 1212 CRC32 0x75c44f0c GTID 0-1-7 trans<br \/>\n105-\/*!100001 SET @@session.gtid_seq_no=7*\/\/*!*\/;<br \/>\n106-BEGIN<br \/>\n107-\/*!*\/;<br \/>\n108-# at 1212<br \/>\n109-# at 1254<br \/>\n110-#180720 10:06:09 server id 1 end_log_pos 1254 CRC32 0xff132128 Annotate_rows:<br \/>\n111-#Q> delete from test.t1<br \/>\n112-#180720 10:06:09 server id 1 end_log_pos 1299 CRC32 0x64d46f5b Table_map: `test`.`t1` mapped to number 22<br \/>\n113-# at 1299<br \/>\n114:#180720 10:06:09 server id 1 end_log_pos 1367 CRC32 0x146f66d7 Delete_rows: table id 22 flags: STMT_END_F<br \/>\n115-### DELETE FROM `test`.`t1`<br \/>\n116-### WHERE<br \/>\n117-### @1=1<br \/>\n118-### DELETE FROM `test`.`t1`<br \/>\n119-### WHERE<br \/>\n120-### @1=2<br \/>\n121-### DELETE FROM `test`.`t1`<br \/>\n122-### WHERE<br \/>\n123-### @1=3<br \/>\n124-### DELETE FROM `test`.`t1`<br \/>\n125-### WHERE<br \/>\n126-### @1=4<br \/>\n127-### DELETE FROM `test`.`t1`<br \/>\n128-### WHERE<br \/>\n129-### @1=5<br \/>\n130-### DELETE FROM `test`.`t1`<br \/>\n131-### WHERE<br \/>\n132-### @1=6<br \/>\n133-### DELETE FROM `test`.`t1`<br \/>\n134-### WHERE<br \/>\n135-### @1=7<br \/>\n136-# Number of rows: 7<br \/>\n137-# at 1367<br \/>\n138-#180720 10:06:09 server id 1 end_log_pos 1398 CRC32 0x71e5e02f Xid = 24<br \/>\n139-COMMIT\/*!*\/;<br \/>\n140-# at 1398<br \/>\n141-#180720 10:11:44 server id 1 end_log_pos 1440 CRC32 0xe8d0e1f9 GTID 0-1-8 ddl<br \/>\n142-\/*!100001 SET @@session.gtid_seq_no=8*\/\/*!*\/;<br \/>\n143-# at 1440<br \/>\n144-#180720 10:11:44 server id 1 end_log_pos 1530 CRC32 0x7b772d2a Query thread_id=10 exec_time=0 error_code=0<\/p>\n<p>[\/crayon]<\/p>\n<p>Bingo! In case of huge line numbers, grep it better and extract into standalone file. Please have in mind that transaction begins right after BEGIN word and ending right before COMMIT word. In our case 1212 and 1398. Extracted paragraph is performed by:<\/p>\n<p>&nbsp;<\/p>\n<p><strong>2) Preparing flashback binlog fragment<\/strong><\/p>\n<p>Looks great, we can prepare again those lines, this time with clause &#8211;flashback, opposite operation will be generated:<\/p>\n<p>[crayon lang=&#8220;shell&#8220;]<\/p>\n<p>mysqlbinlog &#8211;flashback -v &#8211;base64-output=DECODE-ROWS &#8211;start-position=1212 &#8211;stop-position=1398 localhost-bin.000002 > localhost-bin.000002_flash.sql<\/p>\n<p>[\/crayon]<\/p>\n<p>There is no surprise how resulted file will be looking:<\/p>\n<p>[crayon lang=&#8220;shell&#8220;]<\/p>\n<p>[root@localhost mysql]# cat localhost-bin.000002_flash.sql<br \/>\n\/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*\/;<br \/>\n\/*!40019 SET @@session.max_insert_delayed_threads=0*\/;<br \/>\n\/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*\/;<br \/>\nDELIMITER \/*!*\/;<br \/>\n#180720 10:06:09 server id 1 end_log_pos 1254 CRC32 0xff132128 Annotate_rows:<br \/>\n#Q> delete from test.t1<br \/>\n#180720 10:06:09 server id 1 end_log_pos 1299 CRC32 0x64d46f5b Table_map: `test`.`t1` mapped to number 22<br \/>\n# Number of rows: 7<br \/>\n#180720 10:06:09 server id 1 end_log_pos 1398 CRC32 0x71e5e02f Xid = 24<br \/>\nBEGIN\/*!*\/;<br \/>\n#180720 10:06:09 server id 1 end_log_pos 1367 CRC32 0x146f66d7 Write_rows: table id 22 flags: STMT_END_F<br \/>\n### INSERT INTO `test`.`t1`<br \/>\n### SET<br \/>\n### @1=7<br \/>\n### INSERT INTO `test`.`t1`<br \/>\n### SET<br \/>\n### @1=6<br \/>\n### INSERT INTO `test`.`t1`<br \/>\n### SET<br \/>\n### @1=5<br \/>\n### INSERT INTO `test`.`t1`<br \/>\n### SET<br \/>\n### @1=4<br \/>\n### INSERT INTO `test`.`t1`<br \/>\n### SET<br \/>\n### @1=3<br \/>\n### INSERT INTO `test`.`t1`<br \/>\n### SET<br \/>\n### @1=2<br \/>\n### INSERT INTO `test`.`t1`<br \/>\n### SET<br \/>\n### @1=1<br \/>\nCOMMIT<br \/>\n\/*!*\/;<br \/>\nDELIMITER ;<br \/>\n# End of log file<br \/>\nROLLBACK \/* added by mysqlbinlog *\/;<br \/>\n\/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*\/;<br \/>\n\/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*\/;<\/p>\n<p>[\/crayon]<\/p>\n<p>See those changes? It reverted original operation (DELETE) and you are having few INSERT INTO lines there. We need to convert this fragment into binary log format again:<\/p>\n<p>[crayon lang=&#8220;shell&#8220;]<\/p>\n<p>[root@localhost mysql]# mysqlbinlog &#8211;flashback &#8211;start-position=1212 &#8211;stop-position=1398 localhost-bin.000002 > localhost-bin.000002_flash.bin<br \/>\n[root@localhost mysql]#<\/p>\n<p>[\/crayon]<\/p>\n<p>&nbsp;<\/p>\n<p><strong>3) Propagating changes into database + verification<\/strong><\/p>\n<p>From mariadb client we will process this &#8222;flash&#8220;:<\/p>\n<p>[crayon lang=&#8220;shell&#8220;]<\/p>\n<p>MariaDB [(none)]> source localhost-bin.000002_flash.bin<br \/>\nQuery OK, 0 rows affected (0.000 sec)<\/p>\n<p>Query OK, 0 rows affected (0.000 sec)<\/p>\n<p>Query OK, 0 rows affected (0.000 sec)<\/p>\n<p>Query OK, 0 rows affected (0.000 sec)<\/p>\n<p>Query OK, 0 rows affected (0.000 sec)<\/p>\n<p>Query OK, 0 rows affected (0.000 sec)<\/p>\n<p>Query OK, 0 rows affected (0.004 sec)<\/p>\n<p>Query OK, 0 rows affected (0.000 sec)<\/p>\n<p>Query OK, 0 rows affected (0.000 sec)<\/p>\n<p>Query OK, 0 rows affected (0.000 sec)<\/p>\n<p>[\/crayon]<\/p>\n<p>And verification is really easy:<\/p>\n<p>[crayon lang=&#8220;shell&#8220;]<\/p>\n<p>MariaDB [(none)]> select * from test.t1; select * from test.t2;<br \/>\n+&#8212;&#8212;+<br \/>\n| id |<br \/>\n+&#8212;&#8212;+<br \/>\n| 7 |<br \/>\n| 6 |<br \/>\n| 5 |<br \/>\n| 4 |<br \/>\n| 3 |<br \/>\n| 2 |<br \/>\n| 1 |<br \/>\n+&#8212;&#8212;+<br \/>\n7 rows in set (0.000 sec)<\/p>\n<p>+&#8212;&#8212;+<br \/>\n| id |<br \/>\n+&#8212;&#8212;+<br \/>\n| 10 |<br \/>\n| 11 |<br \/>\n| 12 |<br \/>\n+&#8212;&#8212;+<br \/>\n3 rows in set (0.000 sec)<\/p>\n<p>[\/crayon]<\/p>\n<p>Flashback operation performed as expected. Newly created table t2 is intacted and &#8222;bad&#8220; DELETE operation was successfully replaced by original values (INSERT INTO).<\/p>\n<p>-a-<\/p>\n","protected":false},"excerpt":{"rendered":"<p>Neverending story. Commited changes need to be rollback. Some vendors are not resolving this situation at all (stupidity of user is not their problem, indeed), some are providing solutions (Oracle). One of the latest news from MariaDB (10.2) was adding &hellip; <a href=\"http:\/\/it.tuxie.eu\/?p=919\">Continue reading <span class=\"meta-nav\">&rarr;<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"closed","ping_status":"open","sticky":false,"template":"","format":"standard","meta":[],"categories":[13],"tags":[],"_links":{"self":[{"href":"http:\/\/it.tuxie.eu\/index.php?rest_route=\/wp\/v2\/posts\/919"}],"collection":[{"href":"http:\/\/it.tuxie.eu\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/it.tuxie.eu\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/it.tuxie.eu\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"http:\/\/it.tuxie.eu\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=919"}],"version-history":[{"count":0,"href":"http:\/\/it.tuxie.eu\/index.php?rest_route=\/wp\/v2\/posts\/919\/revisions"}],"wp:attachment":[{"href":"http:\/\/it.tuxie.eu\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=919"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/it.tuxie.eu\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=919"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/it.tuxie.eu\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=919"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}