A Little Noise

November 6, 2014

Undelete rows with the binary log

Filed under: MySQL — snoyes @ 3:18 pm

Can you use the binary logs to undo a DELETE? Maybe, if you’re using ROW format logging. The difference between a delete and an insert event could be just one byte – the one that maps it as a DELETE_ROWS_EVENT or a WRITE_ROWS_EVENT. Let’s try it.

I’ve already populated this table with a few rows:

CREATE TABLE `undo_test` (
`id` int(10) unsigned NOT NULL AUTO_INCREMENT,
`t` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
`v` varchar(20) DEFAULT NULL,
`b` blob,
PRIMARY KEY (`id`)
) ENGINE=InnoDB;

Save a hash so we can see if the undo really works later:

mysql -e "SELECT * FROM test.undo_test" | md5sum > before.md5

Delete an unwanted row:

DELETE FROM undo_test;
Query OK, 1693 rows affected (0.14 sec)

Oops! Forgot the WHERE clause! And of course I don’t have any recent backups. Is the data really gone?

mysql> select count(*) from undo_test;
+----------+
| count(*) |
+----------+
| 0 |
+----------+

But maybe there’s hope. Find the delete event in the binary log.

mysql> SHOW BINLOG EVENTS;
+------------+--------+-------------+-----------+-------------+-----
| Log_name   | Pos    | Event_type  | Server_id | End_log_pos | Info
+------------+--------+-------------+-----------+-------------+-----
| bin.000001 |      4 | Format_desc |         1 |         120 | Server ver: 5.6.20-log, Binlog ver: 4
<snip>
| bin.000001 |    516 | Query       |         1 |         588 | BEGIN
| bin.000001 |    588 | Table_map   |         1 |         647 | table_id: 70 (test.undo_test)
| bin.000001 |    647 | Delete_rows |         1 |        8859 | table_id: 70
| bin.000001 |   8859 | Delete_rows |         1 |       16932 | table_id: 70
| bin.000001 |  16932 | Delete_rows |         1 |       25040 | table_id: 70
| bin.000001 |  25040 | Delete_rows |         1 |       33244 | table_id: 70
| bin.000001 |  33244 | Delete_rows |         1 |       41408 | table_id: 70
| bin.000001 |  41408 | Delete_rows |         1 |       49549 | table_id: 70
| bin.000001 |  49549 | Delete_rows |         1 |       57764 | table_id: 70
| bin.000001 |  57764 | Delete_rows |         1 |       65956 | table_id: 70
| bin.000001 |  65956 | Delete_rows |         1 |       74096 | table_id: 70
| bin.000001 |  74096 | Delete_rows |         1 |       82237 | table_id: 70
| bin.000001 |  82237 | Delete_rows |         1 |       90445 | table_id: 70
| bin.000001 |  90445 | Delete_rows |         1 |       98586 | table_id: 70
| bin.000001 |  98586 | Delete_rows |         1 |      106728 | table_id: 70
| bin.000001 | 106728 | Delete_rows |         1 |      114886 | table_id: 70
| bin.000001 | 114886 | Delete_rows |         1 |      123085 | table_id: 70
| bin.000001 | 123085 | Delete_rows |         1 |      131290 | table_id: 70
| bin.000001 | 131290 | Delete_rows |         1 |      139476 | table_id: 70
| bin.000001 | 139476 | Delete_rows |         1 |      146945 | table_id: 70 flags: STMT_END_F
| bin.000001 | 146945 | Xid         |         1 |      146976 | COMMIT /* xid=36 */

The delete starts at position 516 and ends at 146976. We can pass those positions to mysqlbinlog to get just this delete event, along with the necessary header so mysql knows how to interpret the event.

From sql/log_event.h we see that a delete is 0x20 and an insert is 0x1E. This awk program will parse the mysqlbinlog output and make the necessary changes.

undelete.awk:

# In a ROW event, the first 9 bytes are timestamp (4 bytes), event type (1 byte), server id (4 bytes).
# In base64 encoding, 6 bits map to a single character.
# So the first 30 bits of the timestamp are the first 5 characters
# The last 2 bits of the timestamp and the first nibble of event type are character 6
# The last nibble of event type plus first 2 bits of server id are character 7
# The last 30 bits of server id are characters 8-12.

# A DELETE event will match the timestamp and sever id of the table map event (first line after BINLOG ') (I hope)
# Characters 6 and 7 have only four possible values each:
# Char6 is (00, 01, 10, or 11) followed by 0010. These map to CSiy
# Char7 is 0000 followed by (00, 01, 10, or 11). These map to ABCD

# To change DELETE to INSERT:
# - change the last 4 bits of character 6 to 0001. These map to BRhx.
# - change the first 4 bits of character 7 to 1110. These map to 4567.

BEGIN { regexp = "$^" }

/^BINLOG/ {
  print;
  getline;
  regexp = "^" substr($0, 1, 5) "[CSiy][ABCD]" substr($0, 8, 4);
}

$0 ~ regexp {
  n = $0;
  $0 = substr(n, 1, 5)
  $0 = $0 substr("BRhx", index("CSiy", substr(n, 6, 1)), 1)
  $0 = $0 substr("4567", index("ABCD", substr(n, 7, 1)), 1)
  $0 = $0 substr(n, 8) ;
}

{ print; }

Pass the event through that code, and then back into mysql:

mysqlbinlog --start-position=516 --stop-position=146976 bin.000001 | awk -f undelete.awk | mysql

Compare it to the original hash to see if it’s really back:

mysql -e "SELECT * FROM test.undo_test" | md5sum -c before.md5
-: OK

Looks like it worked.

15 Comments »

  1. I think this is a good reason why binlog_row_image=full is a good default.

    Comment by Daniël van Eeden — November 8, 2014 @ 5:33 am

  2. Hi, i tried this method but i failed to find these delete query begin and end positions in “show binlog events”. I have enabled log_bin in mycnf and restarted the server. But still the same. Please check this out below :-

    mysql> select count(*) from test;
    +———-+
    | count(*) |
    +———-+
    | 41 |
    +———-+

    mysql> delete from test;
    Query OK, 41 rows affected (0.14 sec)

    mysql> select count(*) from test;
    +———-+
    | count(*) |
    +———-+
    | 0 |
    +———-+
    1 row in set (0.00 sec)

    mysql> SHOW BINLOG EVENTS;
    +——————+—–+————-+———–+————-+——————————————————————–+
    | Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
    +——————+—–+————-+———–+————-+——————————————————————–+
    | mysql-bin.000001 | 4 | Format_desc | 1 | 107 | Server ver: 5.5.35-0ubuntu0.12.04.2-log, Binlog ver: 4 |
    | mysql-bin.000001 | 107 | Query | 1 | 248 | flush privileges |
    | mysql-bin.000001 | 248 | Query | 1 | 323 | flush privileges |
    | mysql-bin.000001 | 323 | Rotate | 1 | 366 | mysql-bin.000002;pos=4 |
    +——————+—–+————-+———–+————-+——————————————————————–+
    4 rows in set (0.00 sec)

    Please suggest.

    Comment by Jethan — November 10, 2014 @ 11:39 pm

  3. Jethan,

    It’s in a higher log file. If you do not specify ‘log_name’, the first binary log is displayed.
    http://dev.mysql.com/doc/refman/5.6/en/show-binlog-events.html

    You might find it easier to use mysqlbinlog and grep to find the positions around your event.

    Comment by snoyes — November 11, 2014 @ 8:21 am

  4. Could it be possible if someone else is connected to the MySQL server, that an operation could be in the middle of the range you wanted to undo?

    Comment by joseph — November 11, 2014 @ 11:35 pm

  5. Joseph,

    No. Statements or transactions are logged in one fell swoop in commit order. Interleaving of statements is not possible.

    Comment by snoyes — November 12, 2014 @ 8:21 am

  6. Nice, agree with DaniEl.

    Comment by Wagner Bianchi — November 12, 2014 @ 8:59 am

  7. (Sorry, delete that previous post.)

    This is my base64 encoded version, how do I know where the DELETE event type is? I’m not clear how this is determined.

    4TlhVA8BAAAAdAAAAHgAAAABAAQANS42LjExLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
    AAAAAAAAAAAAAAAAAADhOWFUEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAcax
    Dwk=

    Comment by Ian Trill — November 12, 2014 @ 4:34 pm

  8. Ian, that’s the binlog header, which really just tells us what version of MySQL and binlog format you are using. Your delete event appears later. mysqlbinlog output would show lines like:

    #{some timestamp here} server id 1 end_log_pos {some numbers here} Table_map: `dbname here`.`tablename here` mapped to number {some number}

    #{some timestamp here} server id 1 end_log_pos {some numbers here} Delete_rows: table id {some number}

    Then after that is a base64 encoded section. That’s your delete event.

    Comment by snoyes — November 12, 2014 @ 5:21 pm

  9. Thanks for explanation snoyes, I just realised my default MySQL server on Mac OSX is running with a binlog_format=STATEMENT. I’ll try again with ROW format. Curious to know what the best practice is for STATEMENT.

    # at 997
    #141110 22:21:30 server id 1 end_log_pos 1092 CRC32 0x633073db Query thread_id=1 exec_time=0 error_code=0
    use `test`/*!*/;
    SET TIMESTAMP=1415658090/*!*/;
    DELETE FROM undo_test
    /*!*/;

    Comment by Ian Trill — November 17, 2014 @ 3:37 pm

  10. Ian: 1) Don’t. 2) Have backups.

    Comment by snoyes — November 17, 2014 @ 5:04 pm

  11. 1) Thought so. 2) Goes without saying. Any idea what this error this:

    awk: syntax error at source line 14 source file /Users/Documents/undelete.awk
    context is
    print hexString >>> |& <<< base64cmd
    awk: illegal statement at source line 15 source file /Users/Documents/undelete.awk
    awk: illegal statement at source line 15 source file /Users/Documents/undelete.awk

    Comment by Ian Trill — November 17, 2014 @ 6:09 pm

  12. Probably the difference between gawk and awk. If you have gawk or nawk, try those instead.

    Comment by snoyes — November 17, 2014 @ 6:33 pm

  13. I am trying the same but recovery of data is not happening
    mysqlbinlog –start-position=163924 –stop-position=164129 mysql-bin-mysqltestdb001iad.000069 | awk -f undelete.awk | mysql

    mysql> select count(*) from rand_numbers;
    +———-+
    | count(*) |
    +———-+
    | 0 |
    +———-+

    Comment by Amit Agarwal — August 25, 2016 @ 2:20 pm

  14. This does work. But good luck using it on a server with an average rate of 10-30 transactions per second. SHOW BINLOG EVENTS takes up to 30 minutes to show anything and can return a billion rows…unless you’re lucky and the binlog just rolled over to a new file recently.

    Comment by Steffen Scheibler — March 5, 2019 @ 3:33 am

  15. Steffen: So use mysqlbinlog and grep.

    Comment by snoyes — December 13, 2019 @ 11:29 am

RSS feed for comments on this post. TrackBack URL

Leave a comment

Powered by WordPress