diff options
author | Andrei Elkin <andrei.elkin@mariadb.com> | 2020-08-11 21:45:09 +0300 |
---|---|---|
committer | Andrei Elkin <andrei.elkin@mariadb.com> | 2020-08-31 18:37:44 +0300 |
commit | 6112a0f93d137b9754bc04449873311784e0edd9 (patch) | |
tree | dc038437c44d0397460a3acf624163c370d86b81 | |
parent | 9bb17ecf4352e0ba009d6afb9260d291ed70fa4c (diff) | |
download | mariadb-git-6112a0f93d137b9754bc04449873311784e0edd9.tar.gz |
MDEV-16372 ER_BASE64_DECODE_ERROR upon replaying binary log via mysqlbinlog --verbose
(This commit is exclusively for 10.2 branch. Do not merge it to 10.3)
In case of a pattern of non-STMT_END-marked Rows-log-event (A) followed by
a STMT_END marked one (B) mysqlbinlog mixes up the base64 encoded rows events
with their pseudo sql representation produced by the verbose option:
BINLOG '
base64 encoded data for A
### verbose section for A
base64 encoded data for B
### verbose section for B
'/*!*/;
In effect the produced BINLOG '...' query is not valid and is rejected with the error.
Examples of this way malformed BINLOG could have been found in binlog_row_annotate.result
that gets corrected with the patch.
The issue is fixed with introduction an auxiliary IO_CACHE to hold on the verbose
comments until the terminal STMT_END event is found. The new cache is emptied
out after two pre-existing ones are done at that time.
The correctly produced output now for the above case is as the following:
BINLOG '
base64 encoded data for A
base64 encoded data for B
'/*!*/;
### verbose section for A
### verbose section for B
Thanks to Alexey Midenkov for the problem recognition and attempt to tackle,
and to Venkatesh Duggirala who produced a patch for the upstream whose
idea is exploited here, as well as to MDEV-23077 reporter LukeXwang who
also contributed a piece of a patch aiming at this issue.
-rw-r--r-- | client/mysqlbinlog.cc | 11 | ||||
-rw-r--r-- | mysql-test/r/mysqlbinlog_row_minimal.result | 44 | ||||
-rw-r--r-- | mysql-test/suite/binlog/r/binlog_row_annotate.result | 2 | ||||
-rw-r--r-- | mysql-test/suite/binlog/t/binlog_mysqlbinlog_row_frag.test | 3 | ||||
-rw-r--r-- | mysql-test/suite/binlog_encryption/binlog_row_annotate.result | 1 | ||||
-rw-r--r-- | mysql-test/t/mysqlbinlog_row_minimal.test | 32 | ||||
-rw-r--r-- | sql/log_event.cc | 38 | ||||
-rw-r--r-- | sql/log_event.h | 6 | ||||
-rw-r--r-- | sql/log_event_old.cc | 8 |
9 files changed, 96 insertions, 49 deletions
diff --git a/client/mysqlbinlog.cc b/client/mysqlbinlog.cc index 13a92c0b581..4e28876cdf6 100644 --- a/client/mysqlbinlog.cc +++ b/client/mysqlbinlog.cc @@ -891,7 +891,8 @@ static bool print_base64(PRINT_EVENT_INFO *print_event_info, Log_event *ev) ev->print(result_file, print_event_info); return print_event_info->head_cache.error == -1 || - print_event_info->body_cache.error == -1; + print_event_info->body_cache.error == -1 || + print_event_info->tail_cache.error == -1; } @@ -962,8 +963,12 @@ static bool print_row_event(PRINT_EVENT_INFO *print_event_info, Log_event *ev, my_b_printf(body_cache, "'%s\n", print_event_info->delimiter); // flush cache - if ((copy_event_cache_to_file_and_reinit(&print_event_info->head_cache, result_file) || - copy_event_cache_to_file_and_reinit(&print_event_info->body_cache, result_file))) + if ((copy_event_cache_to_file_and_reinit(&print_event_info->head_cache, + result_file) || + copy_event_cache_to_file_and_reinit(&print_event_info->body_cache, + result_file) || + copy_event_cache_to_file_and_reinit(&print_event_info->tail_cache, + result_file))) return 1; } } diff --git a/mysql-test/r/mysqlbinlog_row_minimal.result b/mysql-test/r/mysqlbinlog_row_minimal.result index e78c3ca3a40..776c7ac5b53 100644 --- a/mysql-test/r/mysqlbinlog_row_minimal.result +++ b/mysql-test/r/mysqlbinlog_row_minimal.result @@ -319,6 +319,24 @@ ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; DROP TABLE t1,t2; +# +# MDEV-16372 ER_BASE64_DECODE_ERROR upon replaying binary log with system table +# +FLUSH BINARY LOGS; +CREATE TABLE t1 (pk INT PRIMARY KEY); +INSERT INTO t1 VALUES (1); +INSERT INTO t1 VALUES (1), (2) ON DUPLICATE KEY UPDATE pk= pk + 10; +FLUSH BINARY LOGS; +Proof: two subsequent patterns must be found +FOUND 1 /### UPDATE `test`.`t1`/ in mysqlbinlog.sql +FOUND 2 /### INSERT INTO `test`.`t1`/ in mysqlbinlog.sql +DROP TABLE t1; +SELECT * FROM t1; +pk +2 +11 +# Cleanup +DROP TABLE t1; CREATE TABLE `t1` ( `id` BIGINT(20) UNSIGNED NOT NULL AUTO_INCREMENT, `is_deleted` BIT(1) DEFAULT b'0', @@ -343,33 +361,33 @@ FLUSH BINARY LOGS; /*!40019 SET @@session.max_insert_delayed_threads=0*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; -# at 387 -#<date> server id 1 end_log_pos 429 CRC32 XXX GTID 0-1-16 +# at POS +#<date> server id 1 end_log_pos END_LOG_POS CRC32 XXX GTID D-S-N /*!100101 SET @@session.skip_parallel_replication=0*//*!*/; /*!100001 SET @@session.gtid_domain_id=0*//*!*/; /*!100001 SET @@session.server_id=1*//*!*/; -/*!100001 SET @@session.gtid_seq_no=16*//*!*/; +/*!100001 SET @@session.gtid_seq_no=21*//*!*/; BEGIN /*!*/; -# at 429 -# at 543 -#<date> server id 1 end_log_pos 543 CRC32 XXX Annotate_rows: +# at POS +# at POS +#<date> server id 1 end_log_pos END_LOG_POS CRC32 XXX Annotate_rows: #Q> UPDATE t1 t1 INNER JOIN t2 t2 ON t1.ref_id = t2.id #Q> SET t1.is_deleted = TRUE #Q> WHERE t1.id = -#<date> server id 1 end_log_pos 594 CRC32 XXX Table_map: `test`.`t1` mapped to number 34 -# at 594 -#<date> server id 1 end_log_pos 643 CRC32 XXX Update_rows: table id 34 flags: STMT_END_F +#<date> server id 1 end_log_pos END_LOG_POS CRC32 XXX Table_map: `test`.`t1` mapped to number TID +# at POS +#<date> server id 1 end_log_pos END_LOG_POS CRC32 XXX Update_rows: table id TID flags: STMT_END_F ### UPDATE `test`.`t1` ### WHERE ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### SET ### @2=b'1' /* BIT(1) meta=1 nullable=1 is_null=0 */ ### @3=X /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ -# at 643 -#<date> server id 1 end_log_pos 725 CRC32 XXX Query thread_id=5 exec_time=x error_code=0 +# at POS +#<date> server id 1 end_log_pos END_LOG_POS CRC32 XXX Query thread_id=TID exec_time=x error_code=0 SET TIMESTAMP=X/*!*/; -SET @@session.pseudo_thread_id=5/*!*/; +SET @@session.pseudo_thread_id=TID/*!*/; SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1/*!*/; SET @@session.sql_mode=#/*!*/; SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/; @@ -379,8 +397,6 @@ SET @@session.lc_time_names=0/*!*/; SET @@session.collation_database=DEFAULT/*!*/; COMMIT /*!*/; -# at 725 -#<date> server id 1 end_log_pos 773 CRC32 XXX Rotate to master-bin.000004 pos: 4 DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; diff --git a/mysql-test/suite/binlog/r/binlog_row_annotate.result b/mysql-test/suite/binlog/r/binlog_row_annotate.result index 2104d6b0e51..732ecdd02fd 100644 --- a/mysql-test/suite/binlog/r/binlog_row_annotate.result +++ b/mysql-test/suite/binlog/r/binlog_row_annotate.result @@ -442,7 +442,6 @@ BEGIN ### DELETE FROM `test1`.`t1` ### WHERE ### @1=3 /* INT meta=0 nullable=1 is_null=0 */ -'/*!*/; # at # #010909 4:46:40 server id # end_log_pos # Query thread_id=# exec_time=# error_code=0 SET TIMESTAMP=1000000000/*!*/; @@ -1053,7 +1052,6 @@ BEGIN ### DELETE FROM `test1`.`t1` ### WHERE ### @1=3 /* INT meta=0 nullable=1 is_null=0 */ -'/*!*/; # at # #010909 4:46:40 server id # end_log_pos # Query thread_id=# exec_time=# error_code=0 SET TIMESTAMP=1000000000/*!*/; diff --git a/mysql-test/suite/binlog/t/binlog_mysqlbinlog_row_frag.test b/mysql-test/suite/binlog/t/binlog_mysqlbinlog_row_frag.test index a1791d9701d..9f79deea3db 100644 --- a/mysql-test/suite/binlog/t/binlog_mysqlbinlog_row_frag.test +++ b/mysql-test/suite/binlog/t/binlog_mysqlbinlog_row_frag.test @@ -11,8 +11,7 @@ SELECT a from t into @a; FLUSH LOGS; DELETE FROM t; -# Todo: MDEV-10362 to test multi-row Rows_log_event:s in verbose mode ---exec $MYSQL_BINLOG -vv --debug-binlog-row-event-max-encoded-size=256 $MYSQLD_DATADIR/master-bin.000001 > $MYSQLTEST_VARDIR/tmp/mysqlbinlog.sql +--exec $MYSQL_BINLOG --verbose --debug-binlog-row-event-max-encoded-size=256 $MYSQLD_DATADIR/master-bin.000001 > $MYSQLTEST_VARDIR/tmp/mysqlbinlog.sql --let SEARCH_PATTERN= BINLOG @binlog_fragment_0, @binlog_fragment_1 --let SEARCH_FILE= $MYSQLTEST_VARDIR/tmp/mysqlbinlog.sql diff --git a/mysql-test/suite/binlog_encryption/binlog_row_annotate.result b/mysql-test/suite/binlog_encryption/binlog_row_annotate.result index 9b843dc8a6b..83903ecc18a 100644 --- a/mysql-test/suite/binlog_encryption/binlog_row_annotate.result +++ b/mysql-test/suite/binlog_encryption/binlog_row_annotate.result @@ -449,7 +449,6 @@ BEGIN ### DELETE FROM `test1`.`t1` ### WHERE ### @1=3 /* INT meta=0 nullable=1 is_null=0 */ -'/*!*/; # at # #010909 4:46:40 server id # end_log_pos # Query thread_id=# exec_time=# error_code=0 SET TIMESTAMP=1000000000/*!*/; diff --git a/mysql-test/t/mysqlbinlog_row_minimal.test b/mysql-test/t/mysqlbinlog_row_minimal.test index b69aa6da14b..b399cc4ac45 100644 --- a/mysql-test/t/mysqlbinlog_row_minimal.test +++ b/mysql-test/t/mysqlbinlog_row_minimal.test @@ -33,6 +33,33 @@ FLUSH BINARY LOGS; DROP TABLE t1,t2; +--echo # +--echo # MDEV-16372 ER_BASE64_DECODE_ERROR upon replaying binary log with system table +--echo # +FLUSH BINARY LOGS; +CREATE TABLE t1 (pk INT PRIMARY KEY); +INSERT INTO t1 VALUES (1); +INSERT INTO t1 VALUES (1), (2) ON DUPLICATE KEY UPDATE pk= pk + 10; + +--let $binlog = query_get_value(SHOW MASTER STATUS, File, 1) + +FLUSH BINARY LOGS; +--exec $MYSQL_BINLOG --verbose $datadir/$binlog > $MYSQLTEST_VARDIR/tmp/mysqlbinlog.sql +--echo Proof: two subsequent patterns must be found +--let SEARCH_PATTERN= ### UPDATE `test`.`t1` +--let SEARCH_FILE= $MYSQLTEST_VARDIR/tmp/mysqlbinlog.sql +--source include/search_pattern_in_file.inc +--let SEARCH_PATTERN= ### INSERT INTO `test`.`t1` +--let SEARCH_FILE= $MYSQLTEST_VARDIR/tmp/mysqlbinlog.sql +--source include/search_pattern_in_file.inc + +DROP TABLE t1; +--exec $MYSQL test < $MYSQLTEST_VARDIR/tmp/mysqlbinlog.sql +SELECT * FROM t1; + +--echo # Cleanup +DROP TABLE t1; +--remove_file $MYSQLTEST_VARDIR/tmp/mysqlbinlog.sql # # MDEV-14605 ON UPDATE CURRENT_TIMESTAMP fields by multi-table UPDATE are not logged with binlog_row_image=MINIMAL # @@ -64,11 +91,12 @@ UPDATE t1 t1 INNER JOIN t2 t2 ON t1.ref_id = t2.id WHERE t1.id = 1; --let $binlog = query_get_value(SHOW MASTER STATUS, File, 1) +--let $binlog_end= query_get_value(SHOW MASTER STATUS, Position, 1) FLUSH BINARY LOGS; --replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR ---replace_regex /\d{6} *\d*:\d\d:\d\d/<date>/ /SET TIMESTAMP=\d*/SET TIMESTAMP=X/ /exec_time=\d*/exec_time=x/ /@3=\d*/@3=X/ /CRC32 0x[0-9a-f]+/CRC32 XXX/ /@@session.sql_mode=\d+/@@session.sql_mode=#/ /collation_server=\d+/collation_server=#/ ---exec $MYSQL_BINLOG --verbose --verbose --base64-output=DECODE-ROWS $datadir/$binlog --start-position=$binlog_pos +--replace_regex /table id \d*/table id TID/ /mapped to number \d*/mapped to number TID/ /at \d*/at POS/ /end_log_pos \d*/end_log_pos END_LOG_POS/ /GTID \d*-\d*-\d*/GTID D-S-N/ /\d{6} *\d*:\d\d:\d\d/<date>/ /SET TIMESTAMP=\d*/SET TIMESTAMP=X/ /exec_time=\d*/exec_time=x/ /@3=\d*/@3=X/ /CRC32 0x[0-9a-f]+/CRC32 XXX/ /@@session.sql_mode=\d+/@@session.sql_mode=#/ /collation_server=\d+/collation_server=#/ /thread_id=\d*/thread_id=TID/ +--exec $MYSQL_BINLOG --verbose --verbose --base64-output=DECODE-ROWS $datadir/$binlog --start-position=$binlog_pos --stop-position=$binlog_end DROP TABLE t1,t2; diff --git a/sql/log_event.cc b/sql/log_event.cc index 26c9cb6f9cb..e21a18273b3 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -3579,7 +3579,7 @@ void Log_event::print_base64(IO_CACHE* file, #ifdef WHEN_FLASHBACK_REVIEW_READY ev->need_flashback_review= need_flashback_review; if (print_event_info->verbose) - ev->print_verbose(file, print_event_info); + ev->print_verbose(&print_event_info->tail_cache, print_event_info); else { IO_CACHE tmp_cache; @@ -3589,18 +3589,7 @@ void Log_event::print_base64(IO_CACHE* file, } #else if (print_event_info->verbose) - { - /* - Verbose event printout can't start before encoded data - got enquoted. This is done at this point though multi-row - statement remain vulnerable. - TODO: fix MDEV-10362 to remove this workaround. - */ - if (print_event_info->base64_output_mode != - BASE64_OUTPUT_DECODE_ROWS) - my_b_printf(file, "'%s\n", print_event_info->delimiter); - ev->print_verbose(file, print_event_info); - } + ev->print_verbose(&print_event_info->tail_cache, print_event_info); #endif delete ev; } @@ -11538,11 +11527,8 @@ void copy_cache_to_string_wrapped(IO_CACHE *cache, str_tmp.length= sprintf(str_tmp.str, fmt_frag, 1); ret.append(&str_tmp); ret.append(cache, uint32(cache->end_of_file - (cache_size/2 + 1))); - if (!is_verbose) - { - str_tmp.length= sprintf(str_tmp.str, fmt_delim, delimiter); - ret.append(&str_tmp); - } + str_tmp.length= sprintf(str_tmp.str, fmt_delim, delimiter); + ret.append(&str_tmp); str_tmp.length= sprintf(str_tmp.str, "BINLOG @binlog_fragment_0, @binlog_fragment_1%s\n", delimiter); ret.append(&str_tmp); @@ -11552,11 +11538,8 @@ void copy_cache_to_string_wrapped(IO_CACHE *cache, str_tmp.length= sprintf(str_tmp.str, str_binlog); ret.append(&str_tmp); ret.append(cache, (uint32) cache->end_of_file); - if (!is_verbose) - { - str_tmp.length= sprintf(str_tmp.str, fmt_delim, delimiter); - ret.append(&str_tmp); - } + str_tmp.length= sprintf(str_tmp.str, fmt_delim, delimiter); + ret.append(&str_tmp); } to->length= ret.length(); @@ -11605,6 +11588,7 @@ void Rows_log_event::print_helper(FILE *file, { IO_CACHE *const head= &print_event_info->head_cache; IO_CACHE *const body= &print_event_info->body_cache; + IO_CACHE *const tail= &print_event_info->tail_cache; #ifdef WHEN_FLASHBACK_REVIEW_READY IO_CACHE *const sql= &print_event_info->review_sql_cache; #endif @@ -11646,6 +11630,13 @@ void Rows_log_event::print_helper(FILE *file, print_event_info->verbose); output_buf.append(&tmp_str); my_free(tmp_str.str); + if (copy_event_cache_to_string_and_reinit(tail, &tmp_str)) + { + tail->error= -1; + return; + } + output_buf.append(&tmp_str); + my_free(tmp_str.str); } } #endif @@ -14316,6 +14307,7 @@ st_print_event_info::st_print_event_info() myf const flags = MYF(MY_WME | MY_NABP); open_cached_file(&head_cache, NULL, NULL, 0, flags); open_cached_file(&body_cache, NULL, NULL, 0, flags); + open_cached_file(&tail_cache, NULL, NULL, 0, flags); #ifdef WHEN_FLASHBACK_REVIEW_READY open_cached_file(&review_sql_cache, NULL, NULL, 0, flags); #endif diff --git a/sql/log_event.h b/sql/log_event.h index 1fae201057f..3fc44a9669f 100644 --- a/sql/log_event.h +++ b/sql/log_event.h @@ -848,18 +848,19 @@ typedef struct st_print_event_info ~st_print_event_info() { close_cached_file(&head_cache); close_cached_file(&body_cache); + close_cached_file(&tail_cache); #ifdef WHEN_FLASHBACK_REVIEW_READY close_cached_file(&review_sql_cache); #endif } bool init_ok() /* tells if construction was successful */ - { return my_b_inited(&head_cache) && my_b_inited(&body_cache) + { return my_b_inited(&head_cache) && my_b_inited(&body_cache) && + my_b_inited(&tail_cache) #ifdef WHEN_FLASHBACK_REVIEW_READY && my_b_inited(&review_sql_cache) #endif ; } - /* Settings on how to print the events */ bool short_form; enum_base64_output_mode base64_output_mode; @@ -885,6 +886,7 @@ typedef struct st_print_event_info */ IO_CACHE head_cache; IO_CACHE body_cache; + IO_CACHE tail_cache; #ifdef WHEN_FLASHBACK_REVIEW_READY /* Storing the SQL for reviewing */ IO_CACHE review_sql_cache; diff --git a/sql/log_event_old.cc b/sql/log_event_old.cc index b655d510bd5..2de316a4c55 100644 --- a/sql/log_event_old.cc +++ b/sql/log_event_old.cc @@ -1859,6 +1859,7 @@ void Old_rows_log_event::print_helper(FILE *file, { IO_CACHE *const head= &print_event_info->head_cache; IO_CACHE *const body= &print_event_info->body_cache; + IO_CACHE *const tail= &print_event_info->tail_cache; bool do_print_encoded= print_event_info->base64_output_mode != BASE64_OUTPUT_DECODE_ROWS && !print_event_info->short_form; @@ -1890,6 +1891,13 @@ void Old_rows_log_event::print_helper(FILE *file, print_event_info->verbose); output_buf.append(&tmp_str); my_free(tmp_str.str); + if (copy_event_cache_to_string_and_reinit(tail, &tmp_str)) + { + tail->error= -1; + return; + } + output_buf.append(&tmp_str); + my_free(tmp_str.str); } } #endif |