Bug #41186 rpl_stm_mystery22 fails sporadically on pushbuild while waiting for slave start
Submitted: 2 Dec 2008 20:54 Modified: 2 Jan 18:07
Reporter: Sven Sandberg
Status: Duplicate
Category:Tests: Replication Severity:S2 (Serious)
Version:6.0-rpl, 5.1 OS:Any
Assigned to: Serge Kozlov Target Version:5.1+
Tags: test failure, pushbuild, sporadic, 6.0-rpl-green
Triage: Triaged: D3 (Medium)

[2 Dec 2008 20:54] Sven Sandberg 
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
[7 Dec 2008 21:44] Serge Kozlov 
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.
[7 Dec 2008 22:22] 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/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.
[12 Dec 2008 12:41] 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/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.
[12 Dec 2008 14:08] 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/61480

2751 Serge Kozlov	2008-12-12 [merge]
      Merge. Bug#40142, Bug#41108, Bug#41186
[15 Dec 2008 10:23] 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/61645

2743 He Zhenxing	2008-12-15 [merge]
      Auto merge
[19 Dec 2008 9:29] Sven Sandberg 
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.
[2 Jan 15:20] Sven Sandberg 
The failure showed up once again in 6.0-rpl after the above patch was pushed (see xref),
with the same symptom as before.
[2 Jan 18:07] Sven Sandberg 
This is a duplicate of BUG#37718. See my comment on BUG#37718 from Jan 2 18:06.
[30 Jan 14:30] Bugs System 
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)
[30 Jan 16:10] Bugs System 
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)
[17 Feb 15:59] Bugs System 
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)
[17 Feb 17:46] Bugs System 
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)
[17 Feb 19:22] Bugs System 
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)