Bug #54197 'BINLOG ' statements crash the server
Submitted: 3 Jun 2010 9:20 Modified: 10 Sep 2010 12:09
Reporter: Libing Song Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.1, 5.5 OS:Any
Assigned to: Luis Soares CPU Architecture:Any
Tags: mysql-5.1-bugteam, mysql-trunk-merge

[3 Jun 2010 9:20] Libing Song
Description:
BINLOG statements crash the server.

How to repeat:
1. Use the following statements to create a binary log file.
   source include/have_binlog_format_statement.inc;
   CREATE TABLE t1(c1 INT) ENGINE=myisam;
   FLUSH LOGS;
   INSERT INTO t1 VALUES(1),(2);
   SHOW BINLOG EVENTS;

2. Use mysqlbinlog to export SQL statements.
   ../client/mysqlbinlog --base64-output master-bin.000001 > a.sql

3. Execute a.sql
   --exec $MYSQL test < $MYSQLTEST_VARDIR/std_data/d.sql

Error information
------------------------------------------------------------------
#0  __pthread_kill (threadid=<value optimized out>, signo=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
#1  0x0000000000b70e57 in my_write_core (sig=6) at stacktrace.c:329
#2  0x00000000006c6040 in handle_segfault (sig=6) at mysqld.cc:2571
#3  <signal handler called>
#4  0x00007f035b5eba75 in *__GI_raise (sig=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#5  0x00007f035b5ef5c0 in *__GI_abort () at abort.c:92
#6  0x00007f035b5e4941 in *__GI___assert_fail (assertion=0xc71753 "! is_set()", file=<value optimized out>, line=499, 
    function=0xc72e80 "void Diagnostics_area::set_ok_status(THD*, ha_rows, ulonglong, const char*)") at assert.c:81
#7  0x00000000006a74ed in Diagnostics_area::set_ok_status (this=0x2993e50, thd=0x2992798, affected_rows_arg=0, last_insert_id_arg=0, message_arg=0x0)
    at sql_class.cc:499
#8  0x00000000005d021c in my_ok (thd=0x2992798, affected_rows=0, id=0, message=0x0) at sql_class.h:2366
#9  0x00000000008ff500 in mysql_client_binlog_statement (thd=0x2992798) at sql_binlog.cc:241
#10 0x00000000006e14be in mysql_execute_command (thd=0x2992798) at sql_parse.cc:4909
#11 0x00000000006e43b5 in mysql_parse (thd=0x2992798, 
    inBuf=0x297bee3 "\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217\217"..., length=136, found_semicolon=0x7f035c6c2960) at sql_parse.cc:5994
#12 0x00000000006d68ba in dispatch_command (command=COM_QUERY, thd=0x2992798, packet=0x2973e39 "", packet_length=163) at sql_parse.cc:1280
[3 Jun 2010 10:31] Sveta Smirnova
Thank you for the report.

Verified as described. Option --base64-output is required to get the crash.

Corrected test case:

--source include/have_log_bin.inc

CREATE TABLE t1(c1 INT) ENGINE=myisam;
FLUSH LOGS;
INSERT INTO t1 VALUES(1),(2);
SHOW BINLOG EVENTS;

--let $MYSQLD_DATADIR=`select @@datadir`
--exec $MYSQL_BINLOG --base64-output $MYSQLD_DATADIR/master-bin.000001 > $MYSQL_TEST_DIR/var/tmp/a.sql
drop table t1;
--exec $MYSQL test < $MYSQL_TEST_DIR/var/tmp/a.sql
[21 Jun 2010 0:07] Bugs System
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/111647

3423 Luis Soares	2010-06-21
      BUG#54197: 'BINLOG ' statements crash the server
      
      Some BINLOG statements would make the server hit an assertion,
      because they would lead to setting thd->main_da.m_status
      twice. This was caused because the execution of some BINLOG
      statements (in base 64 output) make my_ok to be called before
      returning from ev->apply_event. Then, my_ok would be called
      again, right before returning from mysql_client_binlog_statement,
      triggering the assertion.
      
      We fix this by:
      
      1. moving the call to my_ok from inside
         mysql_client_binlog_statement function, to
         mysql_execute_command
      
      2. changing the signature of mysql_client_binlog_statement so
         that it returns non-zero on error and zero otherwise.
      
      3. calling my_ok in mysql_execute_command conditionally, ie, if
         the status hasn't been set yet.
[10 Sep 2010 12:09] Luis Soares
Closing as can't repeat.

I was instructed to push this patch to mysql-next-mr-bugfixing.

So I cloned mysql-next-mr-bugfixing (revid:
tor.didriksen@oracle.com-20100910091236-9nyb8u0bybm0o4ql) and run
the test case on it. Instead of a crash, I got:

ERROR 1700 (HY000) at line 13: Only Format_description_log_event
and row events are allowed in BINLOG statements (but Query was
provided)

I searched around and found out that this was fixed by
WL#344 (BUG#28760) cset, which restricted the use of BINLOG
events:

 "- Added check that BINLOG statements only contain row events
    and Format_description_log_events. This avoids possible
    strange side effects and deadlocks that might happen if users
    feed strange events like rotate event to the BINLOG command." [1]

As such, this is already fixed in mysql-next-mr.

REFERENCES
==========

[1] http://lists.mysql.com/commits/108757