revision-id: c648a7a453963e2c2b2910c7d4b8e211c6f30915 (mariadb-10.2.27-49-gc648a7a4539) parent(s): 102bc7beb080e936ba70c0524a8759799f42458e author: Sachin Setiya committer: Sachin Setiya timestamp: 2019-10-01 00:56:51 +0530 message: 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 server 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. --- .../binlog_encryption/binlog_row_annotate.result | 9 ++++ .../suite/binlog_encryption/mysqlbinlog.result | 1 + .../suite/binlog_encryption/mysqlbinlog.test | 3 ++ sql/log_event.cc | 34 ++++++------ sql/slave.cc | 11 ++++ sql/sql_repl.cc | 63 +++++++++++++++------- 6 files changed, 86 insertions(+), 35 deletions(-) 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; diff --git a/sql/log_event.cc b/sql/log_event.cc index 0e0d69b515c..66f1d6bc790 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -2077,6 +2077,19 @@ Log_event* Log_event::read_log_event(const char* buf, uint event_len, alg != BINLOG_CHECKSUM_ALG_OFF)) event_len= event_len - BINLOG_CHECKSUM_LEN; + /* + Create an object of Ignorable_log_event for unrecognized sub-class. + So that SLAVE SQL THREAD will only update the position and continue. + We should look for this flag first instead of judging by event_type + Any event can be Ignorable_log_event if it has this flag on. + look into @note of Ignorable_log_event + */ + if (uint2korr(buf + FLAGS_OFFSET) & LOG_EVENT_IGNORABLE_F) + { + ev= new Ignorable_log_event(buf, fdle, + get_type_str((Log_event_type) event_type)); + goto exit; + } switch(event_type) { case QUERY_EVENT: ev = new Query_log_event(buf, event_len, fdle, QUERY_EVENT); @@ -2203,24 +2216,13 @@ Log_event* Log_event::read_log_event(const char* buf, uint event_len, ev = new Start_encryption_log_event(buf, event_len, fdle); break; default: - /* - Create an object of Ignorable_log_event for unrecognized sub-class. - So that SLAVE SQL THREAD will only update the position and continue. - */ - if (uint2korr(buf + FLAGS_OFFSET) & LOG_EVENT_IGNORABLE_F) - { - ev= new Ignorable_log_event(buf, fdle, - get_type_str((Log_event_type) event_type)); - } - else - { - DBUG_PRINT("error",("Unknown event code: %d", - (uchar) buf[EVENT_TYPE_OFFSET])); - ev= NULL; - break; - } + DBUG_PRINT("error",("Unknown event code: %d", + (uchar) buf[EVENT_TYPE_OFFSET])); + ev= NULL; + break; } } +exit: if (ev) { diff --git a/sql/slave.cc b/sql/slave.cc index 88a80029bba..1bc21f8895b 100644 --- a/sql/slave.cc +++ b/sql/slave.cc @@ -6317,7 +6317,18 @@ static int queue_event(Master_info* mi,const char* buf, ulong event_len) mi->last_queued_gtid.seq_no == 1000) goto skip_relay_logging; }); + goto default_action; #endif + case START_ENCRYPTION_EVENT: + if (uint2korr(buf + FLAGS_OFFSET) & LOG_EVENT_IGNORABLE_F) + { + /* + If the event was not requested by the slave (the slave did not ask for + it), i.e. has end_log_pos=0, we do not increment mi->master_log_pos + */ + inc_pos= uint4korr(buf+LOG_POS_OFFSET) ? event_len : 0; + break; + } /* fall through */ default: default_action: diff --git a/sql/sql_repl.cc b/sql/sql_repl.cc index edff750a9a3..8a6bea34fb4 100644 --- a/sql/sql_repl.cc +++ b/sql/sql_repl.cc @@ -399,16 +399,27 @@ static int send_file(THD *thd) /** Internal to mysql_binlog_send() routine that recalculates checksum for - a FD event (asserted) that needs additional arranment prior sending to slave. + 1. FD event (asserted) that needs additional arranment prior sending to slave. + 2. Start_encryption_log_event whose Ignored flag is set +TODO DBUG_ASSERT can be removed if this function is used for more general cases */ -inline void fix_checksum(String *packet, ulong ev_offset) + +inline void fix_checksum(enum_binlog_checksum_alg checksum_alg, String *packet, + ulong ev_offset) { + if (checksum_alg == BINLOG_CHECKSUM_ALG_OFF || + checksum_alg == BINLOG_CHECKSUM_ALG_UNDEF) + return; /* recalculate the crc for this event */ uint data_len = uint4korr(packet->ptr() + ev_offset + EVENT_LEN_OFFSET); ha_checksum crc; - DBUG_ASSERT(data_len == + DBUG_ASSERT((data_len == LOG_EVENT_MINIMAL_HEADER_LEN + FORMAT_DESCRIPTION_HEADER_LEN + - BINLOG_CHECKSUM_ALG_DESC_LEN + BINLOG_CHECKSUM_LEN); + BINLOG_CHECKSUM_ALG_DESC_LEN + BINLOG_CHECKSUM_LEN) || + (data_len == + LOG_EVENT_MINIMAL_HEADER_LEN + BINLOG_CRYPTO_SCHEME_LENGTH + + BINLOG_KEY_VERSION_LENGTH + BINLOG_NONCE_LENGTH + + BINLOG_CHECKSUM_LEN)); crc= my_checksum(0, (uchar *)packet->ptr() + ev_offset, data_len - BINLOG_CHECKSUM_LEN); int4store(packet->ptr() + ev_offset + data_len - BINLOG_CHECKSUM_LEN, crc); @@ -2135,6 +2146,7 @@ static int send_format_descriptor_event(binlog_send_info *info, IO_CACHE *log, THD *thd= info->thd; String *packet= info->packet; Log_event_type event_type; + bool initial_log_pos= info->clear_initial_log_pos; DBUG_ENTER("send_format_descriptor_event"); /** @@ -2233,7 +2245,7 @@ static int send_format_descriptor_event(binlog_send_info *info, IO_CACHE *log, (*packet)[FLAGS_OFFSET+ev_offset] &= ~LOG_EVENT_BINLOG_IN_USE_F; - if (info->clear_initial_log_pos) + if (initial_log_pos) { info->clear_initial_log_pos= false; /* @@ -2251,9 +2263,7 @@ static int send_format_descriptor_event(binlog_send_info *info, IO_CACHE *log, ST_CREATED_OFFSET+ev_offset, (ulong) 0); /* fix the checksum due to latest changes in header */ - if (info->current_checksum_alg != BINLOG_CHECKSUM_ALG_OFF && - info->current_checksum_alg != BINLOG_CHECKSUM_ALG_UNDEF) - fix_checksum(packet, ev_offset); + fix_checksum(info->current_checksum_alg, packet, ev_offset); } else if (info->using_gtid_state) { @@ -2274,9 +2284,7 @@ static int send_format_descriptor_event(binlog_send_info *info, IO_CACHE *log, { int4store((char*) packet->ptr()+LOG_EVENT_MINIMAL_HEADER_LEN+ ST_CREATED_OFFSET+ev_offset, (ulong) 0); - if (info->current_checksum_alg != BINLOG_CHECKSUM_ALG_OFF && - info->current_checksum_alg != BINLOG_CHECKSUM_ALG_UNDEF) - fix_checksum(packet, ev_offset); + fix_checksum(info->current_checksum_alg, packet, ev_offset); } } @@ -2289,12 +2297,16 @@ static int send_format_descriptor_event(binlog_send_info *info, IO_CACHE *log, } /* - Read the following Start_encryption_log_event but don't send it to slave. - Slave doesn't need to know whether master's binlog is encrypted, - and if it'll want to encrypt its logs, it should generate its own - random nonce, not use the one from the master. + Read the following Start_encryption_log_event and send it to slave as + Ignorable_log_event. Although Slave doesn't need to know whether master's + binlog is encrypted but it needs to update slave log pos (for mysqlbinlog). + + If slave want to encrypt its logs, it should generate its own + random nonce, it should not use the one from the master. */ - packet->length(0); + /* reset transmit packet for the event read from binary log file */ + if (reset_transmit_packet(info, info->flags, &ev_offset, &info->errmsg)) + DBUG_RETURN(1); info->last_pos= linfo->pos; error= Log_event::read_log_event(log, packet, info->fdev, opt_master_verify_checksum @@ -2308,12 +2320,13 @@ static int send_format_descriptor_event(binlog_send_info *info, IO_CACHE *log, DBUG_RETURN(1); } - event_type= (Log_event_type)((uchar)(*packet)[LOG_EVENT_OFFSET]); + event_type= (Log_event_type)((uchar)(*packet)[LOG_EVENT_OFFSET + ev_offset]); if (event_type == START_ENCRYPTION_EVENT) { Start_encryption_log_event *sele= (Start_encryption_log_event *) - Log_event::read_log_event(packet->ptr(), packet->length(), &info->errmsg, - info->fdev, BINLOG_CHECKSUM_ALG_OFF); + Log_event::read_log_event(packet->ptr() + ev_offset, packet->length() + - ev_offset, &info->errmsg, info->fdev, + BINLOG_CHECKSUM_ALG_OFF); if (!sele) { info->error= ER_MASTER_FATAL_ERROR_READING_BINLOG; @@ -2327,6 +2340,18 @@ static int send_format_descriptor_event(binlog_send_info *info, IO_CACHE *log, delete sele; DBUG_RETURN(1); } + /* Make it Ignorable_log_event and send it */ + (*packet)[FLAGS_OFFSET+ev_offset] |= LOG_EVENT_IGNORABLE_F; + if (initial_log_pos) + int4store((char*) packet->ptr()+LOG_POS_OFFSET+ev_offset, (ulong) 0); + /* fix the checksum due to latest changes in header */ + fix_checksum(info->current_checksum_alg, packet, ev_offset); + if (my_net_write(info->net, (uchar*) packet->ptr(), packet->length())) + { + info->errmsg= "Failed on my_net_write()"; + info->error= ER_UNKNOWN_ERROR; + DBUG_RETURN(1); + } delete sele; } else if (start_pos == BIN_LOG_HEADER_SIZE)