Bug #28293 mysqlbinlog: corrupt SQL in hex dump mode [PATCH INCLUDED]

Description:
When playing back logs using mysqlbinlog with the -H flag, a particular type of output line is occasionally missing the '#' comment mark, which makes re-importing the output fail.

How to repeat:
mysqlbinlog -H <binlog file> | mysql <arguments>

ERROR 1064 (42000) at line 267: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'Query    thread_id=<int>  exec_time=0     error_code=0...

If you do this:

mysqlbinlog -H <binlog file> | grep 'Query'

Every so often, you'll notice that a line is missing the starting '#' mark, which should be there.

Suggested fix:
A trivial (2-line) patch to sql/log_event.cc.

I will attach the patch.

Patch for sql/log_event.cc. A possible fixe for this bug.

Attachment: sql_log_event_cc.patch (application/octet-stream, text), 362 bytes.

Thank you for a problem report. Please, send/upload a binary log that demonstrates this problem.

The problem is simple. It will be immediately obvious to you once you look at the code.

mysql-5.0.37/sql/log_event.cc, several Log_event*::print methods call these two lines in succession:

    print_header(file,...);
    fprintf(file,"\t<some string>"); <-- these strings vary a little from method to method, but *always* require the print_header method to print a leading comment ("#") character.

For example mysql-5.0.37/sql/log_event.cc, Load_log_event::print, line 2748:

    print_header(file, print_event_info);
    fprintf(file, "\tQuery\tthread_id=%ld\texec_time=%ld\n",
        thread_id, exec_time);

The bug is that print_header does not print the required leading "#" when in hexdump mode and when the last output line is exactly 16 bytes long.

In mysql-5.0.37/sql/log_event.cc, Log_event::print_header:

When not in hexdump mode, the bug doesn't occur. It simply prints this string: "# server id %d end_log_pos %s" without a newline then exits, so the output line following the print_header call can print (the line already has a "#").

When in hexdump mode, the bug occurs easily. It loops through the data, and prints it in hex. Each hex line is terminated with a "\n".

If the data is not 16 bytes long, it prints the remaining data terminated with "\n# ". If the data is exactly 16 bytes long, it does not print the terminating "# ".

Hence, the simple fix - add this in mysql-5.0.37/sql/log_event.cc, line 989:

    else
        fprintf(file, "# ");

For the sake of completeness, I will attach two binlog files. One does not trigger the error (binlog-noerror), the other one does (binlog-error).

Use like this:

# mysqlbinlog -H binlog-error
# mysqlbinlog -H binlog-noerror

You will notice that the mysqlbinlog output of the binlog-noerror file will have a line like this:

#       Query   thread_id=2     exec_time=0     error_code=0

The mysqlbinlog output of the binlog-error file will have a line like this:

        Query   thread_id=2     exec_time=0     error_code=0

Because of the missing "#", the output cannot be directly processed by mysql client+server. ("\tQuery\tthread_id..." is not correct SQL :-)

Binary log that triggers this bug in hexdump mode.

Attachment: binlog-error (application/octet-stream, text), 349 bytes.

A binary log that does not trigger this bug.

Attachment: binlog-noerror (application/octet-stream, text), 348 bytes.

Sorry for a delay with this bug report. Verified just as described with your binary logs and mysqlbinlog from the latest 5.0.44-BK on Linux.

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

ChangeSet@1.2498, 2007-06-21 00:51:19+05:00, gshchepa@gleb.loc +3 -0
  Fixed bug #28293.
  Occasionally mysqlbinlog --hexdump failed with error:
    ERROR 1064 (42000) at line ...: You have an error in your
    SQL syntax; check the manual that corresponds to your MySQL
    server version for the right syntax to use near
    'Query thread_id=... exec_time=... error_code=...
  
  When the length of hexadecimal dump of binlog header was
  divisible by 16, commentary sign '#' after header was lost.
  The Log_event::print_header function has been modified to always
  finish hexadecimal binlog header with "\n# ".

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

ChangeSet@1.2498, 2007-06-21 02:11:28+05:00, gshchepa@gleb.loc +3 -0
  Fixed bug #28293.
  Occasionally mysqlbinlog --hexdump failed with error:
    ERROR 1064 (42000) at line ...: You have an error in your
    SQL syntax; check the manual that corresponds to your MySQL
    server version for the right syntax to use near
    'Query thread_id=... exec_time=... error_code=...
  
  When the length of hexadecimal dump of binlog header was
  divisible by 16, commentary sign '#' after header was lost.
  The Log_event::print_header function has been modified to always
  finish hexadecimal binlog header with "\n# ".

Pushed into 5.1.21-beta

Pushed into 5.0.46

Noted in 5.0.46, 5.1.21 changelogs.

mysqlbinlog --hexdump generated incorrect output due to omission
of the # comment character for some comment lines.