MySQL Bugs: #59495: rpl.rpl_read_old_relay_log_info fails intermittently in PB2

Bug #59495	rpl.rpl_read_old_relay_log_info fails intermittently in PB2
Submitted:	14 Jan 2011 8:44	Modified:	29 Jun 2011 13:27
Reporter:	Jørgen Løland	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	5.6	OS:	Any
Assigned to:	Alfranio Tavares Correia Junior	CPU Architecture:	Any

Description:
rpl.rpl_read_old_relay_log_info has been failing intermittently in PB2 lately.

How to repeat:
Look at PB2, e.g. mysql-trunk 2011-01-13

Symptom:

rpl.rpl_read_old_relay_log_info w24 [ fail ]
        Test ended at 2011-01-13 18:42:38

CURRENT_TEST: rpl.rpl_read_old_relay_log_info
mysqltest: At line 27: query 'START SLAVE IO_THREAD' failed: 1201: Could not initialize master info structure; more error messages can be found in the MySQL error log

The result from queries just before the failure was:
include/master-slave.inc
[connection master]
CREATE TABLE t1 (a INT);
INSERT INTO t1 VALUES (1);
DROP TABLE t1;
==== Check that we still understand the old format of relay-log.info ====
include/stop_slave.inc
RESET SLAVE;
# Read relay-log.info

 - saving '/tmp/mtr-29889/var-n_mix/24/log/rpl.rpl_read_old_relay_log_info/' to '/tmp/mtr-29889/var-n_mix/log/rpl.rpl_read_old_relay_log_info/'

Retrying test rpl.rpl_read_old_relay_log_info, attempt(2/3)...

In slave's error log, one finds:

CURRENT_TEST: rpl.rpl_read_old_relay_log_info
110113 20:42:37 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='21230', master_log_file='', master_log_pos='4', master_bind=''. New state master_host='127.0.0.1', master_port='21230', master_log_file='master-bin.000001', master_log_pos='4', master_bind=''.
110113 20:42:37 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 4, relay log './slave-relay-bin.000002' position: 4
110113 20:42:37 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:21230',replication started in log 'master-bin.000001' at position 4
110113 20:42:38 [Note] Slave I/O thread killed while reading event
110113 20:42:38 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 529
110113 20:42:38 [Note] Error reading relay log event: slave SQL thread was killed
110113 20:42:38 [ERROR] Failed to open the relay log './slave-relay-bin.000001' (relay_log_pos 4)
110113 20:42:38 [ERROR] Could not find target log during relay log initialization
CURRENT_TEST: rpl.rpl_read_old_relay_log_info
110113 20:42:41 [Warning] The syntax '--master-retry-count' is deprecated and will be removed in a future release. Please use 'CHANGE MASTER TO master_retry_count = <num>' instead.
110113 20:42:41 [Note] Plugin 'FEDERATED' is disabled.
110113 20:42:41 InnoDB: The InnoDB memory heap is disabled
110113 20:42:41 InnoDB: Mutexes and rw_locks use Solaris atomic functions
110113 20:42:41 InnoDB: Compressed tables use zlib 1.2.3
110113 20:42:41 InnoDB: Initializing buffer pool, size = 8.0M
110113 20:42:41 InnoDB: Completed initialization of buffer pool
110113 20:42:41 InnoDB: highest supported file format is Barracuda.
110113 20:42:41 InnoDB: 1.2.1 started; log sequence number 1595675
110113 20:42:41 [Warning] /export/home/pb2/test/sb_1-2793391-1294940277.84/mysql-5.6.2-m5-solaris10-sparc-64bit-test/bin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
110113 20:42:41 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 853baca5-1f3c-11e0-be8b-8d4fe17fd5ae.
110113 20:42:41 [Note] Event Scheduler: Loaded 0 events
110113 20:42:41 [Note] /export/home/pb2/test/sb_1-2793391-1294940277.84/mysql-5.6.2-m5-solaris10-sparc-64bit-test/bin/mysqld: ready for connections.
Version: '5.6.2-m5-log'  socket: '/tmp/mtr-29889/var-n_mix/tmp/24/mysqld.2.sock'  port: 21231  Source distribution
110113 20:42:43 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4', master_bind=''. New state master_host='127.0.0.1', master_port='21230', master_log_file='master-bin.000001', master_log_pos='4', master_bind=''.
110113 20:42:43 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 4, relay log './slave-relay-bin.000001' position: 4
110113 20:42:43 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:21230',replication started in log 'master-bin.000001' at position 4
110113 20:42:43 [Note] Slave I/O thread killed while reading event
110113 20:42:43 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 529
110113 20:42:43 [Note] Error reading relay log event: slave SQL thread was killed
110113 20:42:43 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:21230',replication started in log 'FIRST' at position 4
110113 20:42:43 [Note] Slave I/O thread killed while reading event
110113 20:42:43 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 529
110113 20:42:47 [Note] /export/home/pb2/test/sb_1-2793391-1294940277.84/mysql-5.6.2-m5-solaris10-sparc-64bit-test/bin/mysqld: Normal shutdown

110113 20:42:47 [Note] Event Scheduler: Purging the queue. 0 events
110113 20:42:47  InnoDB: Starting shutdown...
110113 20:42:48  InnoDB: Shutdown completed; log sequence number 1595675
110113 20:42:48 [Note] /export/home/pb2/test/sb_1-2793391-1294940277.84/mysql-5.6.2-m5-solaris10-sparc-64bit-test/bin/mysqld: Shutdown complete

CURRENT_TEST: rpl.rpl_read_old_relay_log_info
(...)

Logs taken form failure:

http://pb2.norway.sun.com/web.py?template=mysql_show_test_failure&search=yes&push_id=19042...

The problem was introduced while developing WL#344 and the failure popped up in the development tree used to hold the WL:

http://pb2.norway.sun.com/?template=mysql_show_test_failure&test_failure_id=&test_output_i...

The test case fails because the START SLAVE IO_THREAD fails while opening a relay log, although it exists:

110104 14:14:15 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 4, relay log './slave-relay-bin.000003' position: 4
110104 14:14:15 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:20010',replication started in log 'master-bin.000001' at position 4
110104 14:14:16 [Note] Slave I/O thread killed while reading event
110104 14:14:16 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 516
110104 14:14:16 [Note] Error reading relay log event: slave SQL thread was killed
110104 14:14:16 [ERROR] Failed to open the relay log './slave-relay-bin.000001' (relay_log_pos 4)

One can find a tar-ball with the error files at http://trollheim.norway.sun.com/archive/2732162.mysql-5.6.2-m5-solaris10-sparc-64bit-test....

The test only fails on Solaris.

Not enough information was provided for us to be able to handle this bug. Please re-read the instructions at http://bugs.mysql.com/how-to-report.php

If you can provide more information, feel free to add it to this bug and change the status back to 'Open'.

Thank you for your interest in MySQL.