MySQL Bugs: #41186: rpl_stm_mystery22 fails sporadically on pushbuild while waiting for slave start

Bug #41186	rpl_stm_mystery22 fails sporadically on pushbuild while waiting for slave start
Submitted:	2 Dec 2008 19:54	Modified:	2 Jan 2009 17:07
Reporter:	Sven Sandberg	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	Tests: Replication	Severity:	S7 (Test Cases)
Version:	6.0-rpl, 5.1	OS:	Any
Assigned to:	Assigned Account	CPU Architecture:	Any
Tags:	6.0-rpl-green, pushbuild, sporadic, test failure

Description:
Sporadic test failure in 6.0-rpl:

rpl.rpl_stm_mystery22                    [ fail ]

CURRENT_TEST: rpl.rpl_stm_mystery22
--- e:/pb/bzr_mysql-6.0-rpl/77/mysql-6.0.8-alpha-pb77/mysql-test/suite/rpl/r/rpl_stm_mystery22.result	2008-09-23 19:14:42.000000000 +0300
+++ e:\pb\bzr_mysql-6.0-rpl\77\mysql-6.0.8-alpha-pb77\mysql-test\suite\rpl\r\rpl_stm_mystery22.reject	2008-09-23 23:05:33.622817500 +0300
@@ -14,18 +14,74 @@
 2	old
 delete from t1 where n = 2;
 start slave;
-stop slave;
-create table t2(n int);
-drop table t2;
-insert into t1 values(NULL,'new');
-set sql_log_bin=0;
-insert into t1 values(NULL,'new');
-set sql_log_bin=1;
-delete from t1 where n=4;
-start slave;
-select * from t1 order by n;
-n	s
-1	new
-2	new
-3	new
-drop table t1;
+**** ERROR: failed while waiting for slave parameter Slave_SQL_Running = Yes ****
+Message: Failed while waiting for slave to start
+Note: the following output may have changed since the failure was detected
+**** Showing SLAVE STATUS, PROCESSLIST, and BINLOG EVENTS on slave ****
+SHOW SLAVE STATUS;
+Slave_IO_State	Waiting for master to send event
+Master_Host	127.0.0.1
+Master_User	root
+Master_Port	12510
+Connect_Retry	1
+Master_Log_File	master-bin.000001
+Read_Master_Log_Pos	479
+Relay_Log_File	slave-relay-bin.000003
+Relay_Log_Pos	502
+Relay_Master_Log_File	master-bin.000001
+Slave_IO_Running	Yes
+Slave_SQL_Running	No
+Replicate_Do_DB	
+Replicate_Ignore_DB	
+Replicate_Do_Table	
+Replicate_Ignore_Table	
+Replicate_Wild_Do_Table	
+Replicate_Wild_Ignore_Table	
+Last_Errno	1062
+Last_Error	Error 'Duplicate entry '2' for key 'PRIMARY'' on query. Default database: 'test'. Query: 'insert into t1 values(NULL,'new')'
+Skip_Counter	0
+Exec_Master_Log_Pos	355
+Relay_Log_Space	782
+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	1062
+Last_SQL_Error	Error 'Duplicate entry '2' for key 'PRIMARY'' on query. Default database: 'test'. Query: 'insert into t1 values(NULL,'new')'
+Replicate_Ignore_Server_Ids	
+Master_Server_Id	1
+SHOW PROCESSLIST;
+Id	User	Host	db	Command	Time	State	Info
+2	root	localhost:23699	test	Query	0	NULL	SHOW PROCESSLIST
+3	root	localhost:23700	test	Sleep	333	NULL	NULL
+4	system user		NULL	Connect	333	Waiting for master to send event	NULL
+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.8-alpha-pb77-log, Binlog ver: 4
+slave-bin.000001	107	Query	1	231	use `test`; create table t1(n int auto_increment primary key, s char(10))
+slave-bin.000001	231	Query	2	325	use `test`; insert into t1 values (2,'old')
+slave-bin.000001	325	Intvar	1	353	INSERT_ID=1
+slave-bin.000001	353	Query	1	449	use `test`; insert into t1 values(NULL,'new')
+slave-bin.000001	449	Query	2	538	use `test`; delete from t1 where n = 2
+**** Showing MASTER STATUS, PROCESSLIST, and BINLOG EVENTS on master ****
+[on master]
+SHOW MASTER STATUS;
+File	master-bin.000001
+Position	479
+Binlog_Do_DB	
+Binlog_Ignore_DB	
+SHOW PROCESSLIST;
+Id	User	Host	db	Command	Time	State	Info
+22	root	localhost:23696	test	Sleep	334	NULL	NULL
+23	root	localhost:23697	test	Query	0	NULL	SHOW PROCESSLIST
+24	root	localhost:23698	test	Sleep	334	NULL	NULL
+25	root	localhost:23701	NULL	Binlog Dump	333	Master has sent all binlog to slave; waiting for binlog to be updated	NULL

mysqltest: In included file ".\include\wait_for_slave_param.inc": Result content mismatch

 - saving 'e:/pb/bzr_mysql-6.0-rpl/77/mysql-6.0.8-alpha-pb77/mysql-test/var-n_mix-5/2/log/rpl.rpl_stm_mystery22/' to 'e:/pb/bzr_mysql-6.0-rpl/77/mysql-6.0.8-alpha-pb77/mysql-test/var-n_mix-5/log/rpl.rpl_stm_mystery22/'

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

cygpath -m e:/pb/bzr_mysql-6.0-rpl/77/mysql-6.0.8-alpha-pb77/sql/relwithdebinfo/mysqld.exe

How to repeat:
https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-6.0-rpl&order=91 pb-valgrind/n_mix
xref: http://tinyurl.com/68gkqr

Possible reason of error is following code:

insert into t1 values(NULL,'new');
insert into t1 values(NULL,'new');
save_master_pos;
connection slave;
# wait until the slave tries to run the query, fails and abort slave thread
source include/wait_for_slave_sql_error.inc

Last line waits any SQL error therefore any unexpected SQL error will passed by test code as correct. We need to wait exact error number.

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/60838

2747 Serge Kozlov	2008-12-08
      Bug#41186: Possible reason of bug is waiting any sql error on slave instead
      exact number of error. The patch does following:
      1) Add new parameter $slave_sql_errno for wait_for_slave_sql_error.inc
      2) Add waiting error 1062 (Duplicate PK) for slave SQL thread in test case.

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/61471

2708 Serge Kozlov	2008-12-12
      Bug#41186: Possible reason of bug is waiting any sql error on slave instead
      exact number of error. The patch does following:
      1) Add new parameter $slave_sql_errno for wait_for_slave_sql_error.inc
      2) Add waiting error 1062 (Duplicate PK) for slave SQL thread in test case.

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/61480

2751 Serge Kozlov	2008-12-12 [merge]
      Merge. Bug#40142, Bug#41108, Bug#41186

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/61645

2743 He Zhenxing	2008-12-15 [merge]
      Auto merge

The bug causing this test to fail has not been fixed. However, the test has been rewritten so that the next failure will give a message pointing to the reason for the failure. Since it will fail with different symptoms, we will open a new bug for that and close the present bug.

The failure showed up once again in 6.0-rpl after the above patch was pushed (see xref), with the same symptom as before.

This is a duplicate of BUG#37718. See my comment on BUG#37718 from Jan 2 18:06.

Pushed into 6.0.10-alpha (revid:luis.soares@sun.com-20090129165607-wiskabxm948yx463) (version source revid:luis.soares@sun.com-20090129163120-e2ntks4wgpqde6zt) (merge vers: 6.0.10-alpha) (pib:6)

Pushed into 5.1.32 (revid:luis.soares@sun.com-20090129165946-d6jnnfqfokuzr09y) (version source revid:alfranio.correia@sun.com-20081213194819-3u93g1xpzyy18u28) (merge vers: 5.1.31) (pib:6)

Pushed into 5.1.32-ndb-6.3.23 (revid:tomas.ulin@sun.com-20090217131017-6u8qz1edkjfiobef) (version source revid:tomas.ulin@sun.com-20090203133556-9rclp06ol19bmzs4) (merge vers: 5.1.32-ndb-6.3.22) (pib:6)

Pushed into 5.1.32-ndb-6.4.3 (revid:tomas.ulin@sun.com-20090217134419-5ha6xg4dpedrbmau) (version source revid:tomas.ulin@sun.com-20090203133556-9rclp06ol19bmzs4) (merge vers: 5.1.32-ndb-6.3.22) (pib:6)

Pushed into 5.1.32-ndb-6.2.17 (revid:tomas.ulin@sun.com-20090217134216-5699eq74ws4oxa0j) (version source revid:tomas.ulin@sun.com-20090201210519-vehobc4sy3g9s38e) (merge vers: 5.1.32-ndb-6.2.17) (pib:6)