Bug #49492 rpl_semi_sync failed on PB2
Submitted: 7 Dec 2009 2:25 Modified: 5 Jul 2010 17:55
Reporter: Luis Soares Email Updates:
Status: Closed Impact on me:
None 
Category:Tests: Replication Severity:S3 (Non-critical)
Version:next-mr, mysql-pe OS:Any
Assigned to: Zhenxing He CPU Architecture:Any

[7 Dec 2009 2:25] Luis Soares
Description:
rpl_semi_sync failed on PB2 on mysql-next-mr tree.

Failure context:

Where 	Build 	Test 	Run 	Suite 	Case 	Mode 	When
mysql-next-mr
710218	binary-debug_max-sles11-x86-tar-gz
710484 loki36	test-debug_max-sles11-x86
719290 loki36	ps_row	rpl	rpl_semi_sync	None	2009-11-25 14:41:51

Failure symptom:

CURRENT_TEST: rpl.rpl_semi_sync
--- /export/home2/pb2/test/sb_1-1003439-1259558722.33/mysql-5.6.0-beta-linux-i686-test/mysql-test/suite/rpl/r/rpl_semi_sync.result	2009-11-25 17:52:30.000000000 +0300
+++ /export/home2/pb2/test/sb_1-1003439-1259558722.33/mysql-5.6.0-beta-linux-i686-test/mysql-test/suite/rpl/r/rpl_semi_sync.reject	2009-11-30 09:49:21.000000000 +0300
@@ -434,7 +434,2556 @@
 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;
-drop user rpl@127.0.0.1;
-flush privileges;
+**** ERROR: timeout after 3000 deci-seconds while waiting for slave parameter Slave_IO_Running = Yes ****
+Message: Failed while waiting for slave to start
+Current connection is 'slave'
+Note: the following output may have changed since the failure was detected
+
+[on slave]
+
+**** SHOW SLAVE STATUS on slave ****
+SHOW SLAVE STATUS;
+Slave_IO_State	
+Master_Host	127.0.0.1
+Master_User	rpl
+Master_Port	13000
+Connect_Retry	1
+Master_Log_File	master-bin.000001
+Read_Master_Log_Pos	787
+Relay_Log_File	slave-relay-bin.000005
+Relay_Log_Pos	254
+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	787
+Relay_Log_Space	727
+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	NULL
+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 on slave ****
+SHOW PROCESSLIST;
+Id	User	Host	db	Command	Time	State	Info
+2	root	localhost:50989	test	Query	0	NULL	SHOW PROCESSLIST
+3	root	localhost:50990	test	Sleep	333		NULL
+25	system user		NULL	Connect	303	Slave has read all relay log; waiting for the slave I/O thread to update it	NULL
+
+**** SHOW BINLOG EVENTS on slave ****
+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: 5.6.0-beta-debug-log, Binlog ver: 4
+slave-bin.000001	107	Query	1	166	BEGIN
+slave-bin.000001	166	Table_map	1	223	table_id: 23 (mtr.test_suppressions)
+slave-bin.000001	223	Write_rows	1	289	table_id: 23 flags: STMT_END_F
+slave-bin.000001	289	Query	1	349	COMMIT
+slave-bin.000001	349	Query	2	416	BEGIN
+slave-bin.000001	416	Table_map	2	473	table_id: 23 (mtr.test_suppressions)
+slave-bin.000001	473	Write_rows	2	544	table_id: 23 flags: STMT_END_F
+slave-bin.000001	544	Query	2	612	COMMIT
+slave-bin.000001	612	Query	2	679	BEGIN
+slave-bin.000001	679	Table_map	2	736	table_id: 23 (mtr.test_suppressions)
+slave-bin.000001	736	Write_rows	2	791	table_id: 23 flags: STMT_END_F
+slave-bin.000001	791	Query	2	859	COMMIT
+slave-bin.000001	859	Query	1	960	use `test`; create table t1(a int) engine = InnoDB
+slave-bin.000001	960	Query	1	1019	BEGIN
+slave-bin.000001	1019	Table_map	1	1060	table_id: 24 (test.t1)
+slave-bin.000001	1060	Write_rows	1	1094	table_id: 24 flags: STMT_END_F
+slave-bin.000001	1094	Xid	1	1121	COMMIT /* xid=69 */
+slave-bin.000001	1121	Query	1	1180	BEGIN
+slave-bin.000001	1180	Table_map	1	1221	table_id: 24 (test.t1)
+slave-bin.000001	1221	Write_rows	1	1255	table_id: 24 flags: STMT_END_F
+slave-bin.000001	1255	Xid	1	1282	COMMIT /* xid=71 */

How to repeat:
http://pb2.norway.sun.com/web.py?template=mysql_show_test_failure&search=yes&push_id=71021...

Suggested fix:
n/a
[7 Dec 2009 2:28] 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
[24 Mar 2010 7:11] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/104150

3127 He Zhenxing	2010-03-24
      Bug#49492 rpl_semi_sync failed on PB2
      
      After stopped slave, it is possible that the Dump thread on master
      is still running and locked the semi-sync master plugin, and when
      uninstall the semi-sync master plugin, a plugin busy warning could
      be generated.
      
      Fixed by disabling the warnings when uninstall semi-sync plugin
      on master.
[30 Mar 2010 9:18] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/104605

3131 He Zhenxing	2010-03-30
      Bug#49492 rpl_semi_sync failed on PB2
      
      After stopped slave, it is possible that the Dump thread on master
      is still running and has locked the semi-sync master plugin, and when
      uninstalling the semi-sync master plugin, a plugin busy warning could
      be generated.
      
      Fixed by disabling the warnings when uninstalling semi-sync plugin
      on master.
[15 Jun 2010 8:16] Bugs System
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100615080459-smuswd9ooeywcxuc) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (merge vers: 5.1.47) (pib:16)
[15 Jun 2010 8:33] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100615080558-cw01bzdqr1bdmmec) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (pib:16)
[5 Jul 2010 17:55] Jon Stephens
Changes in test code only; closed without further action.