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.

Author: andrelkin

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;
     }
   }

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,34 +369,34 @@ 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 */
 ### SET
 ###   @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 */;

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;
 

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.

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

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

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

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,8 +12012,7 @@ 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_delim, delimiter);
 
     my_fprintf(file, fmt_binlog2, delimiter);
   }
@@ -12035,8 +12021,7 @@ 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);
+    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

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

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 &&
@@ -1867,8 +1868,9 @@ 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->delimiter,
+                                   print_event_info->verbose) ||
+        copy_event_cache_to_file_and_reinit(tail, file))
       goto err;
   }
   return 0;