Mysqlbinlog parsing binlog garbled issue decryption

Mysqlbinlog parsing binlog garbled issue decryption

The binlog of mysql database is garbled as follows:
Binlog'
Ixzqvhniaaaalqaaagcbaaaaahoaaaaaeabhrlc3qaano0aaedaabuocny
Ixzqvh5iaaaakaaaai8baaaaahoaaaaaeaagab // 4 BAAAAcu + UpA =. If you use-v to forcibly Execute SQL statements, this problem is very difficult. The core issue is discovered only after in-depth research today.

1. binlog log troubles. Check the log format first.

mysql> show variables like '%binlog%';+-----------------------------------------+----------------------+| Variable_name                           | Value                |+-----------------------------------------+----------------------+| binlog_cache_size                       | 1048576              || binlog_checksum                         | CRC32                || binlog_direct_non_transactional_updates | OFF                  || binlog_format                           | MIXED                || binlog_max_flush_queue_time             | 0                    || binlog_order_commits                    | ON                   || binlog_row_image                        | FULL                 || binlog_rows_query_log_events            | OFF                  || binlog_stmt_cache_size                  | 32768                || innodb_api_enable_binlog                | OFF                  || innodb_locks_unsafe_for_binlog          | OFF                  || max_binlog_cache_size                   | 18446744073709547520 || max_binlog_size                         | 1073741824           || max_binlog_stmt_cache_size              | 18446744073709547520 || sync_binlog                             | 1                    |+-----------------------------------------+----------------------+15 rows in set (0.01 sec)mysql> 

The log format is MIXED, which indicates that some special uuid and now () will be recorded as row, and others will still be logged in the SQL mode.

2. test example:

mysql> use test;Reading table information for completion of table and column namesYou can turn off this feature to get a quicker startup with -ADatabase changedmysql> create table z4 select 1 as a;Query OK, 1 row affected (0.02 sec)Records: 1  Duplicates: 0  Warnings: 0mysql> insert into z4 select 2;Query OK, 1 row affected (0.00 sec)Records: 1  Duplicates: 0  Warnings: 0mysql> 

The blog is owned by the csdn blogger Huang Shan (mchdba). The original address is http://blog.csdn.net/mchdba/article/details/50300035.

3. view the binlog. The binlog mode is garbled and the executed SQL statement is not displayed, as shown below:

[[Email protected] binlog_new] # Total ll usage 32-rw-rw ----. 1 mysql 143 December 10 21:09 mysql-bin.000001-rw-rw ----. 1 mysql 17549 December 11 15:06 mysql-bin.000002-rw-rw ----. 1 mysql 618 December 11 15:07 mysql-bin.000003-rw-rw ----. 1 mysql 135 December 11 15:06 mysql-bin.index [[email protected] binlog_new] #/usr/local/mysql/bin/mysqlbinlog mysql-bin.000003 /*! 50530 SET @ SESSION. pseudo do_slave_mode = 1 */;/*! 40019 SET @ session. max_insert_delayed_threads = 0 */;/*! 50003 SET @ OLD_COMPLETION_TYPE = @ COMPLETION_TYPE, COMPLETION_TYPE = 0 */; DELIMITER /*! */; # At 4 #151211 15:06:46 server id 72 end_log_pos 120 CRC32 0x9961ff72 Start: binlog v 4, server v 5.6.12-log created 151211 15:06:46 # Warning: this binlog is either in use or was not closed properly. BINLOG 'your AAAAICAgCAAAACgoKGRkAAXL/YZk = '/*! */; # At 120 #151211 15:07:13 server id 72 end_log_pos 192 CRC32 0x3ea43b0e Query thread_id = 732 exec_time = 0 error_code = 0 set timestamp = 1449817633 /*! */; SET @ session. pseudo do_thread_id = 732 /*! */; SET @ session. foreign_key_checks = 1, @ session. SQL _auto_is_null = 0, @ session. unique_checks = 1, @ session. autocommit = 1 /*! */; SET session. SQL _mode = 1075838976 /*! */; SET @ session. auto_increment_increment = 1, @ session. auto_increment_offset = 1 /*! */;/*! \ C utf8mb4 *//*! */; SET @ session. character_set_client = 45, @ session. collation_connection = 45, @ session. collation_server = 45 /*! */; SET @ session. lc_time_names = 0 /*! */; SET @ session. collation_database = DEFAULT /*! */; BEGIN /*! */; # At 192 #151211 15:07:13 server id 72 end_log_pos 314 CRC32 0xcaec51ae Query thread_id = 732 exec_time = 0 error_code = 0use 'test '/*! */; Set timestamp = 1449817633 /*! */; Create table 'z4' ('A' int (1) not null default '0 ')/*! */; # At 314 #151211 15:07:13 server id 72 end_log_pos 359 CRC32 0xd8c93954 Table_map: 'test '. 'z4' mapped to number 122 # at 359 #151211 15:07:13 server id 72 end_log_pos 399 CRC32 0xa494ef72 Write_rows: table id 122 flags: STMT_END_FBINLOG 'success // 4 BAAAAcu + UpA = '/*! */; # At 399 #151211 15:07:13 server id 72 end_log_pos 430 CRC32 0xd1ab5b55 Xid = 6908 COMMIT /*! */; # At 430 #151211 15:07:20 server id 72 end_log_pos 502 CRC32 0xdfc3212d Query thread_id = 732 exec_time = 0 error_code = 0 set timestamp = 1449817640 /*! */; BEGIN /*! */; # At 502 #151211 15:07:20 server id 72 end_log_pos 547 CRC32 0xc59aab0e Table_map: 'test '. 'z4' mapped to number 122 # at 547 #151211 15:07:20 server id 72 end_log_pos 587 CRC32 0x648b02a4 Write_rows: table id 122 flags: STMT_END_FBINLOG 'tables // 4 CAAAApAKLZA = '/*! */; # At 587 #151211 15:07:20 server id 72 end_log_pos 618 CRC32 0x9b35600a Xid = 6915 COMMIT /*! */; DELIMITER; # End of log fileROLLBACK/* added by mysqlbinlog */;/*! 50003 SET COMPLETION_TYPE = @ OLD_COMPLETION_TYPE */;/*! 50530 SET @ SESSION. pseudo do_slave_mode = 0 */; [[email protected] binlog_new] #

PS: we can see/usr/local/mysql/bin/mysqlbinlog mysql-bin.000003 parsed are KHZqVhNIAAAALQAAACMCAAAAAHoAAAA such garbled format.

4, google, know that you can use-base64-output = DECODE-ROWS-v to view the SQL statement, as shown below

[[email protected] binlog_new]# /usr/local/mysql/bin/mysqlbinlog --base64-output=DECODE-ROWS -v mysql-bin.000003/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;/*!40019 SET @@session.max_insert_delayed_threads=0*/;/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;DELIMITER /*!*/;# at 4#151211 15:06:46 server id 72  end_log_pos 120 CRC32 0x9961ff72     Start: binlog v 4, server v 5.6.12-log created 151211 15:06:46# Warning: this binlog is either in use or was not closed properly.# at 120#151211 15:07:13 server id 72  end_log_pos 192 CRC32 0x3ea43b0e     Query   thread_id=732   exec_time=0 error_code=0SET TIMESTAMP=1449817633/*!*/;SET @@session.pseudo_thread_id=732/*!*/;SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;SET @@session.sql_mode=1075838976/*!*/;SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;/*!\C utf8mb4 *//*!*/;SET @@session.character_set_client=45,@@session.collation_connection=45,@@session.collation_server=45/*!*/;SET @@session.lc_time_names=0/*!*/;SET @@session.collation_database=DEFAULT/*!*/;BEGIN/*!*/;# at 192#151211 15:07:13 server id 72  end_log_pos 314 CRC32 0xcaec51ae     Query   thread_id=732   exec_time=0 error_code=0use `test`/*!*/;SET TIMESTAMP=1449817633/*!*/;CREATE TABLE `z4` (  `a` int(1) NOT NULL DEFAULT '0')/*!*/;# at 314#151211 15:07:13 server id 72  end_log_pos 359 CRC32 0xd8c93954     Table_map: `test`.`z4` mapped to number 122# at 359#151211 15:07:13 server id 72  end_log_pos 399 CRC32 0xa494ef72     Write_rows: table id 122 flags: STMT_END_F### INSERT INTO `test`.`z4`### SET###   @1=1# at 399#151211 15:07:13 server id 72  end_log_pos 430 CRC32 0xd1ab5b55     Xid = 6908COMMIT/*!*/;# at 430#151211 15:07:20 server id 72  end_log_pos 502 CRC32 0xdfc3212d     Query   thread_id=732   exec_time=0 error_code=0SET TIMESTAMP=1449817640/*!*/;BEGIN/*!*/;# at 502#151211 15:07:20 server id 72  end_log_pos 547 CRC32 0xc59aab0e     Table_map: `test`.`z4` mapped to number 122# at 547#151211 15:07:20 server id 72  end_log_pos 587 CRC32 0x648b02a4     Write_rows: table id 122 flags: STMT_END_F### INSERT INTO `test`.`z4`### SET###   @1=2# at 587#151211 15:07:20 server id 72  end_log_pos 618 CRC32 0x9b35600a     Xid = 6915COMMIT/*!*/;DELIMITER ;# End of log fileROLLBACK /* added by mysqlbinlog */;/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;[[email protected] binlog_new]# 

You can see SQL statements, but they are all in row mode, as shown below:

### INSERT INTO `test`.`z4`### SET### @1=2# at 587

The real SQL statement executed by the application or client is invisible, which is not conducive to business analysis data analysis and optimization of the program.

5. Problem Analysis

In this way, the binlog log format MIXED is recorded as garbled characters, so I will switch to the STATEMENT format to see if the garbled characters will continue ?, After modifying my. cnf, restart the mysql database and start the table creation test. However, the following error is returned:

mysql> create table z3 select 1 as a;ERROR 1665 (HY000): Cannot execute statement: impossible to write to binary log since BINLOG_FORMAT = STATEMENT and at least one table uses a storage engine limited to row-based logging. InnoDB is limited to row-logging when transaction isolation level is READ COMMITTED or READ UNCOMMITTED.mysql> 

When the problem is found, we can see the problem: the isolation level is too low. My default isolation level is READ-COMMITTED, so the binlog records must be in the row mode, the parsing is garbled, forced to use-v display is also the row mode, so if I upgrade the isolation level to the REPEATABLE-READ, there will be a row format also has statement format. Next, we will use two small instances to verify my judgment:

4.1 REPEATABLE-READ and STATEMENT test results

** So I upgraded the isolation level to REPEATABLE-READ and set binlog to binlog_format = STATEMENT
:**

# Set the default transaction isolation level. Levels available are:# READ-UNCOMMITTED, READ-COMMITTED, REPEATABLE-READ, SERIALIZABLEtransaction_isolation = REPEATABLE-READbinlog_format=STATEMENT

Restart mysql to see what the binlog record format is, as shown below:

BEGIN/*!*/;# at 219# at 251#151211 16:15:02 server id 72 end_log_pos 251 CRC32 0x4ea440db IntvarSET INSERT_ID=10550/*!*/;#151211 16:15:02 server id 72 end_log_pos 435 CRC32 0xa37c5f2d Query thread_id=1 exec_time=0 error_code=0use `parking_db`/*!*/;SET TIMESTAMP=1449821702/*!*/;INSERT INTO access_log.access_log VALUES(NULL,CONNECTION_ID(),NOW(),USER(),CURRENT_USER())/*!*/;# at 435#151211 16:15:02 server id 72 end_log_pos 466 CRC32 0x2970e89a Xid = 3COMMIT/*!*/;# at 466#151211 16:16:22 server id 72 end_log_pos 569 CRC32 0xbe43b367 Query thread_id=2 exec_time=0 error_code=0use `test`/*!*/;SET TIMESTAMP=1449821782/*!*/;create table z4 select 1 as a/*!*/;# at 569#151211 16:16:32 server id 72 end_log_pos 648 CRC32 0x69b2383c Query thread_id=2 exec_time=0 error_code=0SET TIMESTAMP=1449821792/*!*/;BEGIN/*!*/;# at 648#151211 16:16:32 server id 72 end_log_pos 745 CRC32 0xcd1721a4 Query thread_id=2 exec_time=0 error_code=0SET TIMESTAMP=1449821792/*!*/;insert into z4 select 2/*!*/;# at 745#151211 16:16:32 server id 72 end_log_pos 776 CRC32 0xfc0dcfc4 Xid = 70COMMIT/*!*/;DELIMITER ;# End of log fileROLLBACK /* added by mysqlbinlog */;/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;[[email protected] binlog_new]# 

The insert into access_log.access_log VALUES (NULL, CONNECTION_ID (), NOW (), USER (), CURRENT_USER () functions are recommended in row mode, during master-slave replication, the uuid is now () and so on, which may cause time delay. Therefore, the statement format is not the best choice for data consistency.

4.2 REPEATABLE-READ and MIXED test results

Modify settings in my. cnf:

transaction_isolation = REPEATABLE-READbinlog_format=MIXED

After the mysql database is restarted, enter the test data:

mysql> insert into z4 select 3;Query OK, 1 row affected (0.00 sec)Records: 1 Duplicates: 0 Warnings: 0mysql> exit

View the binlog data. The SQL record insert into z4 select 3 is displayed, indicating that the parsed SQL statement is normal in mixed mode, and some now () the uuid has been directly parsed into the row format, as shown below:

[[email protected] binlog_new]# /usr/local/mysql/bin/mysqlbinlog --base64-output=DECODE-ROWS -v mysql-bin.000007...# at 274#151211 16:21:02 server id 72 end_log_pos 368 CRC32 0x156a1c51 Write_rows: table id 70 flags: STMT_END_F### INSERT INTO `access_log`.`access_log`### SET### @1=10551### @2=1### @3=1449822062### @4='[email protected]'### @5='[email protected]%'# at 368#151211 16:21:02 server id 72 end_log_pos 399 CRC32 0x8254defe Xid = 3COMMIT/*!*/;# at 399#151211 16:21:25 server id 72 end_log_pos 478 CRC32 0xe252f5c7 Query thread_id=2 exec_time=0 error_code=0SET TIMESTAMP=1449822085/*!*/;BEGIN/*!*/;# at 478#151211 16:21:25 server id 72 end_log_pos 575 CRC32 0x34308ad6 Query thread_id=2 exec_time=0 error_code=0use `test`/*!*/;SET TIMESTAMP=1449822085/*!*/;insert into z4 select 3/*!*/;# at 575#151211 16:21:25 server id 72 end_log_pos 606 CRC32 0x67c460eb Xid = 61COMMIT/*!*/;DELIMITER ;# End of log fileROLLBACK /* added by mysqlbinlog */;/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;[[email protected] binlog_new]#