Bug #57892 Crash in my_b_write_quoted (log_event.cc) from mysqlbinlog with checksum
Submitted: 1 Nov 2010 12:02 Modified: 10 Nov 2010 14:45
Reporter: John Embretsen Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:5.6.99 (bzr_mysql-next-mr-wl2540) OS:Any
Assigned to: Assigned Account CPU Architecture:Any
Tags: pushbuild, wl2540

[1 Nov 2010 12:02] John Embretsen
Description:
This issue is found while testing WL#2540's implementation in mysql-next-mr-wl2540 branch as of 2010-10-28.

The test binlog_row_mysqlbinlog_db_filter fails with symptoms as described below. The reason is a segmentation fault in mysqlbinlog, at log_event.cc line 1770, function my_b_write_quoted.

The failure is observed on both Linux and Solaris, but it seems to happen more frequently on Solaris, with both debug and optimized builds.

(Paths shortened for readability)

binlog.binlog_row_mysqlbinlog_db_filter 'row' [ fail ]
        Test ended at 2010-11-01 12:31:08

CURRENT_TEST: binlog.binlog_row_mysqlbinlog_db_filter
mysqltest: At line 102: command "$cmd $flags $log_file1 > $outfile.1" failed

Output from before failure:
exec of 'bin/mysqlbinlog --defaults-file=mysql-test/var-misc/my.cnf --database=b42941 --verbose --hexdump mysql-test/var-misc/mysqld.1/data//master-bin.000001 > mysql-test/var-misc/tmp/b42941-mysqlbinlog.1' failed, error: 139, status: 0, errno: 29

The result from queries just before the failure was:
< snip >
CREATE TABLE t1 (id int);
CREATE TABLE t2 (id int);
CREATE TABLE t3 (txt TEXT);
CREATE TABLE t4 (a int) ENGINE= InnoDB;
INSERT INTO t1 VALUES (1);
INSERT INTO t1 VALUES (2);
INSERT INTO t2 VALUES (1);
INSERT INTO t2 VALUES (2);
INSERT INTO t1 VALUES (3);
LOAD DATA INFILE 'MYSQLTEST_VARDIR/std_data/words.dat' INTO TABLE t3;
INSERT INTO t1 VALUES (4);
INSERT INTO test.t1 VALUES (5);
FLUSH LOGS;
UPDATE test.t1 t11, b42941.t1 t12 SET t11.id=10, t12.id=100;
BEGIN;
INSERT INTO test.t4 VALUES (1);
INSERT INTO b42941.t4 VALUES (1);
UPDATE test.t4 tn4, b42941.t4 tt4 SET tn4.a= 10, tt4.a= 100;
COMMIT;
FLUSH LOGS;

More results from queries before failure can be found in mysql-test/var-misc/log/binlog_row_mysqlbinlog_db_filter.log

 - saving 'mysql-test/var-misc/log/binlog.binlog_row_mysqlbinlog_db_filter-row/' to 'mysql-test/var-misc/log/binlog.binlog_row_mysqlbinlog_db_filter-row/'
 - found 'core', moving it to 'mysql-test/var-misc/log/binlog.binlog_row_mysqlbinlog_db_filter-row'
 - found 'core' (0/5)

Trying 'dbx' to get a backtrace
Core generated by 'bin/mysqlbinlog'
Output from dbx follows. Stack trace is printed for all threads in order,
above this you should see info about which thread was the failing one.
----------------------------
For information about new features see `help changes'
To remove this message, put `dbxenv suppress_startup_message 7.7' in your .dbxrc
Reading mysqlbinlog
core file header read successfully
Reading ld.so.1
Reading libthread.so.1
Reading libsocket.so.1
Reading libnsl.so.1
Reading libm.so.2
Reading libCstd.so.1
Reading libCrun.so.1
Reading libc.so.1
t@1 (l@1) program terminated by signal SEGV (no mapping at the fault address)
Current function is my_b_write_quoted
 1770       if (*s > 0x1F)
current thread: t@1
=>[1] my_b_write_quoted(file = 0xfffffd7fffdfc600, ptr = 0xadd7d4 "«", length = 46040U), line 1770 in "log_event.cc"
  [2] log_event_print_value(file = 0xfffffd7fffdfc600, ptr = 0xadd7d2 "^D̫", type = 252U, meta = 2U, typestr = 0xfffffd7fffdfa9f4 "", typestr_length = 64U), line 2102 in "log_event.cc"
  [3] Rows_log_event::print_verbose_one_row(this = 0xadd400, file = 0xfffffd7fffdfc600, td = 0xa6b210, print_event_info = 0xfffffd7fffdfc0a0, cols_bitmap = 0xadd458, value = 0xadd7d2 "^D̫", prefix = 0x7336c0 "### SET\n"), line 2189 in "log_event.cc"
  [4] Rows_log_event::print_verbose(this = 0xadd400, file = 0xfffffd7fffdfc600, print_event_info = 0xfffffd7fffdfc0a0), line 2278 in "log_event.cc"
  [5] Log_event::print_base64(this = 0xadcc00, file = 0xfffffd7fffdfc600, print_event_info = 0xfffffd7fffdfc0a0, more = false), line 2367 in "log_event.cc"
  [6] Rows_log_event::print_helper(this = 0xadcc00, file = 0xfffffd7fff30afa0, print_event_info = 0xfffffd7fffdfc0a0, name = 0x7357fe "Write_rows"), line 8526 in "log_event.cc"
  [7] Write_rows_log_event::print(this = 0xadcc00, file = 0xfffffd7fff30afa0, print_event_info = 0xfffffd7fffdfc0a0), line 9463 in "log_event.cc"
  [8] process_event(print_event_info = 0xfffffd7fffdfc0a0, ev = 0xadcc00, pos = 4064ULL, logname = 0xfffffd7fffdfcf5d "mysql-test/var-misc/mysqld.1/data//master-bin.000001"), line 987 in "mysqlbinlog.cc"
  [9] dump_local_log_entries(print_event_info = 0xfffffd7fffdfc0a0, logname = 0xfffffd7fffdfcf5d "mysql-test/var-misc/mysqld.1/data//master-bin.000001"), line 2119 in "mysqlbinlog.cc"
  [10] dump_log_entries(logname = 0xfffffd7fffdfcf5d "mysql-test/var-misc/mysqld.1/data//master-bin.000001"), line 1479 in "mysqlbinlog.cc"
  [11] main(argc = 0, argv = 0xa94738), line 2251 in "mysqlbinlog.cc"
current thread: t@1
=>[1] my_b_write_quoted(file = 0xfffffd7fffdfc600, ptr = 0xadd7d4 "«", length = 46040U), line 1770 in "log_event.cc"
  [2] log_event_print_value(file = 0xfffffd7fffdfc600, ptr = 0xadd7d2 "^D̫", type = 252U, meta = 2U, typestr = 0xfffffd7fffdfa9f4 "", typestr_length = 64U), line 2102 in "log_event.cc"
  [3] Rows_log_event::print_verbose_one_row(this = 0xadd400, file = 0xfffffd7fffdfc600, td = 0xa6b210, print_event_info = 0xfffffd7fffdfc0a0, cols_bitmap = 0xadd458, value = 0xadd7d2 "^D̫", prefix = 0x7336c0 "### SET\n"), line 2189 in "log_event.cc"
  [4] Rows_log_event::print_verbose(this = 0xadd400, file = 0xfffffd7fffdfc600, print_event_info = 0xfffffd7fffdfc0a0), line 2278 in "log_event.cc"
  [5] Log_event::print_base64(this = 0xadcc00, file = 0xfffffd7fffdfc600, print_event_info = 0xfffffd7fffdfc0a0, more = false), line 2367 in "log_event.cc"
  [6] Rows_log_event::print_helper(this = 0xadcc00, file = 0xfffffd7fff30afa0, print_event_info = 0xfffffd7fffdfc0a0, name = 0x7357fe "Write_rows"), line 8526 in "log_event.cc"
  [7] Write_rows_log_event::print(this = 0xadcc00, file = 0xfffffd7fff30afa0, print_event_info = 0xfffffd7fffdfc0a0), line 9463 in "log_event.cc"
  [8] process_event(print_event_info = 0xfffffd7fffdfc0a0, ev = 0xadcc00, pos = 4064ULL, logname = 0xfffffd7fffdfcf5d "mysql-test/var-misc/mysqld.1/data//master-bin.000001"), line 987 in "mysqlbinlog.cc"
  [9] dump_local_log_entries(print_event_info = 0xfffffd7fffdfc0a0, logname = 0xfffffd7fffdfcf5d "mysql-test/var-misc/mysqld.1/data//master-bin.000001"), line 2119 in "mysqlbinlog.cc"
  [10] dump_log_entries(logname = 0xfffffd7fffdfcf5d "mysql-test/var-misc/mysqld.1/data//master-bin.000001"), line 1479 in "mysqlbinlog.cc"
  [11] main(argc = 0, argv = 0xa94738), line 2251 in "mysqlbinlog.cc"

------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 12 seconds executing testcases

Completed: Failed 1/1 tests, 0.00% were successful.

Failing test(s): binlog.binlog_row_mysqlbinlog_db_filter

How to repeat:
With the code branch mysql-next-mr-wl2540 on a Solaris platform, do:

perl ./mysql-test-run.pl --mysqld=--binlog-checksum=CRC32 binlog.binlog_row_mysqlbinlog_db_filter

(add --repeat=10 if it does not happen on first try)
[10 Nov 2010 14:45] Andrei Elkin
see bug#57893 as the parent.