MySQL Bugs: #26194: mysqlbinlog --base64-output produces invalid SQL

Bug #26194	mysqlbinlog --base64-output produces invalid SQL
Submitted:	8 Feb 2007 20:18	Modified:	4 Apr 2007 4:18
Reporter:	Guilhem Bichot	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	5.1-bk	OS:	Linux (linux)
Assigned to:	Guilhem Bichot	CPU Architecture:	Any

Description:
Extracted from BUG#20929, so that BUG#20929 is really about "invalid free in the server", while this bug is in mysqlbinlog.
A certain sequence of commands run on the server causes "mysqlbinlog --base64-output" (available in 5.1 only) to produce output which cannot be parsed  by the server.

How to repeat:
Start mysqld in the default binlogging mode (i.e. mixed). Do:
RESET MASTER;
CREATE DATABASE mydb;
USE mydb;
CREATE TABLE t (a DATETIME);
INSERT INTO t VALUES(NOW());
DROP DATABASE mydb;
FLUSH LOGS;
then run mysqlbinlog --base64-output on the log containing the commands (the one which has been closed by the FLUSH LOGS): you can see it starts like this:
# at 102
#728 21:56:17 server id 1  end_log_pos 185 cY7LRQIBAAAAUwAAALkAAAAIAAEAAAAAAAAAB
AAAGgAAAEAAAAEAAAAAAAAAAAYDc3RkBAgACAAI
AG15ZGIAQ1JFQVRFIERBVEFCQVNFIG15ZGI=
'/*!*/;
# at 185

When piped into "mysql", the syntax error being due of course to the absence of the keyword "BINLOG" at the start;
cY7LRQIBAAAAUwAAALkAAAAIAAEAAAAAAAAAB
AAAGgAAAEAAAAEAAAAAAAAAAAYDc3RkBAgACAAI
AG15ZGIAQ1JFQVRFIERBVEFCQVNFIG15ZGI=
is not a valid SQL command ;)

Suggested fix:
extracted from BUG#20929:
The syntax error is due to the fact that the BINLOG keyword is not printed
anymore in the mysqlbinlog dump; we get only base64 codes. No wonder it's a
syntax error.
It's not seen in the testsuite because the "mysqlbinlog_base64" test only tests
the --hexdump option, not the --base64-output option, in spite of its name.
The reason why BINLOG disappeared is that, for example for Query_log_event, this
is called:
static int
write_event_header_and_base64(Log_event *ev, FILE *result_file,
                              PRINT_EVENT_INFO *print_event_info)
which calls ev->print_header() and ev->print_base64() with the same IO_CACHE in
argument. First print_header() runs and prints comments (#...) into the
IO_CACHE. So when ev->print_base64() executes, the IO_CACHE is not empty, so
this code:
  if (my_b_tell(file) == 0)
    my_b_printf(file, "\nBINLOG '\n");
has the effect that "BINLOG" is not printed.
A (quick?) fix is using the two available separate IO_CACHEs:
--- 1.141/client/mysqlbinlog.cc 2007-01-24 22:10:33 +01:00
+++ edited/../client/mysqlbinlog.cc     2007-01-24 21:53:57 +01:00
@@ -485,21 +485,20 @@ static int
 write_event_header_and_base64(Log_event *ev, FILE *result_file,
                               PRINT_EVENT_INFO *print_event_info)
 {
+  IO_CACHE *head= &print_event_info->head_cache;
+  IO_CACHE *body= &print_event_info->body_cache;
   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)))
-  {
-    return 1;
-  }

-  ev->print_header(&result_cache, print_event_info, FALSE);
-  ev->print_base64(&result_cache, print_event_info, FALSE);
+  ev->print_header(head, print_event_info, FALSE);
+  ev->print_base64(body, 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);
+  my_b_copy_to_file(head, result_file);
+  my_b_copy_to_file(body, result_file);
+  reinit_io_cache(head, WRITE_CACHE, 0, FALSE, TRUE);
+  reinit_io_cache(body, WRITE_CACHE, 0, FALSE, TRUE);
+
   DBUG_RETURN(0);
 }                    

And after that, the BINLOG word is printed again, no syntax error.

adding Mats as he knows this code best

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/19618

ChangeSet@1.2373, 2007-02-09 16:16:01+01:00, guilhem@gbichot3.local +5 -0
  Fix for BUG#26194 "mysqlbinlog --base64-output produces invalid SQL";
  when it was printing a Query event, it produced invalid SQL (missing
  the BINLOG keyword, so the SQL started with the base64 string, which
  is incorrect).
  Note: the .test will NOT be pushed; indeed, it triggers BUG#20929
  ("BINLOG command causes invalid free") and so gives Valgrind warnings
  or crashes mysqld. Instead, I'll ship this test to the fixer of
  BUG#20929 for her/him to push when she/he fixes BUG#20929.

Patch works as described. Tested on Windows XP.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/22596

ChangeSet@1.2373, 2007-03-22 11:24:27+01:00, guilhem@gbichot3.local +3 -0
  Fix for BUG#26194 "mysqlbinlog --base64-output produces invalid SQL";
  when it was printing a Query event, it produced invalid SQL (missing
  the BINLOG keyword, so the SQL started with the base64 string, which
  is incorrect).
  Note: no testcase; I have a .test which shows that the bugfix works,
  but it triggers BUG#26361 and so gives Valgrind warnings. I'm sending
  this test to the fixer of BUG#26361 for her/him to push when she/he
  fixes BUG#26361.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/22660

ChangeSet@1.2479, 2007-03-22 17:31:39+01:00, guilhem@gbichot3.local +4 -0
  Fix for BUG#26194 "mysqlbinlog --base64-output produces invalid SQL";
  when it was printing a Query event, it produced invalid SQL (missing
  the BINLOG keyword, so the SQL started with the base64 string, which
  is incorrect).
  Note: no testcase; I have a .test which shows that the bugfix works,
  but it triggers BUG#26361 and so gives Valgrind warnings. I'm sending
  this test to the fixer of BUG#26361 for her/him to push when she/he
  fixes BUG#26361.

pushed to 5.1-rpl

Pushed into 5.1.18-beta

Noted in 5.1.18 changelog.