MySQL Bugs: #43509: Assertion failed: ! is_set() when replaying binlog file with row based events

Bug #43509	Assertion failed: ! is_set() when replaying binlog file with row based events
Submitted:	9 Mar 2009 20:19	Modified:	28 Apr 2009 8:35
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Row Based Replication ( RBR )	Severity:	S3 (Non-critical)
Version:	5.1.32-debug, 5.1, 6.0 bzr	OS:	Any (MS Windows, Linux)
Assigned to:		CPU Architecture:	Any
Tags:	crash, pushbuild, sporadic, test failure

Description:
Version: '5.1.32-debug-log'  socket: ''  port: 3306  Source distribution
Assertion failed: ! is_set(), file .\sql_class.cc, line 436

0057DC43    mysqld.exe!my_sigabrt_handler()[mysqld.cc:1982]
00A00FE9    mysqld.exe!raise()[winsig.c:590]
009FA0D3    mysqld.exe!abort()[abort.c:71]
009F450F    mysqld.exe!_wassert()[assert.c:212]
00651041    mysqld.exe!Diagnostics_area::set_ok_status()[sql_class.cc:436]
005C1D89    mysqld.exe!my_ok()[sql_class.h:2254]
0078AB78    mysqld.exe!mysql_client_binlog_statement()[sql_binlog.cc:238]
00699178    mysqld.exe!mysql_execute_command()[sql_parse.cc:4744]
0069C8C7    mysqld.exe!mysql_parse()[sql_parse.cc:5810]
00690E7E    mysqld.exe!dispatch_command()[sql_parse.cc:1216]
006904F4    mysqld.exe!do_command()[sql_parse.cc:857]
007AEC06    mysqld.exe!handle_one_connection()[sql_connect.cc:1115]
008813E6    mysqld.exe!pthread_start()[my_winthread.c:85]
00A02FC1    mysqld.exe!_callthreadstart()[thread.c:293]
00A02F67    mysqld.exe!_threadstart()[thread.c:277]
7D4DFFF1    kernel32.dll!FlsSetValue()
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 00000000=(null)

How to repeat:
Run this against a debug binary:

BINLOG 'smy1SQ8BAAAAZgAAAGoAAAABAAQANS4xLjMyLWVudGVycHJpc2UtZ3BsLWFkdmFuY2VkLWRlYnVn
LWxvZwAAAAAAAAAAAACybLVJEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC';

BINLOG 'y2y1SQIBAAAAXgAAAMgAAAAQAAUAAAAAAAAABAAAGgAAAEAAAAEAAAAAAAAAAAYDc3RkBAgACAAI
AHRlc3QAZHJvcCB0YWJsZSBpZiBleGlzdHMgYHRhYmxlMzg1YA==';

I have the original binlog these statements came from, in case you need it.

Thank you for the report.

Verified as described.

Backtrace on Linux:

Thread 1 (process 19613):
#0  0x002ce402 in __kernel_vsyscall ()
#1  0x0046264f in pthread_kill () from /lib/libpthread.so.0
#2  0x085a3775 in my_write_core (sig=6) at stacktrace.c:310
#3  0x0824c139 in handle_segfault (sig=6) at mysqld.cc:2505
#4  <signal handler called>
#5  0x002ce402 in __kernel_vsyscall ()
#6  0x00314f90 in raise () from /lib/libc.so.6
#7  0x00316678 in abort () from /lib/libc.so.6
#8  0x0030e269 in __assert_fail () from /lib/libc.so.6
#9  0x08232681 in Diagnostics_area::set_ok_status (this=0x9e00b6c, thd=0x9dffdc0, affected_rows_arg=0, last_insert_id_arg=0, message_arg=0x0) at sql_class.cc:436
#10 0x08174c4f in my_ok (thd=0x9dffdc0, affected_rows=0, id=0, message=0x0) at sql_class.h:2253
#11 0x0843e2e1 in mysql_client_binlog_statement (thd=0x9dffdc0) at sql_binlog.cc:238
#12 0x08269ba3 in mysql_execute_command (thd=0x9dffdc0) at sql_parse.cc:4744
#13 0x0826a85e in mysql_parse (thd=0x9dffdc0, inBuf=0x9e610a8 '\217' <repeats 200 times>..., length=137, found_semicolon=0xb74912fc) at sql_parse.cc:5810
#14 0x0826b49a in dispatch_command (command=COM_QUERY, thd=0x9dffdc0, 
    packet=0x9e4e189 "BINLOG 'y2y1SQIBAAAAXgAAAMgAAAAQAAUAAAAAAAAABAAAGgAAAEAAAAE", 'A' <repeats 11 times>, "YDc3RkBAgACAAIAHRlc3QAZHJvcCB0YWJsZSBpZiBleGlzdHMgYHRhYmxlMzg1YA=='", packet_length=137)
    at sql_parse.cc:1216
#15 0x0826c6b8 in do_command (thd=0x9dffdc0) at sql_parse.cc:857
#16 0x08259315 in handle_one_connection (arg=0x9dffdc0) at sql_connect.cc:1115
#17 0x0045fbd4 in start_thread () from /lib/libpthread.so.0
#18 0x003b74fe in clone () from /lib/libc.so.6

Hi Shane,

How can I reproduce the sequence below?

BINLOG 'smy1SQ8BAAAAZgAAAGoAAAABAAQANS4xLjMyLWVudGVycHJpc2UtZ3BsLWFkdmFuY2VkLWRlYnVn
LWxvZwAAAAAAAAAAAACybLVJEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC';

BINLOG 'y2y1SQIBAAAAXgAAAMgAAAAQAAUAAAAAAAAABAAAGgAAAEAAAAEAAAAAAAAAAAYDc3RkBAgACAAI
AHRlc3QAZHJvcCB0YWJsZSBpZiBleGlzdHMgYHRhYmxlMzg1YA==';

Cheers.

I lost original binlog and sql.  It was some operation against a non-existant table, `table385`.  I'll try make another testcase then.

Alfranio, I checked in the debugger what this query is.

The first BINLOG is of course the needed binlog description thing (i.e first binlog command in each binlog).

The second BINLOG command is this:  "drop table if exists `table385`"

Found by putting a breakpoint in
Query_log_event::Query_log_event at this lines:

db= (char *)start;
query= (char *)(start + db_len + 1);
q_len= data_len - db_len -1;

This is why a release binary prints out the *warning* about table not found.
The big question now is, why was this statement encoded like this?  I dunno.

See also bug #44520