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)