Bug #47566 rpl.rpl_semi_sync fails sporadically
Submitted: 23 Sep 2009 19:06 Modified: 30 Sep 2009 7:03
Reporter: Alexander Nozdrin Email Updates:
Status: Duplicate Impact on me:
None 
Category:Tests: Replication Severity:S3 (Non-critical)
Version:6.0 OS:Any
Assigned to: Assigned Account CPU Architecture:Any
Tags: experimental, pb2, sporadic, test failure

[23 Sep 2009 19:06] Alexander Nozdrin
Description:
rpl.rpl_semi_sync.test fails sporadically:

-------------------------------------------------------
rpl.rpl_semi_sync 'mix'                  w5 [ fail ]  Found warnings/errors in server log file!
        Test ended at 2009-09-23 22:36:10
mysqltest: Logging to ''.
mysqltest: Results saved in ''.
mysqltest: Connecting to server localhost:13031 (socket /mnt/raid/alik/MySQL/bzr/00.builds/mysql-6.0-codebase-alik/mysql-test/var/tmp/5/mysqld.2.sock) as 'root', connection 'default', attempt 0 ...
mysqltest: ... Connected.
mysqltest: Start processing test commands from './include/check-warnings.test' ...
file_name	line
/mnt/raid/alik/MySQL/bzr/00.builds/mysql-6.0-codebase-alik/mysql-test/var/5/log/mysqld.2.err	090923 21:36:08 [ERROR] Set 'rpl_semi_sync_master_reply_log_file_pos' on master failed
/mnt/raid/alik/MySQL/bzr/00.builds/mysql-6.0-codebase-alik/mysql-test/var/5/log/mysqld.2.err	090923 21:36:08 [ERROR] Slave I/O: Fatal error: Failed to run 'after_queue_event' hook, Error_code: 1593
^ Found warnings!!
mysqltest: ... Done processing test commands.
mysqltest: Test has succeeded!
ok
------------------------------------------------------

The failure happens on Linux x86_64.

The failure seems to come from WL#3352.

How to repeat:
Failures in 5.1:
http://pb2.norway.sun.com/web.py?template=mysql_show_test_failure&test_failure_id=2330459&...

Failures everywhere:
http://pb2.norway.sun.com/web.py?template=mysql_show_test_failure&test_failure_id=2330459&...
[30 Sep 2009 7:03] Zhenxing He
Dup of bug#45852
[7 Dec 2009 2:27] Luis Soares
There is also a failure in mysql-pe.

Failure context:

Where 	Build 	Test 	Run 	Suite 	Case 	Mode 	When
mysql-pe
739652	binary-max-ubuntu-x86_64-tar-gz
739711 loki38	test-max-ubuntu-x86_64
739992 tyr20	n_mix	rpl	rpl_semi_sync	None	2009-12-05 23:32:41

Failure symptom:

rpl.rpl_semi_sync                        [ fail ]
        Test ended at 2009-12-06 07:40:18

CURRENT_TEST: rpl.rpl_semi_sync
=== SHOW MASTER STATUS ===
---- 1. ----
File	slave-bin.000001
Position	108062
Binlog_Do_DB	
Binlog_Ignore_DB	
==========================

=== SHOW SLAVE STATUS ===
---- 1. ----
Slave_IO_State	
Master_Host	127.0.0.1
Master_User	rpl
Master_Port	13010
Connect_Retry	1
Master_Log_File	master-bin.000001
Read_Master_Log_Pos	840
Relay_Log_File	slave-relay-bin.000004
Relay_Log_Pos	438
Relay_Master_Log_File	master-bin.000001
Slave_IO_Running	No
Slave_SQL_Running	Yes
Replicate_Do_DB	
Replicate_Ignore_DB	
Replicate_Do_Table	
Replicate_Ignore_Table	
Replicate_Wild_Do_Table	
Replicate_Wild_Ignore_Table	
Last_Errno	0
Last_Error	
Skip_Counter	0
Exec_Master_Log_Pos	840
Relay_Log_Space	924
Until_Condition	None
Until_Log_File	
Until_Log_Pos	0
Master_SSL_Allowed	No
Master_SSL_CA_File	
Master_SSL_CA_Path	
Master_SSL_Cert	
Master_SSL_Cipher	
Master_SSL_Key	
Seconds_Behind_Master	
Master_SSL_Verify_Server_Cert	No
Last_IO_Errno	0
Last_IO_Error	
Last_SQL_Errno	0
Last_SQL_Error	
Replicate_Ignore_Server_Ids	
Master_Server_Id	1
=========================

=== SHOW PROCESSLIST ===
---- 1. ----
Id	2
User	root
Host	localhost:37995
db	test
Command	Query
Time	0
State	
Info	SHOW PROCESSLIST
---- 2. ----
Id	3
User	root
Host	localhost:37996
db	test
Command	Sleep
Time	330
State	
Info	
---- 3. ----
Id	25
User	system user
Host	
db	
Command	Connect
Time	300
State	Slave has read all relay log; waiting for the slave I/O thread to update it
Info	
========================

analyze: sync_with_master
mysqltest: At line 583: sync_slave_with_master failed: 'select master_pos_wait('master-bin.000001', 916, 300)' returned -1 indicating timeout after 300 seconds

The result from queries just before the failure was:
< snip >
SHOW VARIABLES LIKE 'rpl_semi_sync_slave_enabled';
Variable_name	Value
rpl_semi_sync_slave_enabled	OFF
SHOW STATUS LIKE 'Rpl_semi_sync_slave_status';
Variable_name	Value
Rpl_semi_sync_slave_status	OFF
include/start_slave.inc
SHOW STATUS LIKE 'Rpl_semi_sync_slave_status';
Variable_name	Value
Rpl_semi_sync_slave_status	OFF
#
# Clean up
#
include/stop_slave.inc
UNINSTALL PLUGIN rpl_semi_sync_slave;
UNINSTALL PLUGIN rpl_semi_sync_master;
Warnings:
Warning	1620	Plugin is busy and will be uninstalled on shutdown
include/start_slave.inc
drop table t1;

More results from queries before failure can be found in /export/home2/pb2/test/sb_1-1043204-1260080501.89/mysql-6.0.14-alpha-linux-x86_64-test/mysql-test/var/log/rpl_semi_sync.log

 == /export/home2/pb2/test/sb_1-1043204-1260080501.89/mysql-6.0.14-alpha-linux-x86_64-test/mysql-test/var/tmp/analyze-sync_with_master-mysqld.1.err ==
SHOW PROCESSLIST;
Id	User	Host	db	Command	Time	State	Info
14	rpl	localhost:39940	NULL	Binlog Dump	300	NULL	NULL
26	root	localhost	NULL	Query	0	NULL	SHOW PROCESSLIST
SHOW BINLOG EVENTS IN 'master-bin.000001';
Log_name	Pos	Event_type	Server_id	End_log_pos	Info
master-bin.000001	4	Format_desc	1	107	Server ver: 6.0.14-alpha-log, Binlog ver: 4
master-bin.000001	107	Query	1	175	BEGIN
master-bin.000001	175	Query	1	263	use `test`; insert into t1 values (4)
master-bin.000001	263	Xid	1	290	COMMIT /* xid=952 */
master-bin.000001	290	Query	1	358	BEGIN
master-bin.000001	358	Query	1	446	use `test`; insert into t1 values (5)
master-bin.000001	446	Xid	1	473	COMMIT /* xid=953 */
master-bin.000001	473	Query	1	541	BEGIN
master-bin.000001	541	Query	1	629	use `test`; insert into t1 values (8)
master-bin.000001	629	Xid	1	656	COMMIT /* xid=974 */
master-bin.000001	656	Query	1	724	BEGIN
master-bin.000001	724	Query	1	813	use `test`; insert into t1 values (10)
master-bin.000001	813	Xid	1	840	COMMIT /* xid=993 */
master-bin.000001	840	Query	1	916	use `test`; drop table t1

 == /export/home2/pb2/test/sb_1-1043204-1260080501.89/mysql-6.0.14-alpha-linux-x86_64-test/mysql-test/var/tmp/analyze-sync_with_master-mysqld.2.err ==
SHOW PROCESSLIST;
Id	User	Host	db	Command	Time	State	Info
25	system user		NULL	Connect	300	Slave has read all relay log; waiting for the slave I/O thread to update it	NULL
26	root	localhost	NULL	Query	0	NULL	SHOW PROCESSLIST
SHOW BINLOG EVENTS IN 'slave-bin.000001';
Log_name	Pos	Event_type	Server_id	End_log_pos	Info
slave-bin.000001	4	Format_desc	2	107	Server ver: 6.0.14-alpha-log, Binlog ver: 4
slave-bin.000001	107	Query	1	313	use `mtr`; INSERT INTO test_suppressions (pattern) VALUES ( NAME_CONST('pattern',_latin1'Timeout waiting for reply of binlog' COLLATE 'latin1_swedish_ci'))
slave-bin.000001	313	Query	2	524	use `mtr`; INSERT INTO test_suppressions (pattern) VALUES ( NAME_CONST('pattern',_latin1'Master server does not support semi-sync' COLLATE 'latin1_swedish_ci'))
slave-bin.000001	524	Query	1	715	use `mtr`; INSERT INTO test_suppressions (pattern) VALUES ( NAME_CONST('pattern',_latin1'Read semi-sync reply' COLLATE 'latin1_swedish_ci'))
slave-bin.000001	715	Query	2	910	use `mtr`; INSERT INTO test_suppressions (pattern) VALUES ( NAME_CONST('pattern',_latin1'Semi-sync slave .* reply' COLLATE 'latin1_swedish_ci'))
slave-bin.000001	910	Query	1	1011	use `test`; create table t1(a int) engine = InnoDB
slave-bin.000001	1011	Query	1	1070	BEGIN
slave-bin.000001	1070	Query	1	1160	use `test`; insert into t1 values (300)
slave-bin.000001	1160	Xid	1	1187	COMMIT /* xid=73 */
slave-bin.000001	1187	Query	1	1246	BEGIN
slave-bin.000001	1246	Query	1	1336	use `test`; insert into t1 values (299)
slave-bin.000001	1336	Xid	1	1363	COMMIT /* xid=75 */
slave-bin.000001	1363	Query	1	1422	BEGIN
slave-bin.000001	1422	Query	1	1512	use `test`; insert into t1 values (298)
slave-bin.000001	1512	Xid	1	1539	COMMIT /* xid=77 */
slave-bin.000001	1539	Query	1	1598	BEGIN
slave-bin.000001	1598	Query	1	1688	use `test`; insert into t1 values (297)
slave-bin.000001	1688	Xid	1	1715	COMMIT /* xid=79 */
slave-bin.000001	1715	Query	1	1774	BEGIN
slave-bin.000001	1774	Query	1	1864	use `test`; insert into t1 values (296)
slave-bin.000001	1864	Xid	1	1891	COMMIT /* xid=81 */
slave-bin.000001	1891	Query	1	1950	BEGIN
slave-bin.000001	1950	Query	1	2040	use `test`; insert into t1 values (295)
slave-bin.000001	2040	Xid	1	2067	COMMIT /* xid=83 */
slave-bin.000001	2067	Query	1	2126	BEGIN

URL: http://pb2.norway.sun.com/web.py?template=mysql_show_test_failure&search=yes&push_id=73965...
Push: http://pb2.norway.sun.com/web.py?template=push_details&push=739652
[7 Dec 2009 2:28] Luis Soares
Ignore previous comment. This was meant for BUG#49492.