From 27664ef29d97be2973982aedcc0c8c90d18b20a4 Mon Sep 17 00:00:00 2001 From: Sachin Setiya Date: Thu, 26 Sep 2019 15:05:55 +0530 Subject: MDEV-20574 Position of events reported by mysqlbinlog is wrong with encrypted binlogs, SHOW BINLOG EVENTS reports the correct one. Analysis Mysqlbinlog output for encrypted binary log #Q> insert into tab1 values (3,'row 003') #190912 17:36:35 server id 10221 end_log_pos 980 CRC32 0x53bcb3d3 Table_map: `test`.`tab1` mapped to number 19 # at 940 #190912 17:36:35 server id 10221 end_log_pos 1026 CRC32 0xf2ae5136 Write_rows: table id 19 flags: STMT_END_F Here we can see Table_map_log_event ends at 980 but Next event starts at 940. And the reason for that is we do not send START_ENCRYPTION_EVENT to the slave Solution:- Send Start_encryption_log_event as Ignorable_log_event to slave(mysqlbinlog), So that mysqlbinlog can update its log_pos. Since Slave can request multiple FORMAT_DESCRIPTION_EVENT while master does not have so We only update slave master pos when master actually have the FORMAT_DESCRIPTION_EVENT. Similar logic should be applied for START_ENCRYPTION_EVENT. Also added the test case when new server reads the data from old server which does not send START_ENCRYPTION_EVENT to slave. Master Slave Upgrade Scenario. When Slave is updated first, Slave will have extra logic of handling START_ENCRYPTION_EVENT But master willnot be sending START_ENCRYPTION_EVENT. So there will be no issue. When Master is updated first, It will send START_ENCRYPTION_EVENT to slave , But slave will ignore this event in queue_event. --- mysql-test/std_data/binlog_before_20574.bin | Bin 0 -> 1022 bytes .../binlog_mdev_20574_old_binlog.result | 27 ++++++++++++ .../binlog_mdev_20574_old_binlog.test | 46 +++++++++++++++++++++ .../binlog_encryption/binlog_row_annotate.result | 9 ++++ .../suite/binlog_encryption/mysqlbinlog.result | 1 + .../suite/binlog_encryption/mysqlbinlog.test | 3 ++ 6 files changed, 86 insertions(+) create mode 100644 mysql-test/std_data/binlog_before_20574.bin create mode 100644 mysql-test/suite/binlog_encryption/binlog_mdev_20574_old_binlog.result create mode 100644 mysql-test/suite/binlog_encryption/binlog_mdev_20574_old_binlog.test (limited to 'mysql-test') diff --git a/mysql-test/std_data/binlog_before_20574.bin b/mysql-test/std_data/binlog_before_20574.bin new file mode 100644 index 00000000000..596a883dc71 Binary files /dev/null and b/mysql-test/std_data/binlog_before_20574.bin differ diff --git a/mysql-test/suite/binlog_encryption/binlog_mdev_20574_old_binlog.result b/mysql-test/suite/binlog_encryption/binlog_mdev_20574_old_binlog.result new file mode 100644 index 00000000000..cf660297640 --- /dev/null +++ b/mysql-test/suite/binlog_encryption/binlog_mdev_20574_old_binlog.result @@ -0,0 +1,27 @@ +include/master-slave.inc +[connection master] +connection slave; +include/stop_slave.inc +connection master; +include/rpl_stop_server.inc [server_number=1] +# Data in binlog +# CREATE TABLE t1 (a INT); +# INSERT INTO t1 VALUES (1),(2),(3); +# REPLACE INTO t1 VALUES (4); +include/rpl_start_server.inc [server_number=1] +connection slave; +RESET SLAVE; +RESET MASTER; +CHANGE MASTER TO master_host='127.0.0.1', master_port=SERVER_MYPORT_1, master_user='root', master_log_file='master-bin.000001', master_log_pos=4; +include/start_slave.inc +DESC t1; +Field Type Null Key Default Extra +a int(11) YES NULL +SELECT * FROM t1 ORDER BY a; +a +1 +2 +3 +4 +DROP TABLE t1; +include/rpl_end.inc diff --git a/mysql-test/suite/binlog_encryption/binlog_mdev_20574_old_binlog.test b/mysql-test/suite/binlog_encryption/binlog_mdev_20574_old_binlog.test new file mode 100644 index 00000000000..417df631878 --- /dev/null +++ b/mysql-test/suite/binlog_encryption/binlog_mdev_20574_old_binlog.test @@ -0,0 +1,46 @@ +# MDEV-20574 Position of events reported by mysqlbinlog is wrong with encrypted binlogs, SHOW BINLOG EVENTS reports the correct one. +# Test replicating off old master. +# Test case Desc:- When new server reads the data from old server binlog which +# does not send START_ENCRYPTION_EVENT to slave. +# We simulate old master by copying in pre-generated binlog files from earlier +# server versions with encrypted binlog. +--source include/have_binlog_format_row.inc +--source include/master-slave.inc +--source include/have_innodb.inc + +--connection slave +--source include/stop_slave.inc + +--connection master +--let $datadir= `SELECT @@datadir` + +--let $rpl_server_number= 1 +--source include/rpl_stop_server.inc + +--remove_file $datadir/master-bin.000001 +--remove_file $datadir/master-bin.state +--echo # Data in binlog +--echo # CREATE TABLE t1 (a INT); +--echo # INSERT INTO t1 VALUES (1),(2),(3); +--echo # REPLACE INTO t1 VALUES (4); + +--copy_file $MYSQL_TEST_DIR/std_data/binlog_before_20574.bin $datadir/master-bin.000001 + +--let $rpl_server_number= 1 +--source include/rpl_start_server.inc + +--source include/wait_until_connected_again.inc +--save_master_pos + +--connection slave +RESET SLAVE; +RESET MASTER; +--replace_result $SERVER_MYPORT_1 SERVER_MYPORT_1 +eval CHANGE MASTER TO master_host='127.0.0.1', master_port=$SERVER_MYPORT_1, master_user='root', master_log_file='master-bin.000001', master_log_pos=4; +--source include/start_slave.inc +--sync_with_master +DESC t1; +SELECT * FROM t1 ORDER BY a; + +DROP TABLE t1; +--source include/rpl_end.inc diff --git a/mysql-test/suite/binlog_encryption/binlog_row_annotate.result b/mysql-test/suite/binlog_encryption/binlog_row_annotate.result index 88c690a8bb7..9b843dc8a6b 100644 --- a/mysql-test/suite/binlog_encryption/binlog_row_annotate.result +++ b/mysql-test/suite/binlog_encryption/binlog_row_annotate.result @@ -104,6 +104,9 @@ DELIMITER /*!*/; #010909 4:46:40 server id # end_log_pos # Start: binlog v 4, server v #.##.## created 010909 4:46:40 at startup ROLLBACK/*!*/; # at # +#010909 4:46:40 server id # end_log_pos # Ignorable +# Ignorable event type 164 (Start_encryption) +# at # #010909 4:46:40 server id # end_log_pos # Gtid list [] # at # #010909 4:46:40 server id # end_log_pos # Binlog checkpoint master-bin.000001 @@ -336,6 +339,9 @@ DELIMITER /*!*/; #010909 4:46:40 server id # end_log_pos # Start: binlog v 4, server v #.##.## created 010909 4:46:40 at startup ROLLBACK/*!*/; # at # +#010909 4:46:40 server id # end_log_pos # Ignorable +# Ignorable event type 164 (Start_encryption) +# at # #010909 4:46:40 server id # end_log_pos # Gtid list [] # at # #010909 4:46:40 server id # end_log_pos # Binlog checkpoint master-bin.000001 @@ -495,6 +501,9 @@ DELIMITER /*!*/; #010909 4:46:40 server id # end_log_pos # Start: binlog v 4, server v #.##.## created 010909 4:46:40 at startup ROLLBACK/*!*/; # at # +#010909 4:46:40 server id # end_log_pos # Ignorable +# Ignorable event type 164 (Start_encryption) +# at # #010909 4:46:40 server id # end_log_pos # Gtid list [] # at # #010909 4:46:40 server id # end_log_pos # Binlog checkpoint master-bin.000001 diff --git a/mysql-test/suite/binlog_encryption/mysqlbinlog.result b/mysql-test/suite/binlog_encryption/mysqlbinlog.result index 71758f7d6e7..e97e0569571 100644 --- a/mysql-test/suite/binlog_encryption/mysqlbinlog.result +++ b/mysql-test/suite/binlog_encryption/mysqlbinlog.result @@ -4,3 +4,4 @@ INSERT INTO t1 VALUES (1),(2),(3); REPLACE INTO t1 VALUES (4); DROP TABLE t1; FLUSH LOGS; +FOUND 1 /Ignorable event type 164.*/ in binlog_enc.sql diff --git a/mysql-test/suite/binlog_encryption/mysqlbinlog.test b/mysql-test/suite/binlog_encryption/mysqlbinlog.test index b80388aaa45..108dbd8782f 100644 --- a/mysql-test/suite/binlog_encryption/mysqlbinlog.test +++ b/mysql-test/suite/binlog_encryption/mysqlbinlog.test @@ -17,5 +17,8 @@ let outfile=$MYSQLTEST_VARDIR/tmp/binlog_enc.sql; exec $MYSQL_BINLOG $local > $outfile; exec $MYSQL_BINLOG $local --force-read >> $outfile; exec $MYSQL_BINLOG $remote >> $outfile; +--let SEARCH_FILE= $outfile +--let SEARCH_PATTERN= Ignorable event type 164.* +--source include/search_pattern_in_file.inc remove_file $outfile; -- cgit v1.2.1