Fix for BUG#25628: "mysqlbinlog crashes while processing binary logs".

mysqlbinlog prints all row-based events of a single statement as a
single "BINLOG" statement containing the concatenation of those events.
Big (i.e. >64k) concatenations of row-based events
(e.g. Write_rows_log_event) caused mysqlbinlog's IO_CACHE to overflow
to a temporary file but the IO_CACHE had not been inited with
open_cached_file(), so it tried to create a temporary file in
an uninitialized directory (thus failing to create, then to write;
some OS errors were printed, and it finally segfaulted).
After fixing this, it appeared that mysqlbinlog was printing only
a piece of big concatenations of row-based events (it printed
at most the size of the IO_CACHE's buffer i.e. 64k); that caused data
loss at restore. We fix and test that.
Last, mysqlbinlog's printouts looked a bit strange with the informative
header (#-prefixed) of groupped Rows_log_event all on one line,
so we insert \n. After that, a small bug in the --hexdump code appeared
(only if the string to hex-print had its length a multiple of 16),
we fix it.



client/mysqlbinlog.cc:
  if we write to IO_CACHE more than can fit into its memory buffer,
  it will try to overflow into a file; for that to work, IO_CACHE
  must be inited via open_cached_file().
mysql-test/r/mysqlbinlog_base64.result:
  result update
mysql-test/t/mysqlbinlog_base64.test:
  test for BUG#25628: test that mysqlbinlog does not have OS errors
  with big concatenations of row-based events
  (e.g. Write_rows_log_event), and prints those concatenations entirely
  (testing by piping the output back into the server and comparing data).
mysys/mf_iocache2.c:
  my_b_copy_to_file() had a problem: it assumed that bytes_in_cache
  are all the bytes to copy to the file, while it only tells how many
  bytes are in the buffer; so the code forgot to copy what had already
  overflown into a temporary file. Thus any big event was printed only
  partially by mysqlbinlog (loss of data at restore). The fix is
  inspired by MYSQL_BIN_LOG::write_cache().
sql/log_event.cc:
  Several Table_map/Write_rows events generated by one single statement
  get groupped together in mysqlbinlog's output; it printed things like
  #718 7:30:51 server id 12 end_log_pos 988      Write_rows: table id 17#718 7:30:51 server id 12 #718 7:30:51 server id 12  end_log_pos 988      Write_rows: table id 17#718 7:30:51 server id 12 end_log_pos 1413 <cut>
  It didn't look nice to have printouts glued like this without line
  breaks. Adding a line break.
  Doing this, when using --hexdump the result was:
  #718 7:30:51 server id 12 end_log_pos 988
  # <hexdump output>
  # Write_rows: table id 17
  which is correct; unfortunately if the hex dump had only full lines
  (i.e the string to print in hex had its length a multiple of 16),
  then the # in front of Write_rows was not printed. Fixed.
sql/log_event.h:
  removing strcpy() (one less function call).
  If we write to IO_CACHE more than can fit into its memory buffer,
  it will try to overflow into a file; for that to work, IO_CACHE
  must be inited via open_cached_file().
  open_cached_file(), like init_io_cache(), can fail; we make sure to
  catch this constructor's problem via the init_ok() method.

client/mysqlbinlog.cc

@@ -487,18 +487,15 @@ write_event_header_and_base64(Log_event *ev, FILE *result_file,
   DBUG_ENTER("write_event_header_and_base64");
   /* Write header and base64 output to cache */
   IO_CACHE result_cache;
-  if (init_io_cache(&result_cache, -1, 0, WRITE_CACHE, 0L, FALSE,
-                    MYF(MY_WME | MY_NABP)))
-  {
+  if (open_cached_file(&result_cache, NULL, NULL, 0, MYF(MY_WME | MY_NABP)))
     return 1;
-  }
 
   ev->print_header(&result_cache, print_event_info, FALSE);
   ev->print_base64(&result_cache, print_event_info, FALSE);
 
   /* Read data from cache and write to result file */
   my_b_copy_to_file(&result_cache, result_file);
-  end_io_cache(&result_cache);
+  close_cached_file(&result_cache);
   DBUG_RETURN(0);
 }
 
@@ -1016,6 +1013,9 @@ static int dump_log_entries(const char* logname)
 {
   int rc;
   PRINT_EVENT_INFO print_event_info;
+
+  if (!print_event_info.init_ok())
+    return 1;
   /*
      Set safe delimiter, to dump things
      like CREATE PROCEDURE safely

mysql-test/r/mysqlbinlog_base64.result

@@ -86,5 +86,25 @@ Aberdeen
 Abernathy
 aberrant
 aberration
+flush logs;
+drop table t2;
+create table t2 (word varchar(20));
+load data infile '../std_data_ln/words.dat' into table t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+select count(*) from t2;
+count(*)
+35840
+flush logs;
+select count(*) from t2;
+count(*)
+35840
 drop table t1;
 drop table t2;

mysql-test/t/mysqlbinlog_base64.test

@@ -31,6 +31,34 @@ drop table t2;
 select * from t1;
 select * from t2;
 
+#
+#  Verify that events larger than the default IO_CACHE buffer
+#  are handled correctly (BUG#25628).
+#
+flush logs;
+drop table t2;
+create table t2 (word varchar(20));
+load data infile '../std_data_ln/words.dat' into table t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+insert into t2 select * from t2;
+select count(*) from t2;
+
+flush logs;
+--exec $MYSQL_BINLOG --hexdump $MYSQLTEST_VARDIR/log/master-bin.000003 > $MYSQLTEST_VARDIR/tmp/mysqlbinlog_base64.sql
+--exec $MYSQL test < $MYSQLTEST_VARDIR/tmp/mysqlbinlog_base64.sql
+
+#
+#  Verify that all binlog events have been executed
+#
+select count(*) from t2;
+
 #
 #  Test cleanup
 #

mysys/mf_iocache2.c

@@ -50,7 +50,6 @@
 int
 my_b_copy_to_file(IO_CACHE *cache, FILE *file)
 {
-  byte buf[IO_SIZE];
   uint bytes_in_cache;
   DBUG_ENTER("my_b_copy_to_file");
 
@@ -58,19 +57,17 @@ my_b_copy_to_file(IO_CACHE *cache, FILE *file)
   if (reinit_io_cache(cache, READ_CACHE, 0L, FALSE, FALSE))
     DBUG_RETURN(1);
   bytes_in_cache= my_b_bytes_in_cache(cache);
-  while (bytes_in_cache > 0) {
-    uint const read_bytes= min(bytes_in_cache, sizeof(buf));
-    DBUG_PRINT("debug", ("Remaining %u bytes - Reading %u bytes",
-                         bytes_in_cache, read_bytes));
-    if (my_b_read(cache, buf, read_bytes))
-      DBUG_RETURN(1);
-    if (my_fwrite(file, buf, read_bytes, MYF(MY_WME | MY_NABP)) == (uint) -1)
+  do
+  {
+    if (my_fwrite(file, cache->read_pos, bytes_in_cache,
+                  MYF(MY_WME | MY_NABP)) == (uint) -1)
       DBUG_RETURN(1);
-    bytes_in_cache -= read_bytes;
-  }
+    cache->read_pos= cache->read_end;
+  } while ((bytes_in_cache= my_b_fill(cache)));
   DBUG_RETURN(0);
 }
 
+
 my_off_t my_b_append_tell(IO_CACHE* info)
 {
   /*

sql/log_event.cc

@@ -1144,13 +1144,18 @@ void Log_event::print_header(IO_CACHE* file,
       char emit_buf[256];
       int const bytes_written=
         my_snprintf(emit_buf, sizeof(emit_buf),
-                    "# %8.8lx %-48.48s |%s|\n# ",
+                    "# %8.8lx %-48.48s |%s|\n",
                     (unsigned long) (hexdump_from + (i & 0xfffffff0)),
                     hex_string, char_string);
       DBUG_ASSERT(bytes_written >= 0);
       DBUG_ASSERT(static_cast<my_size_t>(bytes_written) < sizeof(emit_buf));
       my_b_write(file, (byte*) emit_buf, bytes_written);
     }
+    /*
+      need a # to prefix the rest of printouts for example those of
+      Rows_log_event::print_helper().
+    */
+    my_b_write(file, "# ", 2);
   }
   DBUG_VOID_RETURN;
 }
@@ -6106,7 +6111,7 @@ void Rows_log_event::print_helper(FILE *file,
   {
     bool const last_stmt_event= get_flags(STMT_END_F);
     print_header(head, print_event_info, !last_stmt_event);
-    my_b_printf(head, "\t%s: table id %lu", name, m_table_id);
+    my_b_printf(head, "\t%s: table id %lu\n", name, m_table_id);
     print_base64(body, print_event_info, !last_stmt_event);
   }
 

sql/log_event.h

@@ -546,16 +546,19 @@ typedef struct st_print_event_info
       bzero(db, sizeof(db));
       bzero(charset, sizeof(charset));
       bzero(time_zone_str, sizeof(time_zone_str));
-      strcpy(delimiter, ";");
-      uint const flags = MYF(MY_WME | MY_NABP);
-      init_io_cache(&head_cache, -1, 0, WRITE_CACHE, 0L, FALSE, flags);
-      init_io_cache(&body_cache, -1, 0, WRITE_CACHE, 0L, FALSE, flags);
+      delimiter[0]= ';';
+      delimiter[1]= 0;
+      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);
     }
 
   ~st_print_event_info() {
-    end_io_cache(&head_cache);
-    end_io_cache(&body_cache);
+    close_cached_file(&head_cache);
+    close_cached_file(&body_cache);
   }
+  bool init_ok() /* tells if construction was successful */
+    { return my_b_inited(&head_cache) && my_b_inited(&body_cache); }
 
 
   /* Settings on how to print the events */