MDEV-16372 ER_BASE64_DECODE_ERROR upon replaying binary log via mysqlbinlog --verbose

(This commit is for 10.3 and upper branches) 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.
2025-08-01 03:47:19 +03:00 · 2020-08-11 21:45:09 +03:00
parent 6a042281bd
commit caa35f8e25
10 changed files with 88 additions and 51 deletions
--- a/client/mysqlbinlog.cc
+++ b/client/mysqlbinlog.cc
@ -969,8 +969,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;
    }
  }
--- a/mysql-test/main/mysqlbinlog_row_minimal.result
+++ b/mysql-test/main/mysqlbinlog_row_minimal.result
@ -327,6 +327,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',
@ -351,23 +369,23 @@ 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*//*!*/;
 START TRANSACTION
 /*!*/;
-# 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 35
-# at 594
-#<date> server id 1  end_log_pos 643 CRC32 XXX 	Update_rows: table id 35 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 */
@ -375,10 +393,10 @@ START TRANSACTION
 ###   @2=b'1' /* BIT(1) meta=1 nullable=1 is_null=0 */
 ###   @3=X /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */
 # Number of rows: 1
-# 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/*!*/;
@ -388,8 +406,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 */;
--- a/mysql-test/main/mysqlbinlog_row_minimal.test
+++ b/mysql-test/main/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;

--- a/mysql-test/suite/binlog/r/binlog_mysqlbinlog_row.result
+++ b/mysql-test/suite/binlog/r/binlog_mysqlbinlog_row.result
@ -5356,7 +5356,5 @@ START TRANSACTION
 #010909  4:46:40 server id 1  end_log_pos # CRC32 XXX 	Table_map: `test`.`t1dec102` mapped to number #
 # at #
 #010909  4:46:40 server id 1  end_log_pos # CRC32 XXX 	Write_rows: table id # flags: STMT_END_F
-### INSERT INTO `test`.`t1dec102`
-### SET
-###   @1=
+
 Error: Found Old DECIMAL (mysql-4.1 or earlier). Not enough metadata to display the value.
--- a/mysql-test/suite/binlog/r/binlog_row_annotate.result
+++ b/mysql-test/suite/binlog/r/binlog_row_annotate.result
@ -449,7 +449,6 @@ START TRANSACTION
 ### 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/*!*/;
@ -1073,7 +1072,6 @@ START TRANSACTION
 ### 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/*!*/;
--- 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
--- a/mysql-test/suite/binlog_encryption/binlog_row_annotate.result
+++ b/mysql-test/suite/binlog_encryption/binlog_row_annotate.result
@ -456,7 +456,6 @@ START TRANSACTION
 ### 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/*!*/;
--- a/sql/log_event.cc
+++ b/sql/log_event.cc
@ -3875,7 +3875,7 @@ bool Log_event::print_base64(IO_CACHE* file,
      ev->need_flashback_review= need_flashback_review;
      if (print_event_info->verbose)
      {
-        if (ev->print_verbose(file, print_event_info))
+        if (ev->print_verbose(&print_event_info->tail_cache, print_event_info))
          goto err;
      }
      else
@ -3899,22 +3899,9 @@ bool 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);
-        error= ev->print_verbose(file, print_event_info);
-      }
+        error= ev->print_verbose(&print_event_info->tail_cache, print_event_info);
      else
-      {
        ev->count_row_events(print_event_info);
-      }
 #endif
      delete ev;
      if (unlikely(error))
@ -11992,7 +11979,7 @@ bool copy_cache_to_file_wrapped(IO_CACHE *body,
                                FILE *file,
                                bool do_wrap,
                                const char *delimiter,
-                                bool is_verbose)
+                                bool is_verbose /*TODO: remove */)
 {
  const my_off_t cache_size= my_b_tell(body);

@ -12025,7 +12012,6 @@ bool copy_cache_to_file_wrapped(IO_CACHE *body,
    my_fprintf(file, fmt_frag, 1);
    if (my_b_copy_to_file(body, file, SIZE_T_MAX))
      goto err;
-    if (!is_verbose)
    my_fprintf(file, fmt_delim, delimiter);

    my_fprintf(file, fmt_binlog2, delimiter);
@ -12035,7 +12021,6 @@ bool copy_cache_to_file_wrapped(IO_CACHE *body,
    my_fprintf(file, str_binlog);
    if (my_b_copy_to_file(body, file, SIZE_T_MAX))
      goto err;
-    if (!is_verbose)
    my_fprintf(file, fmt_delim, delimiter);
  }
  reinit_io_cache(body, WRITE_CACHE, 0, FALSE, TRUE);
@ -12122,7 +12107,6 @@ bool copy_cache_to_string_wrapped(IO_CACHE *cache,
      goto err;
    str += (add_to_len= uint32(cache->end_of_file - (cache_size/2 + 1)));
    to->length += add_to_len;
-    if (!is_verbose)
    {
      str += (add_to_len= sprintf(str , fmt_delim, delimiter));
      to->length += add_to_len;
@ -12138,7 +12122,6 @@ bool copy_cache_to_string_wrapped(IO_CACHE *cache,
      goto err;
    str += cache->end_of_file;
    to->length += (size_t)cache->end_of_file;
-    if (!is_verbose)
      to->length += sprintf(str , fmt_delim, delimiter);
  }

@ -12186,6 +12169,7 @@ bool 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
@ -12216,7 +12200,8 @@ bool Rows_log_event::print_helper(FILE *file,
      if (copy_event_cache_to_file_and_reinit(head, file) ||
          copy_cache_to_file_wrapped(body, file, do_print_encoded,
                                     print_event_info->delimiter,
-                                     print_event_info->verbose))
+                                     print_event_info->verbose) ||
+          copy_event_cache_to_file_and_reinit(tail, file))
        goto err;
    }
    else
@ -12234,6 +12219,11 @@ bool Rows_log_event::print_helper(FILE *file,
      return 1;
    output_buf.append(tmp_str.str, tmp_str.length);
    my_free(tmp_str.str);
+    if (copy_event_cache_to_string_and_reinit(tail, &tmp_str))
+      return 1;
+    output_buf.append(tmp_str.str, tmp_str.length);
+    my_free(tmp_str.str);
+
 #ifdef WHEN_FLASHBACK_REVIEW_READY
    if (copy_event_cache_to_string_and_reinit(sql, &tmp_str))
      return 1;
@ -15056,6 +15046,7 @@ st_print_event_info::st_print_event_info()
  base64_output_mode=BASE64_OUTPUT_UNSPEC;
  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
--- a/sql/log_event.h
+++ b/sql/log_event.h
@ -889,6 +889,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;
@ -899,6 +900,7 @@ 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
--- a/sql/log_event_old.cc
+++ b/sql/log_event_old.cc
@ -1848,6 +1848,7 @@ bool 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->base64_output_mode != BASE64_OUTPUT_NEVER &&
@ -1868,7 +1869,8 @@ bool Old_rows_log_event::print_helper(FILE *file,
    if (copy_event_cache_to_file_and_reinit(head, file) ||
        copy_cache_to_file_wrapped(body, file, do_print_encoded,
                                   print_event_info->delimiter,
-                                     print_event_info->verbose))
+                                   print_event_info->verbose) ||
+        copy_event_cache_to_file_and_reinit(tail, file))
      goto err;
  }
  return 0;