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.

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) ||
+      if ((copy_event_cache_to_file_and_reinit(&print_event_info->head_cache,
-          copy_event_cache_to_file_and_reinit(&print_event_info->body_cache, result_file)))
+                                               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;
     }
   }

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
+# at POS
-#<date> server id 1  end_log_pos 429 CRC32 XXX 	GTID 0-1-16
+#<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 POS
-# at 543
+# at POS
-#<date> server id 1  end_log_pos 543 CRC32 XXX 	Annotate_rows:
+#<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
+#<date> server id 1  end_log_pos END_LOG_POS CRC32 XXX 	Table_map: `test`.`t1` mapped to number TID
-# at 594
+# at POS
-#<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 	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
+# at POS
-#<date> server id 1  end_log_pos 725 CRC32 XXX 	Query	thread_id=5	exec_time=x	error_code=0
+#<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 */;

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/*!*/;

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 --verbose --debug-binlog-row-event-max-encoded-size=256 $MYSQLD_DATADIR/master-bin.000001 > $MYSQLTEST_VARDIR/tmp/mysqlbinlog.sql
---exec $MYSQL_BINLOG -vv --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

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/*!*/;

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=#/
+--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
+--exec $MYSQL_BINLOG --verbose --verbose --base64-output=DECODE-ROWS $datadir/$binlog --start-position=$binlog_pos --stop-position=$binlog_end
 
 DROP TABLE t1,t2;
 

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)
-      {
+        ev->print_verbose(&print_event_info->tail_cache, print_event_info);
-        /*
-          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);
-      }
 #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

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;

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