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

(This commit is exclusively for 10.1 branch, do not merge it to upper ones)

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,
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.

Extra: mysqlbinlog_row_minimal refined to not produce mutable numeric values into the result file.

client/mysqlbinlog.cc

@@ -860,7 +860,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;
 }
 
 
@@ -912,8 +913,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;
     }
   }

mysql-test/r/mysqlbinlog_row_minimal.result

@@ -295,6 +295,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 /### UPDATE `test`.`t1`/ in mysqlbinlog.sql
+FOUND /### 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',
@@ -319,28 +337,28 @@ FLUSH BINARY LOGS;
 /*!40019 SET @@session.max_insert_delayed_threads=0*/;
 /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
 DELIMITER /*!*/;
-# at 368
-#<date> server id 1  end_log_pos 406 	GTID 0-1-16
+# at POS
+#<date> server id 1  end_log_pos END_LOG_POS 	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 406
-#<date> server id 1  end_log_pos 453 	Table_map: `test`.`t1` mapped to number 34
-# at 453
-#<date> server id 1  end_log_pos 498 	Update_rows: table id 34 flags: STMT_END_F
+# at POS
+#<date> server id 1  end_log_pos END_LOG_POS 	Table_map: `test`.`t1` mapped to number TID
+# at POS
+#<date> server id 1  end_log_pos END_LOG_POS 	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 498
-#<date> server id 1  end_log_pos 576 	Query	thread_id=4	exec_time=x	error_code=0
+# at POS
+#<date> server id 1  end_log_pos END_LOG_POS 	Query	thread_id=TID	exec_time=x	error_code=0
 SET TIMESTAMP=X/*!*/;
-SET @@session.pseudo_thread_id=4/*!*/;
+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/*!*/;
 SET @@session.sql_mode=1342177280/*!*/;
 SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
@@ -350,8 +368,6 @@ SET @@session.lc_time_names=0/*!*/;
 SET @@session.collation_database=DEFAULT/*!*/;
 COMMIT
 /*!*/;
-# at 576
-#<date> server id 1  end_log_pos 620 	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

@@ -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/*!*/;
@@ -1117,7 +1116,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,7 +11,7 @@ SELECT a from t into @a;
 FLUSH LOGS;
 DELETE FROM t;
 
---exec $MYSQL_BINLOG --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

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,35 @@ 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 +93,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/
---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/ /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;
 

sql/log_event.cc

@@ -2865,10 +2865,10 @@ void Log_event::print_base64(IO_CACHE* file,
     default:
       break;
     }
-    
+
     if (ev)
     {
-      ev->print_verbose(file, print_event_info);
+      ev->print_verbose(&print_event_info->tail_cache, print_event_info);
       delete ev;
     }
   }
@@ -10671,6 +10671,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;
   bool do_print_encoded=
     print_event_info->base64_output_mode != BASE64_OUTPUT_DECODE_ROWS &&
     !print_event_info->short_form;
@@ -10694,6 +10695,11 @@ void Rows_log_event::print_helper(FILE *file,
     }
     copy_cache_to_file_wrapped(file, body, do_print_encoded,
                                print_event_info->delimiter);
+    if (copy_event_cache_to_file_and_reinit(tail, file))
+    {
+      tail->error= -1;
+      return;
+    }
   }
 }
 #endif
@@ -13220,6 +13226,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);
 }
 #endif
 

sql/log_event.h

@@ -781,9 +781,12 @@ 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);
   }
   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); }
 
 
   /* Settings on how to print the events */
@@ -811,6 +814,7 @@ typedef struct st_print_event_info
    */
   IO_CACHE head_cache;
   IO_CACHE body_cache;
+  IO_CACHE tail_cache;
 } PRINT_EVENT_INFO;
 #endif
 

sql/log_event_old.cc

@@ -1856,6 +1856,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;
@@ -1879,6 +1880,11 @@ void Old_rows_log_event::print_helper(FILE *file,
     }
     copy_cache_to_file_wrapped(file, body, do_print_encoded,
                                print_event_info->delimiter);
+    if (copy_event_cache_to_file_and_reinit(tail, file))
+    {
+      tail->error= -1;
+      return;
+    }
   }
 }
 #endif