MySQL Bugs: #34132: Crash when replaying binary log

Bug #34132	Crash when replaying binary log
Submitted:	29 Jan 2008 13:58	Modified:	5 Mar 2008 13:01
Reporter:	Philip Stoev	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S1 (Critical)
Version:	5.1-BK	OS:	Any
Assigned to:	Assigned Account	CPU Architecture:	Any
Tags:	simpler_testcase_needed

Description:
When running the rpl_sys systems test against Maria, the slave asserts like this:

mysqld: sql_base.cc:5143: int lock_tables(THD*, TABLE_LIST*, uint, bool*): Assertion `thd->lock == 0' failed on query:

INSERT INTO test.viewer_tbl1 VALUES (NULL,RAND() * 10, RAND() * 100);

Then, when restarting the slave and replaying the slave relay log, the server crashes with:

#1  0x00138037 in pthread_kill () from /lib/libpthread.so.0
#2  0x0832982b in write_core (sig=11) at stacktrace.c:240
#3  0x081cda44 in handle_segfault (sig=11) at mysqld.cc:2298
#4  <signal handler called>
#5  0x0829dc31 in unpack_row (rli=0xa1bd5e8, table=0xa31dbc8, colcnt=4, row_data=0xa2f7f48 "П\004", cols=0xa30b2f4, row_end=0xa30b358,
    master_reclength=0xa30b320) at rpl_utility.h:195
#6  0x0829b6b0 in Rows_log_event::write_row (this=0xa30b2c0, rli=0xa1bd5e8, overwrite=true) at log_event.h:3100
#7  0x0829bee7 in Write_rows_log_event::do_exec_row (this=0xa30b2c0, rli=0xa1bd5e8) at log_event.cc:7644
#8  0x08299c1a in Rows_log_event::do_apply_event (this=0xa30b2c0, rli=0xa1bd5e8) at log_event.cc:6424
#9  0x0836307a in mysql_client_binlog_statement (thd=0xa172488) at log_event.h:951
#10 0x081e3396 in mysql_execute_command (thd=0xa172488) at sql_parse.cc:4592
#11 0x081e4570 in mysql_parse (thd=0xa172488,
    inBuf=0xa1a6c90 "BINLOG '\nrSqfRxcBAAAAPAAAAPgDKQEAAB4AAAAAAAAABP/wBAAAdT/3REMSAAAOcm9vdEBsb2NhbGhvc3TJ\nuus+\nrSqfRxMBAAAAPQAAADUEKQEAABgAAAAAAAAABHRlc3QADHBpbnNkZWwyX3RibAAGCQf+/AkPBf7/\nBP8APA==\nrSqfRxkBAAAAewAAALAEKQE"..., length=345, found_semicolon=0xb20c52d4) at sql_parse.cc:5631
#12 0x081e52b6 in dispatch_command (command=COM_QUERY, thd=0xa172488,
    packet=0xa198181 "BINLOG '\nrSqfRxcBAAAAPAAAAPgDKQEAAB4AAAAAAAAABP/wBAAAdT/3REMSAAAOcm9vdEBsb2NhbGhvc3TJ\nuus+\nrSqfRxMBAAAAPQAAADUEKQEAABgAAAAAAAAABHRlc3QADHBpbnNkZWwyX3RibAAGCQf+/AkPBf7/\nBP8APA==\nrSqfRxkBAAAAewAAALAEKQE"..., packet_length=345) at sql_parse.cc:1129
#13 0x081e632f in do_command (thd=0xa172488) at sql_parse.cc:789
#14 0x081d5f24 in handle_one_connection (arg=0xa172488) at sql_connect.cc:1120
#15 0x0013344b in start_thread () from /lib/libpthread.so.0
#16 0x0037f80e in clone () from /lib/libc.so.6

How to repeat:
Replay the attached log against server. The log was converted from binary form into SQL using mysqlbinlog.

Just replaying the crashing binlog statement (after the table has been created) causes an assertion:

CREATE TABLE test.pinsdel2_tbl(id MEDIUMINT NOT NULL AUTO_INCREMENT, dt TIMESTAMP, user CHAR(255), uuidf LONGBLOB, fkid MEDIUMINT, filler VARCHAR(255), PRIMARY KEY(id))ENGINE=Maria PARTITION BY RANGE(id) SUBPARTITION BY hash(id) subpartitions 2 (PARTITION pa1 values less than (10), PARTITION pa2 values less than (20), PARTITION pa3 values less than (30), PARTITION pa4 values less than (40), PARTITION pa5 values less than (50), PARTITION pa6 values less than (60), PARTITION pa7 values less than (70), PARTITION pa8 values less than (80), PARTITION pa9 values less than (90), PARTITION pa10 values less than (100), PARTITION pa11 values less than MAXVALUE)/*!*/;                                                                             BINLOG '                                                                                                                                              rSqfRxcBAAAAPAAAAPgDKQEAAB4AAAAAAAAABP/wBAAAdT/3REMSAAAOcm9vdEBsb2NhbGhvc3TJ    uus+                                                                            rSqfRxMBAAAAPQAAADUEKQEAABgAAAAAAAAABHRlc3QADHBpbnNkZWwyX3RibAAGCQf+/AkPBf7/    BP8APA==                                                                        rSqfRxkBAAAAewAAALAEKQEQABgAAAAAAAEABv/AvgAArCqfRw5yb290QGxvY2FsaG9zdCQAAABh    YjVlNjc0ZTFmLWJlMTAtMmJhYS0xZDAwLTBjMjljODMxNGMLAAAbR29pbmcgdG8gdGVzdCBNQlIg    Zm9yIE15U1FM                                                                                                                                                  '/*!*/;

The assert happens if with both Maria and MyISAM in the CREATE TABLE.

The issue is reproducible on the latest 5.1 BitKeeper treee.

Thank you for the report.

Verified as described.

Philip, about your second comment (the assert): I pasted your two queries (CREATE TABLE and BINLOG) to a client (started with mtr --start-and-exit rpl_ps). It didn't give an assert, just an error message:

ERROR 1609 (HY000): The BINLOG statement of type `Write_rows` was not preceded by a format description BINLOG statement.

This was with the current mysql-5.1-new-rpl tree.
Did you get something else?

Yes I now see that very recently a new error message ER_NO_FORMAT_DESCRIPTION_EVENT_BEFORE_BINLOG_STATEMENT has been introduced which is printed when trying the CREATE + BINLOG query combination.

Right, I should have known. But even after I add a BINLOG statement with a  Format_description_log_event, it only gives an error message:

BINLOG '
9CmfRw8BAAAAZgAAAGoAAAAAAAQANS4xLjIzLW1hcmlhLWFscGhhLWRlYnVnLWxvZwAAAAAAAAAA
AAAAAAAAAAAAAAAAAAD0KZ9HEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
'/*!*/;

CREATE TABLE test.pinsdel2_tbl(id MEDIUMINT NOT NULL AUTO_INCREMENT, dt TIMESTAMP, user
CHAR(255), uuidf LONGBLOB, fkid MEDIUMINT, filler VARCHAR(255), PRIMARY
KEY(id))ENGINE=Maria PARTITION BY RANGE(id) SUBPARTITION BY hash(id) subpartitions 2
(PARTITION pa1 values less than (10), PARTITION pa2 values less than (20), PARTITION pa3
values less than (30), PARTITION pa4 values less than (40), PARTITION pa5 values less than
(50), PARTITION pa6 values less than (60), PARTITION pa7 values less than (70), PARTITION
pa8 values less than (80), PARTITION pa9 values less than (90), PARTITION pa10 values less than (100), PARTITION pa11 values less than MAXVALUE)/*!*/;                               

Query OK, 0 rows affected, 2 warnings (0.58 sec)

BINLOG '
rSqfRxcBAAAAPAAAAPgDKQEAAB4AAAAAAAAABP/wBAAAdT/3REMSAAAOcm9vdEBsb2NhbGhvc3TJ 
uus+
rSqfRxMBAAAAPQAAADUEKQEAABgAAAAAAAAABHRlc3QADHBpbnNkZWwyX3RibAAGCQf+/AkPBf7/    BP8APA==
rSqfRxkBAAAAewAAALAEKQEQABgAAAAAAAEABv/AvgAArCqfRw5yb290QGxvY2FsaG9zdCQAAABh   
YjVlNjc0ZTFmLWJlMTAtMmJhYS0xZDAwLTBjMjljODMxNGMLAAAbR29pbmcgdG8gdGVzdCBNQlIg   
Zm9yIE15U1FM                                                                              
'/*!*/;

ERROR 1032 (HY000): Can't find record in 'pinsdel2_tbl'

Please try this on your side, and if you get other results, include the full error message and any logs.

The assert was present in the 5.1 tree as of 29th of January, however I think it is gone now -- I get either ER_NO_FORMAT_DESCRIPTION_EVENT_BEFORE_BINLOG_STATEMENT  or "Can't find record in 'pinsdel2_tbl'". I would say that this part of the bug report has been resolved.

Philip,

I'm a bit lost - what kind of problem this bug is about?

I was unable to repeat server crash using provided binlogs (both raw binlog and mysqlbinlog dump). According to discussion with Sven this problem seem to be resolved.

If this bug is about assertion failure (thd->lock == 0), could you please provide repeatable test case? Is this problem repeatable with the main 5.1 tree?

If this bug is about incorrect binary log (row event is not preceded by a Table_map_log_event), could you please provide repeatable test case? Is this problem repeatable with the main 5.1 tree?

Please note that BUG#29020 may be related. It is possible (but I don't know for sure) that a fix to BUG#29020 would fix this bug too.

This bug is a duplicate of BUG#29020 and will be fixed by the patch that that bug.

Ok then, this only leaves the assertion, for which I will file a separate bug report once I have a repeatable test case. Any pointers as to what the assertion is supposed to safeguard are still welcome.