A Little Noise

6Nov/1413

Undelete rows with the binary log

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.

Filed under: MySQL Leave a comment
Comments (13) Trackbacks (0)
  1. I think this is a good reason why binlog_row_image=full is a good default.

  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.

  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.

  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?

  5. Joseph,

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

  6. (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=

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

  8. 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
    /*!*/;

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

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

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

  12. 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 |
    +———-+


Leave a comment

No trackbacks yet.