MySQL Bugs: #34141: mysqlbinlog cannot read 4.1 binlogs containing load data infile

Bug #34141	mysqlbinlog cannot read 4.1 binlogs containing load data infile
Submitted:	29 Jan 2008 18:36	Modified:	16 Feb 2008 12:16
Reporter:	Sven Sandberg
Status:	Closed
Category:	Server: Replication	Severity:	S3 (Non-critical)
Version:	5.1	OS:	Any
Assigned to:	Sven Sandberg	Target Version:
Tags:	create_file_log_event, LOAD DATA INFILE, mysqlbinlog

Description:
When a 4.1 server logs a "LOAD DATA INFILE" query, it generates a Create_file_log_event.
mysqlbinlog fails to read such events: either it produces an error message or it produces
invalid output. I have seen the bug is in 5.1 but not in 5.0.

How to repeat:
Create a binlog using 4.1 that includes a "LOAD DATA INFILE" query.
Read the binlog using 5.1.

The first 4.1 binlog attached was generated as follows:

  use test;
  create table t1 (a int);
  load data local infile 'tmp1' into table t1;

where tmp1 is a file contains the single character '1'. When mysqlbinlog from 5.1 reads
this binlog, it produces the error message "ERROR: Error in Log_event::read_log_event():
'Found invalid event in binary log', data_len: 67, event_type: 8"

The second 4.1 binlog attached was generated as follows:

  use test;
  create table t1 (a int, b int);
  load data infile 'tmp2' into table t1;

where tmp2 is a file containing four lines:

1 2
3 4
5 6
7 8

(the numbers on each line are separated by tabs).

When mysqlbinlog from 5.1 reads this binlog, it produces bad output. More precisely, it
inserts a newline in a comment, such that the tail of a commented line ends up on a line
of its own, causing a syntax error when the output is piped to a client:

# at 144 (0x90)
#080129 18:17:00 server id 1  end_log_pos 228   Query   thread_id=1     exec_time=0
# LOAD DATA INFILE '' INTO TABLE `` FIELDS TERMINATED BY '\t' ENCLOSED BY '' ESCAPED BY
'\\' LINES TERMINATED BY '\n' STARTING BY '' (\1\n,b)/*!*/;
# file_id: 1  block_len: 12

(I have replaced ascii 1 and a newline by the escaped form, \1\n)

first binlog

Attachment: binlog-4.1-load-minimal.000001 (application/octet-stream, text), 227 bytes.

second binlog

Attachment: binlog-4.1-load-small.000001 (application/octet-stream, text), 251 bytes.

The reason for the bug is in sql_ex_info::init, in the branch where "if (use_new_format)"
evaluates to true. Here, it takes a copy of the buf pointer before reading from it. The
read_str() function updates this pointer (sets it to the end of the string it read).
Then, the buf pointer is incremented and returned, but it should really be the ptr
pointer that should be incremented and returned.

In 5.0, we did not take a copy of the buf pointer. Taking a copy of the buf pointer was
probably introduced (erroneously) when the const attribute was added to the first
parameter of read_str(). ptr was added so that we could write &ptr instead of the longer
(const char**)&buf.

A working solution is to copy ptr back to buf before reading opt_flags.

A better solution is to get rid of ptr, and add the const attribute to the buf parameter
in sql_ex_info::init(). Since sql_ex_info::init() does not modify the contents of the buf
string, the buf string should be const. A few other strings need to be made const as a
consequence. Each of these should really be const. See the patch soon to be committed.

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/41376

ChangeSet@1.2660, 2008-01-29 20:18:14+01:00, sven@riska.(none) +2 -0
  BUG#34141: mysqlbinlog cannot read 4.1 binlogs containing load data infile
  Problem: mysql 5.1 cannot read binlogs from 4.1.
  The reason is a mistake in sql_ex_info::init. The read_str() function
  updates its first argument to point to the next character to read.
  However, it is applied only to a copy of the buffer pointer, so the real
  buffer pointer is not updated.
  Fix: do not take a copy of the buffer pointer. The copy was needed because
  sql_ex_info::init does not use the const attribute on some of its
  arguments. So we add the const attribute, too.

Another problem prevents 4.1 binlogs to be read by mysqlbinlog and piped to a client:
since the fix of BUG#32407, the server asserts that the first BINLOG statement seen is a
FORMAT_DESCRIPTION_EVENT, so that we know how to read future BINLOG statements (in
sql_binlog.cc, function mysql_client_binlog_statement, where it generates an
ER_NO_FORMAT_DESCRIPTION_EVENT_BEFORE_BINLOG_STATEMENT error).

However, 4.1 binlogs use START_EVENT_V3 instead of FORMAT_DESCRIPTION_EVENT. The solution
is to check for START_EVENT_V3 too.

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/41422

ChangeSet@1.2678, 2008-01-30 14:12:40+01:00, sven@riska.(none) +6 -0
  BUG#34141: mysqlbinlog cannot read 4.1 binlogs containing load data infile
  Main problem: mysql 5.1 cannot read binlogs from 4.1.
  Subproblem 1: There is a mistake in sql_ex_info::init. The read_str()
  function updates its first argument to point to the next character to
  read. However, it is applied only to a copy of the buffer pointer, so the
  real buffer pointer is not updated.
  Fix 1: do not take a copy of the buffer pointer. The copy was needed
  because sql_ex_info::init does not use the const attribute on some of its
  arguments. So we add the const attribute, too.
  Subproblem 2: The first BINLOG statement is asserted to be a
  FORMAT_DESCRIPTION_LOG_EVENT, but 4.1 binlogs begin with START_EVENT_V3.
  Fix 2: allow START_EVENT_V3 too.

Pushed into 5.1.24-rc

Pushed into 6.0.5-alpha

Documented in the 5.1.24 and 6.0.5 changelogs as follows:

        mysqlbinlog from a 5.1 or later MySQL distribution could not
        read binary logs generated by a 4.1 server when the logs contained 
        LOAD DATA INFILE statements.

Also noted fix in the 5.1.23-ndb-6.2.14 and 5.1.23-ndb-6.3.11 changelogs.