Bug #38316 Assertion `m_curr_row_end <= m_rows_end' failed in unpack_current_row
Submitted: 23 Jul 2008 16:54 Modified: 19 Dec 2008 9:42
Reporter: Sven Sandberg Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:5.1-bugteam OS:Linux (ubuntu 8.04)
Assigned to: Andrei Elkin CPU Architecture:Any
Tags: assertion, binlog.binlog_base64_flag, crash, disabled, unpack_current_row
Triage: Triaged: D1 (Critical)

[23 Jul 2008 16:54] Sven Sandberg
Description:
When running the binlog suite locally, I got the following assertion in binlog.binlog_base64_flag:

========= BEGIN MTR OUTPUT ========
binlog.binlog_base64_flag 'row' [ fail ]

Warning: Not freed memory segments: 2
Warning: Memory that was not free'ed (555 bytes):
	    99 bytes at 0x008098748, allocated at line 1019 in 'log_event.cc'
	   456 bytes at 0x008072040, allocated at line  201 in 'my_alloc.c'
ERROR: --base64-output=never specified, but binlog contains a Table_map event which must be printed in base64.
Warning: Not freed memory segments: 2
Warning: Memory that was not free'ed (555 bytes):
	    99 bytes at 0x008098748, allocated at line 1019 in 'log_event.cc'
	   456 bytes at 0x008072040, allocated at line  201 in 'my_alloc.c'
mysqltest: At line 147: query 'BINLOG '
iONkSBMBAAAANwAAAJkBAAAAABAAAAAAAAAABHRlc3QADGNoYXIxMjhfdXRmOAADA/4DAv6AAA==
iONkSBcBAAAAKwAAAMQBAAAQABAAAAAAAAEAA//4AQAAAAMAMTIzAQAAAA==
'' failed with wrong errno 2013: 'Lost connection to MySQL server during query', instead of 1105...

The result from queries just before the failure was:
< snip >
CREATE TABLE char63_utf8 (
i1 INT NOT NULL,
c CHAR(63) CHARACTER SET utf8 NOT NULL,
i2 INT NOT NULL);
BINLOG '
MuNkSA8BAAAAZgAAAGoAAAAAAAQANS4xLjI1LXJjLWRlYnVnLWxvZwAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAy42RIEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
';
BINLOG '
3u9kSBMBAAAANgAAAJYBAAAAABAAAAAAAAAABHRlc3QAC2NoYXI2M191dGY4AAMD/gMC/r0A
3u9kSBcBAAAAKgAAAMABAAAQABAAAAAAAAEAA//4AQAAAAMxMjMBAAAA
';
SELECT * FROM char63_utf8;
i1	c	i2
1	123	1
BINLOG '
iONkSBMBAAAANwAAAJkBAAAAABAAAAAAAAAABHRlc3QADGNoYXIxMjhfdXRmOAADA/4DAv6AAA==
iONkSBcBAAAAKwAAAMQBAAAQABAAAAAAAAEAA//4AQAAAAMAMTIzAQAAAA==
';
ERROR HY000: Lost connection to MySQL server during query

More results from queries before failure can be found in /home/sven/bzr/debug-max/5.1-bugteam/mysql-test/var/log/binlog_base64_flag.log

Aborting: binlog.binlog_base64_flag failed in default mode. 
To continue, re-run with '--force'.
Stopping All Servers
========= END MTR OUTPUT ========

========= BEGIN master.err ========
CURRENT_TEST: binlog.binlog_auto_increment_bug33029
InnoDB: The first specified data file ./ibdata1 did not exist:
InnoDB: a new database to be created!
080723 19:32:01  InnoDB: Setting file ./ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
080723 19:32:02  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
InnoDB: Database physically writes the file full: wait...
080723 19:32:02  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 5 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
080723 19:32:02  InnoDB: Started; log sequence number 0 0
080723 19:32:02 [Note] Event Scheduler: Loaded 0 events
080723 19:32:03 [Note] /home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld: ready for connections.
Version: '5.1.28-debug-log'  socket: '/home/sven/bzr/debug-max/5.1-bugteam/mysql-test/var/tmp/master.sock'  port: 10260  Source distribution
080723 19:32:03 [Note] Slave SQL thread initialized, starting replication in log 'FIRST' at position 0, relay log 'slave-relay-bin.000001' position: 4
080723 19:32:03 [Note] next log './slave-relay-bin.000002' is currently active
080723 19:32:03 [Note] Error reading relay log event: slave SQL thread was killed
080723 19:32:03 [Note] Got signal 15 to shutdown mysqld
080723 19:32:03 [Note] /home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld: Normal shutdown

080723 19:32:03 [Note] Event Scheduler: Purging the queue. 0 events
080723 19:32:03  InnoDB: Starting shutdown...
080723 19:32:04  InnoDB: Shutdown completed; log sequence number 0 46409
080723 19:32:04 [Note] /home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld: Shutdown complete

CURRENT_TEST: binlog.binlog_base64_flag
080723 19:32:04  InnoDB: Started; log sequence number 0 46409
080723 19:32:04 [Note] Event Scheduler: Loaded 0 events
080723 19:32:04 [Note] /home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld: ready for connections.
Version: '5.1.28-debug-log'  socket: '/home/sven/bzr/debug-max/5.1-bugteam/mysql-test/var/tmp/master.sock'  port: 10260  Source distribution
mysqld: log_event.h:3469: int Rows_log_event::unpack_current_row(const Relay_log_info*): Assertion `m_curr_row_end <= m_rows_end' failed.
080723 19:32:05 - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=2
max_threads=151
threads_connected=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 59966 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x8f23c08
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0xb51873d0 thread_stack 0x30000
/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld(my_print_stacktrace+0x26)[0x8704605]
/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld(handle_segfault+0x2ae)[0x82b759a]
[0xb7fbd420]
/lib/tls/i686/cmov/libc.so.6(abort+0x101)[0xb7df7a01]
/lib/tls/i686/cmov/libc.so.6(__assert_fail+0xee)[0xb7def10e]
/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld(_ZN14Rows_log_event18unpack_current_rowEPK14Relay_log_info+0x125)[0x83b4ff1]
/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld(_ZN14Rows_log_event9write_rowEPK14Relay_log_infob+0x15c)[0x83a1dba]
/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld(_ZN20Write_rows_log_event11do_exec_rowEPK14Relay_log_info+0x6c)[0x83a28e4]
/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld(_ZN14Rows_log_event14do_apply_eventEPK14Relay_log_info+0x8e6)[0x83a64e6]
/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld(_ZN9Log_event11apply_eventEPK14Relay_log_info+0x1f)[0x8452137]
/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld(_Z26apply_event_and_update_posP9Log_eventP3THDP14Relay_log_infob+0x2f0)[0x8448f2e]
/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld(_Z29mysql_client_binlog_statementP3THD+0x585)[0x84a73e1]
/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld(_Z21mysql_execute_commandP3THD+0x9353)[0x82d20ab]
/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld(_Z11mysql_parseP3THDPKcjPS2_+0x234)[0x82d27da]
/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xb7f)[0x82d34eb]
/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld(_Z10do_commandP3THD+0x249)[0x82d48c7]
/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld(handle_one_connection+0x11b)[0x82c1083]
/lib/tls/i686/cmov/libpthread.so.0[0xb7f934fb]
/lib/tls/i686/cmov/libc.so.6(clone+0x5e)[0xb7ea1e5e]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x8f83f90 = BINLOG '
iONkSBMBAAAANwAAAJkBAAAAABAAAAAAAAAABHRlc3QADGNoYXIxMjhfdXRmOAADA/4DAv6AAA==
iONkSBcBAAAAKwAAAMQBAAAQABAAAAAAAAEAA//4AQAAAAMAMTIzAQAAAA==
'
thd->thread_id=1
thd->killed=NOT_KILLED
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file
========= END master.err ========

How to repeat:
./mtr binlog_base64_flag
[23 Jul 2008 16:59] Sven Sandberg
traceback according to gdb:

$ gdb ../sql/mysqld var/master-data/core.21841 --eval-command=bt --batch

warning: Can't read pathname for load map: Input/output error.
Core was generated by `/home/sven/bzr/debug-max/5.1-bugteam/sql/mysqld --no-defaults --basedir=/home/s'.
Program terminated with signal 6, Aborted.
[New process 21861]
[New process 21843]
[New process 21841]
#0  0xb7f03410 in __kernel_vsyscall ()
#0  0xb7f03410 in __kernel_vsyscall ()
#1  0xb7edeae7 in pthread_kill () from /lib/tls/i686/cmov/libpthread.so.0
#2  0x08704689 in my_write_core (sig=6) at stacktrace.c:310
#3  0x082b77c7 in handle_segfault (sig=6) at mysqld.cc:2507
#4  <signal handler called>
#5  0xb7f03410 in __kernel_vsyscall ()
#6  0xb7d3c085 in raise () from /lib/tls/i686/cmov/libc.so.6
#7  0xb7d3da01 in abort () from /lib/tls/i686/cmov/libc.so.6
#8  0xb7d3510e in __assert_fail () from /lib/tls/i686/cmov/libc.so.6
#9  0x083b4ff1 in Rows_log_event::unpack_current_row (this=0x8ab3fb8, 
    rli=0x8ab0bd0) at log_event.h:3469
#10 0x083a1dba in Rows_log_event::write_row (this=0x8ab3fb8, rli=0x8ab0bd0, 
    overwrite=false) at log_event.cc:7617
#11 0x083a28e4 in Write_rows_log_event::do_exec_row (this=0x8ab3fb8, 
    rli=0x8ab0bd0) at log_event.cc:7790
#12 0x083a64e6 in Rows_log_event::do_apply_event (this=0x8ab3fb8, 
    rli=0x8ab0bd0) at log_event.cc:6609
#13 0x08452137 in Log_event::apply_event (this=0x8ab3fb8, rli=0x8ab0bd0)
    at log_event.h:1011
#14 0x08448f2e in apply_event_and_update_pos (ev=0x8ab3fb8, thd=0x8a5e890, 
    rli=0x8ab0bd0, skip=false) at slave.cc:1938
#15 0x084a73e1 in mysql_client_binlog_statement (thd=0x8a5e890)
    at sql_binlog.cc:209
#16 0x082d20ab in mysql_execute_command (thd=0x8a5e890) at sql_parse.cc:4599
#17 0x082d27da in mysql_parse (thd=0x8a5e890, 
    inBuf=0x8abb280 "BINLOG '\niONkSBMBAAAANwAAAJkBAAAAABAAAAAAAAAABHRlc3QADGNoYXIxMjhfdXRmOAADA/4DAv6AAA==\niONkSBcBAAAAKwAAAMQBAAAQABAAAAAAAAEAA//4AQAAAAMAMTIzAQAAAA==\n'", length=148, found_semicolon=0xb73ee09c) at sql_parse.cc:5656
#18 0x082d34eb in dispatch_command (command=COM_QUERY, thd=0x8a5e890, 
    packet=0x8aac389 "BINLOG '\niONkSBMBAAAANwAAAJkBAAAAABAAAAAAAAAABHRlc3QADGNoYXIxMjhfdXRmOAADA/4DAv6AAA==\niONkSBcBAAAAKwAAAMQBAAAQABAAAAAAAAEAA//4AQAAAAMAMTIzAQAAAA==\n'", packet_length=148) at sql_parse.cc:1137
#19 0x082d48c7 in do_command (thd=0x8a5e890) at sql_parse.cc:794
#20 0x082c1083 in handle_one_connection (arg=0x8a5e890) at sql_connect.cc:1115
#21 0xb7ed94fb in start_thread () from /lib/tls/i686/cmov/libpthread.so.0
#22 0xb7de7e5e in clone () from /lib/tls/i686/cmov/libc.so.6
[23 Jul 2008 17:54] Sven Sandberg
Wait, I get this always in 5.1 main and 5.1-bugteam, but I can't get it in 5.1-rpl (after 1000 runs). So it may already be fixed in 5.1-rpl.
[23 Jul 2008 17:55] Sven Sandberg
Hmm, and that means that BUG#38290 may already be fixed, too.
[8 Dec 2008 12:27] Alexander Nozdrin
binlog_base64_flag is disabled due to this bug.
[19 Dec 2008 9:42] Sven Sandberg
I can't repeat this anymore.