Bug #56504 rpl.rpl_master_retry_count fails in 5.1
Submitted: 2 Sep 2010 16:00 Modified: 10 Sep 2010 17:15
Reporter: Sveta Smirnova Email Updates:
Status: Can't repeat Impact on me:
None 
Category:Tests: Replication Severity:S3 (Non-critical)
Version:5.1 OS:Any
Assigned to: Luis Soares CPU Architecture:Any

[2 Sep 2010 16:00] Sveta Smirnova
Description:
rpl.rpl_master_retry_count fails in 5.1

How to repeat:
$./mtr rpl_master_retry_count
Logging: ./mtr  rpl_master_retry_count
100902 17:42:46 [Note] Plugin 'FEDERATED' is disabled.
100902 17:42:46 [Note] Plugin 'ndbcluster' is disabled.
MySQL Version 5.1.51
Checking supported features...
 - using ndbcluster when necessary, mysqld supports it
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
 - adding combinations for rpl
vardir: /users/ssmirnova/blade12/src/mysql-5.1/mysql-test/var
Checking leftover processes...
Removing old var directory...
 - WARNING: Using the 'mysql-test/var' symlink
Creating var directory '/users/ssmirnova/blade12/src/mysql-5.1/mysql-test/var'...
Installing system database...
Using server port 49858
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009

==============================================================================

TEST                                      RESULT   TIME (ms)
------------------------------------------------------------

stop slave;
drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
reset master;
reset slave;
drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
start slave;
include/stop_slave.inc
CHANGE MASTER TO  master_connect_retry=1;
include/start_slave.inc
### stop slave server
worker[1] Trying to dump core for [mysqltest - pid: 26167, winpid: 26167]
worker[1] Trying to dump core for [mysqld.1 - pid: 26121, winpid: 26121, exit: 0]
worker[1] Trying to dump core for [mysqld.2 - pid: 26124, winpid: 26124]
rpl.rpl_master_retry_count 'row'         [ fail ]  timeout after 900 seconds
        Test ended at 2010-09-02 17:58:40

Test case timeout after 900 seconds

 == /users/ssmirnova/blade12/src/mysql-5.1/mysql-test/var/tmp/analyze-timeout-mysqld.1.err ==
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local MySQL server through socket '/users/ssmirnova/blade12/src/mysql-5.1/mysql-test/var/tmp/mysqld.1.sock' (2)

 == /users/ssmirnova/blade12/src/mysql-5.1/mysql-test/var/tmp/analyze-timeout-mysqld.2.err ==
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local MySQL server through socket '/users/ssmirnova/blade12/src/mysql-5.1/mysql-test/var/tmp/mysqld.2.sock' (111)

 - saving '/users/ssmirnova/blade12/src/mysql-5.1/mysql-test/var/log/rpl.rpl_master_retry_count-row/' to '/users/ssmirnova/blade12/src/mysql-5.1/mysql-test/var/log/rpl.rpl_master_retry_count-row/'
 - found 'core.26126' (0/5)

Trying 'dbx' to get a backtrace

Trying 'gdb' to get a backtrace
Core generated by '/users/ssmirnova/blade12/src/mysql-5.1/sql/mysqld'
Output from gdb follows. The first stack trace is from the failing thread.
The following stack traces are from all threads (so the failing one is
duplicated).
--------------------------
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `/users/ssmirnova/blade12/src/mysql-5.1/sql/mysqld --defaults-group-suffix=.2 --'.
Program terminated with signal 6, Aborted.
#0  0x0000003429e0b002 in pthread_kill () from /lib64/libpthread.so.0
#0  0x0000003429e0b002 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000b28c5d in my_write_core (sig=6) at stacktrace.c:331
#2  0x0000000000697ca2 in handle_segfault (sig=6) at mysqld.cc:2606
#3  <signal handler called>
#4  0x00000034292c6952 in __select_nocancel () from /lib64/libc.so.6
#5  0x000000000069bc80 in handle_connections_sockets (arg=0x0) at mysqld.cc:5103
#6  0x000000000069b0a7 in main (argc=8, argv=0x7fff10007c18) at mysqld.cc:4587

Thread 4 (process 26128):
#0  0x0000003429e0da78 in do_sigwait () from /lib64/libpthread.so.0
#1  0x0000003429e0db1d in sigwait () from /lib64/libpthread.so.0
#2  0x0000000000698505 in signal_hand (arg=0x0) at mysqld.cc:2808
#3  0x0000003429e061b5 in start_thread () from /lib64/libpthread.so.0
#4  0x00000034292cd39d in clone () from /lib64/libc.so.6
#5  0x0000000000000000 in ?? ()

Thread 3 (process 26188):
#0  0x0000000000b0e491 in _checkchunk (irem=0x11975ca0, filename=0xd35601 "mf_cache.c", lineno=118) at safemalloc.c:497
#1  0x0000000000b0e59e in _sanity (filename=0xd35601 "mf_cache.c", lineno=118) at safemalloc.c:527
#2  0x0000000000b0dcc9 in _myfree (ptr=0x1198bc18, filename=0xd35601 "mf_cache.c", lineno=118, myflags=64) at safemalloc.c:275
#3  0x0000000000b0bab5 in close_cached_file (cache=0x11a31248) at mf_cache.c:118
#4  0x0000000000780f7c in ~binlog_trx_data (this=0x11a31248) at log.cc:165
#5  0x00000000007736cd in binlog_close_connection (hton=0x11990ed8, thd=0x119f0718) at log.cc:1378
#6  0x00000000007ede12 in closecon_handlerton (thd=0x119f0718, plugin=0x40a81f20, unused=0x0) at handler.cc:607
#7  0x00000000008bf56f in plugin_foreach_with_mask (thd=0x119f0718, func=0x7edd98 <closecon_handlerton>, type=1, state_mask=4294967287, arg=0x0) at sql_plugin.cc:1870
#8  0x00000000007ede5e in ha_close_connection (thd=0x119f0718) at handler.cc:621
#9  0x000000000067bf73 in ~THD (this=0x119f0718) at sql_class.cc:1015
#10 0x000000000069748e in unlink_thd (thd=0x119f0718) at mysqld.cc:1900
#11 0x00000000006976d2 in one_thread_per_connection_end (thd=0x119f0718, put_in_cache=true) at mysqld.cc:1979
#12 0x00000000006a4cc0 in handle_one_connection (arg=0x119f0718) at sql_connect.cc:1143
#13 0x0000003429e061b5 in start_thread () from /lib64/libpthread.so.0
#14 0x00000034292cd39d in clone () from /lib64/libc.so.6
#15 0x0000000000000000 in ?? ()
Current language:  auto; currently c

Thread 2 (process 26194):
#0  0x0000003429e0a376 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1  0x0000000000b34446 in safe_cond_wait (cond=0x119e6a40, mp=0x119e6498, file=0xc9d55c "log.cc", line=4912) at thr_mutex.c:237
#2  0x000000000077d530 in MYSQL_BIN_LOG::wait_for_update (this=0x119e6490, thd=0x11a58348, is_slave=true) at log.cc:4912
#3  0x000000000086832b in next_event (rli=0x119e6000) at slave.cc:4269
#4  0x0000000000862d77 in exec_relay_log_event (thd=0x11a58348, rli=0x119e6000) at slave.cc:2260
#5  0x0000000000864fa9 in handle_slave_sql (arg=0x119e4c10) at slave.cc:3077
#6  0x0000003429e061b5 in start_thread () from /lib64/libpthread.so.0
#7  0x00000034292cd39d in clone () from /lib64/libc.so.6
#8  0x0000000000000000 in ?? ()

Thread 1 (process 26126):
#0  0x0000003429e0b002 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000b28c5d in my_write_core (sig=6) at stacktrace.c:331
#2  0x0000000000697ca2 in handle_segfault (sig=6) at mysqld.cc:2606
#3  <signal handler called>
#4  0x00000034292c6952 in __select_nocancel () from /lib64/libc.so.6
#5  0x000000000069bc80 in handle_connections_sockets (arg=0x0) at mysqld.cc:5103
#6  0x000000000069b0a7 in main (argc=8, argv=0x7fff10007c18) at mysqld.cc:4587

Only  1  of 3 completed.