EmergencyEMERGENCY? Get 24/7 Help Now!

MySQL Bug 72804 Workaround: “BINLOG statement can no longer be used to apply query events”

 | February 16, 2017 |  Posted In: MySQL

PREVIOUS POST
NEXT POST

MySQL Bug 72804In this blog post, we’ll look at a workaround for MySQL bug 72804.

Recently I worked on a ticket where a customer performed a point-in-time recovery PITR using a large set of binary logs. Normally we handle this by applying the last backup, then re-applying all binary logs created since the last backup. In the middle of the procedure, their new server crashed. We identified the binary log position and tried to restart the PITR from there. However, using the option --start-position, the restore failed with the error “The BINLOG statement of type Table_map was not preceded by a format description BINLOG statement.” This is a known bug and is reported as MySQL Bug #72804: “BINLOG statement can no longer be used to apply Query events.”

I created a small test to demonstrate a workaround that we implemented (and worked).

First, I ran a large import process that created several binary logs. I used a small value in  max_binlog_size and tested using the database “employees” (a standard database used for testing).Then I dropped the database.

To demonstrate the recovery process, I joined all the binary log files into one SQL file and started an import.

I intentionally generated a syntax error in the resulting file with the help of the GENERATE_ERROR.sh script (which just inserts a bogus SQL statement in a random row). The error message clearly showed where the import stopped: line 9020. I then created a file that cropped out the part that had already been imported (lines 1- 9020), and tried to import this new file.

Again, the import failed with exactly the same error as the customer. The reason for this error is that the BINLOG statement – which applies changes from the binary log – expects that the format description event gets run in the same session as the binary log import, but before it. The format description existed initially at the start of the import that failed at line 9020. The later import (from line 9021 on) doesn’t contain this format statement.

Fortunately, this format is the same for the same version! We can simply take it from the beginning the SQL log file (or the original binary file) and put into the file created after the crash without lines 1-9020.

With MySQL versions 5.6 and 5.7, this event is located in the first 11 rows:

The first six rows are meta information, and rows 6-11 are the format event itself. The only thing we need to export into our resulting file is these 11 lines:

After this, the import succeeded!

PREVIOUS POST
NEXT POST
Sveta Smirnova

Sveta joined Percona in 2015. Her main professional interests are problem solving, working with tricky issues, bugs, finding patterns that can solve typical issues quicker and teaching others how to deal with MySQL issues, bugs and gotchas effectively. Before joining Percona Sveta worked as a Support Engineer in the MySQL Bugs Analysis Support Group in MySQL AB-Sun-Oracle. She is the author of the book "MySQL Troubleshooting" and JSON UDF functions for MySQL.

10 Comments

  • Hi Svela, if I understand well, Bug#72804 can happen if you do not restart the import at a transaction boundary. In this case, wouldn’t your import be inconsistent (missing the previous statements in the transaction) ? If this is the case, I think it should be closed as “Not a Bug”.

    For PITR, I prefer to use Binlog Server. I wrote a blog post in the past about this: [1]. The advantage of using Binlog Server is using all power of replication: easy restart, transaction skipping, parallel replication, possibility of using filtering, … I also understand that Facebook built their own Binlog Server exactly for that ([2]).

    [1]: http://jfg-mysql.blogspot.nl/2015/10/binlog-servers-for-backups-and-point-in-time-recovery.html

    [2]: https://www.percona.com/live/plam16/sessions/binlog-server-facebook

    Best regards.

  • I think you’ve misunderstood bug 72804. In the bug report he encodes a QUERY event in base64 and applies after a having already appied a binlog format description event. Which is currently not allowed.

    In your hypothetical example, you were making a mistake by not having sent a format description event before your table_map event. Using –start-position with mysqlbinlog it should still emit a format_description_event before applying the event at the start position

    The issue your customer had, where they were using the –start-position option with mysqlbinlog, that sounds like a bug with the version of mysqlbinlog they were using to me. I don’t know whether this once has been a problem

    Happy to be corrected if I’m mistaken

    • This is true that if you run mysqlbinlog with option –start-position it will print format event.

      Issue with my customer was that they already had SQL file, generated by mysqlbinlog command. And importing this SQL file failed.

      Now they had two options: re-generate SQL file using mysqlbinlog command or make changes manually. They had many huge binlog files (several GB) and this would take a lot of time.

      You can test this with quite small binary log file, generated by 1200 seconds standard SysBench OLTP test run:

      sveta@delly:~/tmp$ ls -lh master.000001
      -rw-rw—- 1 sveta sveta 716M Feb 19 23:36 master.000001

      sveta@delly:~/tmp$ time ~/build/mysql-5.7/bin/mysqlbinlog master.000001 > master.000001.sql

      real 0m46.651s
      user 0m41.256s
      sys 0m5.308s

      sveta@delly:~/tmp$ ls -lh master.000001.sql
      -rw-rw-r– 1 sveta sveta 1.4G Feb 19 23:40 master.000001.sql

      So it takes 46 seconds to generate 1.4G SQL file out of 716M binary log.

      Now lets assume import has broken at some position and next transaction starts at position 190111037. So we need to re-generate SQL file, starting from this position:

      sveta@delly:~/tmp$ time ~/build/mysql-5.7/bin/mysqlbinlog master.000001 –start-position=190111037 > master.000001.sql.4

      real 0m40.570s
      user 0m36.504s
      sys 0m3.924s

      It takes 40 seconds if use mysqlbinlog.

      However if use OS tools whole operation will take much less time:

      sveta@delly:~/tmp$ time tail -n +3410882 master.000001.sql > master.000001.sql.2

      real 0m3.202s
      user 0m0.108s
      sys 0m3.084s

      sveta@delly:~/tmp$ time head -n 11 master.000001.sql > master.000001.sql.3; time cat master.000001.sql.2 >> master.000001.sql.3

      real 0m0.266s
      user 0m0.000s
      sys 0m0.264s

      real 0m2.879s
      user 0m0.012s
      sys 0m2.856s

      Total amount is 3.202+0.266+2.879 = 6.347 seconds which is more than 6 times faster than if use msyqlbinlog.

      For this tiny amount timing, while noticeable, does not matter much, but if you have larger amount of binary logs you may not want to re-generate SQL from binary logs again.

    • > I think you’ve misunderstood bug 72804. In the bug report he encodes a QUERY event in base64 and applies after a having already appied a binlog format description event. Which is currently not allowed.

      No, he is not. He just tries to apply any query event using command line client. This worked fine for years and was very useful when you tried to find out a reason why one or another event, replicated, from master fails on slave. Or if you needed to continue loading broken imports like my customer did.

  • Is it a bit dangerous that use the binlog_rest.sql directly? If there is a transaction just cross the 9020th line, this transaction will fail and rollback when it occur the error in 9020. After that, when we use the second part, the transaction is partial. So it may lead to data lost.

    • Yes, this is dangerous. I skipped this part for brevity, but you have to care yourself about your transactions. There are two techniques to find a row at which you need to split the file: find a row where import failed and either skip forward to the next transaction or skip backward to the start of failed transaction, then crop the file.

      But you should care about partial transactions if use mysqlbinlog wth –start-position option as well.

      Lets consider following case:

      mysql> create table t(f1 int) engine=innodb;
      Query OK, 0 rows affected (0.00 sec)

      mysql> begin;
      Query OK, 0 rows affected (0.00 sec)

      mysql> insert into t values(1);
      Query OK, 1 row affected (0.00 sec)

      mysql> insert into t values(2);
      Query OK, 1 row affected (0.00 sec)

      mysql> insert into t values(3);
      Query OK, 1 row affected (0.00 sec)

      mysql> commit;
      Query OK, 0 rows affected (0.00 sec)

      Now lets flush logs and truncate the table. We will have binary log file master.000001 with transaction which inserts 3 rows and next log file will contain truncate statement.

      mysql> flush logs;
      Query OK, 0 rows affected (0.00 sec)

      mysql> truncate t;
      Query OK, 0 rows affected (0.02 sec)

      If run mysqlbinlog without any option we will have all 3 INSERT statements in the output:

      /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
      /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
      DELIMITER /*!*/;
      # at 4
      #170220 4:04:14 server id 1 end_log_pos 123 CRC32 0x40dc8145 Start: binlog v 4, server v 5.7.17-log created 170220 4:04:14 at startup
      ROLLBACK/*!*/;
      BINLOG ‘
      DrGqWA8BAAAAdwAAAHsAAAAAAAQANS43LjE3LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
      AAAAAAAAAAAAAAAAAAAOsapYEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
      AUWB3EA=
      ‘/*!*/;
      # at 123
      #170220 4:04:14 server id 1 end_log_pos 154 CRC32 0xb42a8615 Previous-GTIDs
      # [empty]
      # at 154
      #170220 4:04:57 server id 1 end_log_pos 219 CRC32 0x792b0944 Anonymous_GTID last_committed=0 sequence_number=1
      SET @@SESSION.GTID_NEXT= ‘ANONYMOUS’/*!*/;
      # at 219
      #170220 4:04:57 server id 1 end_log_pos 329 CRC32 0xebcbbc8c Query thread_id=3 exec_time=0 error_code=0
      use test/*!*/;
      SET TIMESTAMP=1487581497/*!*/;
      SET @@session.pseudo_thread_id=3/*!*/;
      SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
      SET @@session.sql_mode=1436549152/*!*/;
      SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
      /*!\C latin1 *//*!*/;
      SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
      SET @@session.lc_time_names=0/*!*/;
      SET @@session.collation_database=DEFAULT/*!*/;
      create table t(f1 int) engine=innodb
      /*!*/;
      # at 329
      #170220 4:05:23 server id 1 end_log_pos 394 CRC32 0xbfe8f73a Anonymous_GTID last_committed=1 sequence_number=2
      SET @@SESSION.GTID_NEXT= ‘ANONYMOUS’/*!*/;
      # at 394
      #170220 4:05:13 server id 1 end_log_pos 466 CRC32 0x38458ff5 Query thread_id=3 exec_time=0 error_code=0
      SET TIMESTAMP=1487581513/*!*/;
      BEGIN
      /*!*/;
      # at 466
      #170220 4:05:13 server id 1 end_log_pos 510 CRC32 0xd5c3e335 Table_map: test.t mapped to number 221
      # at 510
      #170220 4:05:13 server id 1 end_log_pos 550 CRC32 0xd8dd2cb4 Write_rows: table id 221 flags: STMT_END_F

      BINLOG ‘
      SbGqWBMBAAAALAAAAP4BAAAAAN0AAAAAAAEABHRlc3QAAXQAAQMAATXjw9U=
      SbGqWB4BAAAAKAAAACYCAAAAAN0AAAAAAAEAAgAB//4BAAAAtCzd2A==
      ‘/*!*/;
      ### INSERT INTO test.t
      ### SET
      ### @1=1
      # at 550
      #170220 4:05:15 server id 1 end_log_pos 594 CRC32 0x2370970c Table_map: test.t mapped to number 221
      # at 594
      #170220 4:05:15 server id 1 end_log_pos 634 CRC32 0x3fa551f8 Write_rows: table id 221 flags: STMT_END_F

      BINLOG ‘
      S7GqWBMBAAAALAAAAFICAAAAAN0AAAAAAAEABHRlc3QAAXQAAQMAAQyXcCM=
      S7GqWB4BAAAAKAAAAHoCAAAAAN0AAAAAAAEAAgAB//4CAAAA+FGlPw==
      ‘/*!*/;
      ### INSERT INTO test.t
      ### SET
      ### @1=2
      # at 634
      #170220 4:05:21 server id 1 end_log_pos 678 CRC32 0x97555a06 Table_map: test.t mapped to number 221
      # at 678
      #170220 4:05:21 server id 1 end_log_pos 718 CRC32 0xef3753a3 Write_rows: table id 221 flags: STMT_END_F

      BINLOG ‘
      UbGqWBMBAAAALAAAAKYCAAAAAN0AAAAAAAEABHRlc3QAAXQAAQMAAQZaVZc=
      UbGqWB4BAAAAKAAAAM4CAAAAAN0AAAAAAAEAAgAB//4DAAAAo1M37w==
      ‘/*!*/;
      ### INSERT INTO test.t
      ### SET
      ### @1=3
      # at 718
      #170220 4:05:23 server id 1 end_log_pos 749 CRC32 0x2ade2d48 Xid = 8
      COMMIT/*!*/;
      # at 749
      #170220 4:05:26 server id 1 end_log_pos 793 CRC32 0x3ba055c0 Rotate to master.000002 pos: 4
      SET @@SESSION.GTID_NEXT= ‘AUTOMATIC’ /* added by mysqlbinlog */ /*!*/;
      DELIMITER ;
      # End of log file
      /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
      /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

      But if we start, say, from position 634, we will have partial transaction:

      sveta.smirnova@bm-support01:~/mysql-5.7.17-linux-glibc2.5-x86_64/mysql-test$ ../bin/mysqlbinlog -v –start-position=634 var/mysqld.1/data/master.000001 > test_634.sql
      sveta.smirnova@bm-support01:~/mysql-5.7.17-linux-glibc2.5-x86_64/mysql-test$ cat test_634.sql
      /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
      /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
      DELIMITER /*!*/;
      # at 4
      #170220 4:04:14 server id 1 end_log_pos 123 CRC32 0x40dc8145 Start: binlog v 4, server v 5.7.17-log created 170220 4:04:14 at startup
      ROLLBACK/*!*/;
      BINLOG ‘
      DrGqWA8BAAAAdwAAAHsAAAAAAAQANS43LjE3LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
      AAAAAAAAAAAAAAAAAAAOsapYEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
      AUWB3EA=
      ‘/*!*/;
      # at 634
      #170220 4:05:21 server id 1 end_log_pos 678 CRC32 0x97555a06 Table_map: test.t mapped to number 221
      # at 678
      #170220 4:05:21 server id 1 end_log_pos 718 CRC32 0xef3753a3 Write_rows: table id 221 flags: STMT_END_F

      BINLOG ‘
      UbGqWBMBAAAALAAAAKYCAAAAAN0AAAAAAAEABHRlc3QAAXQAAQMAAQZaVZc=
      UbGqWB4BAAAAKAAAAM4CAAAAAN0AAAAAAAEAAgAB//4DAAAAo1M37w==
      ‘/*!*/;
      ### INSERT INTO test.t
      ### SET
      ### @1=3
      # at 718
      #170220 4:05:23 server id 1 end_log_pos 749 CRC32 0x2ade2d48 Xid = 8
      COMMIT/*!*/;
      # at 749
      #170220 4:05:26 server id 1 end_log_pos 793 CRC32 0x3ba055c0 Rotate to master.000002 pos: 4
      SET @@SESSION.GTID_NEXT= ‘AUTOMATIC’ /* added by mysqlbinlog */ /*!*/;
      DELIMITER ;
      # End of log file
      /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
      /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

      And if we then try to apply this file we receive partial set of rows in our table too:

      sveta.smirnova@bm-support01:~/mysql-5.7.17-linux-glibc2.5-x86_64/mysql-test$ ../bin/mysql -uroot -h127.0.0.1 -P13000 test < test_634.sql sveta.smirnova@bm-support01:~/mysql-5.7.17-linux-glibc2.5-x86_64/mysql-test$ ../bin/mysql -uroot -h127.0.0.1 -P13000 test Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 5 Server version: 5.7.17-log MySQL Community Server (GPL) Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> select * from t;
      +——+
      | f1 |
      +——+
      | 3 |
      +——+
      1 row in set (0.00 sec)

      So no matter which method you use to apply partial updates you have to care about data consistency yourself.

Leave a Reply