MySQL Bugs: #37939: rpl_row_stop_middle

Bug #37939	rpl_row_stop_middle_update fails on pushbuild
Submitted:	7 Jul 2008 16:42	Modified:	9 Jul 2008 19:22
Reporter:	Sven Sandberg	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	Tests: Replication	Severity:	S7 (Test Cases)
Version:	6.0-rpl	OS:	Any
Assigned to:	Mats Kindahl	CPU Architecture:	Any
Tags:	pushbuild, rpl_row_stop_middle_update, test failure

Description:
rpl_row_stop_middle_update fails on pushbuild with this error:

rpl.rpl_row_stop_middle_update [ fail ]

CURRENT_TEST: rpl.rpl_row_stop_middle_update
--- /data0/pushbuild/pb/bzr_mysql-6.0-rpl/15/bzr_mysql-6.0-rpl-exp/mysql-test/suite/rpl/r/rpl_row_stop_middle_update.result	2008-06-23 11:18:04.000000000 +0300
+++ /data0/pushbuild/pb/bzr_mysql-6.0-rpl/15/bzr_mysql-6.0-rpl-exp/mysql-test/suite/rpl/r/rpl_row_stop_middle_update.reject	2008-06-23 12:17:29.000000000 +0300
@@ -9,8 +9,43 @@
 select count(*) from t1;
 count(*)
 70
-select count(*) from t1;
-count(*)
-70
-drop table t1;
-drop table t1;
+"Failed while waiting for slave to stop"
+SHOW SLAVE STATUS;
+Slave_IO_State	#
+Master_Host	127.0.0.1
+Master_User	root
+Master_Port	MASTER_PORT
+Connect_Retry	1
+Master_Log_File	master-bin.000001
+Read_Master_Log_Pos	#
+Relay_Log_File	#
+Relay_Log_Pos	#
+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	0
+Last_Error	
+Skip_Counter	0
+Exec_Master_Log_Pos	#
+Relay_Log_Space	#
+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	

mysqltest: In included file "./include/wait_for_slave_to_stop.inc": Result length mismatch

Warnings from just before the error:
Note 1051 Unknown table 't1' 
Note 1051 Unknown table 't2' 
Note 1051 Unknown table 't3' 
Note 1051 Unknown table 't4' 
Note 1051 Unknown table 't5' 
Note 1051 Unknown table 't6' 
Note 1051 Unknown table 't7' 
Note 1051 Unknown table 't8' 

Stopping all servers...
Saving datadirs...
 - saving '/dev/shm/var-ps_row-132/mysqld.1'
 - saving '/dev/shm/var-ps_row-132/mysqld.2'
Resuming tests...

Retrying, attempt(1/3)...

Restarting all servers

How to repeat:
E.g., here:
https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-6.0-rpl&order=22
'sapsrv1' Autopush/ps_row

See also xref: http://tinyurl.com/6bo8hx

Note that it has only failed in the 6.0-rpl tree.

I see nothing strange in the test case and can't repeat it manually. It would be really useful to have the binlog for a failing run of the test.

Waiting to fix until mtr/pushbuild can save binlogs.

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

2674 Mats Kindahl	2008-07-08
      Bug #37939  	rpl_row_stop_middle_update fails sporadically on pushbuild
      Bug #37940  	rpl_dual_pos_advance fails sporadically on pushbuild,fail wait_for_slave_to_stop
      Bug #37941  	rpl_flushlog_loop fails sporadically on pushbuild
      
      Several tests fail when waiting for the slave to stop in what
      appears to be timeouts caused by a timeout value set to low. 
      This causes false failures when the servers are loaded.
      
      In order to try to avoid false negatives, we increase the
      timeout 10 times and also print some more information in the
      event that the slave fails to stop when expected to.
      
      We add a printout of the current processes running to be able
      to see if any process have been executing for an unexpectedly
      long time, and also print the binlog events at the position
      indicated by SHOW SLAVE STATUS.

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

2620 Mats Kindahl	2008-07-08
      Bug #37939    rpl_row_stop_middle_update fails sporadically on pushbuild
      Bug #37940    rpl_dual_pos_advance fails sporadically on pushbuild,fail wait_for_slave_to_stop
      Bug #37941    rpl_flushlog_loop fails sporadically on pushbuild
        
      Several tests fail when waiting for the slave to stop in what
      appears to be timeouts caused by a timeout value set to low. 
      This causes false failures when the servers are loaded.
        
      In order to try to avoid false negatives, we increase the
      timeout 10 times and also print some more information in the
      event that the slave fails to stop when expected to.
        
      We add a printout of the current processes running to be able
      to see if any process have been executing for an unexpectedly
      long time, and also print the binlog events at the position
      indicated by SHOW SLAVE STATUS.

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

2620 Mats Kindahl	2008-07-08
      Bug #37939    rpl_row_stop_middle_update fails sporadically on pushbuild
      Bug #37940    rpl_dual_pos_advance fails sporadically on pushbuild,fail wait_for_slave_to_stop
      Bug #37941    rpl_flushlog_loop fails sporadically on pushbuild
        
      Several tests fail when waiting for the slave to stop in what
      appears to be timeouts caused by a timeout value set to low. 
      This causes false failures when the servers are loaded.
        
      In order to try to avoid false negatives, we increase the
      timeout 10 times and also print some more information in the
      event that the slave fails to stop when expected to.
        
      We add a printout of the current processes running to be able
      to see if any process have been executing for an unexpectedly
      long time, and also print the binlog events at the position
      indicated by SHOW SLAVE STATUS.

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

2620 Mats Kindahl	2008-07-08
      Bug #37939    rpl_row_stop_middle_update fails sporadically on pushbuild
      Bug #37940    rpl_dual_pos_advance fails sporadically on pushbuild,fail wait_for_slave_to_stop
      Bug #37941    rpl_flushlog_loop fails sporadically on pushbuild
        
      Several tests fail when waiting for the slave to stop in what
      appears to be timeouts caused by a timeout value set to low. 
      This causes false failures when the servers are loaded.
        
      In order to try to avoid false negatives, we increase the
      timeout 10 times and also print some more information in the
      event that the slave fails to stop when expected to.
        
      We add a printout of the current processes running to be able
      to see if any process have been executing for an unexpectedly
      long time, and also print the binlog events at the position
      indicated by SHOW SLAVE STATUS.

The test is not sporadic, if fails for all ps_row runs in the indicated push. The reason for the failure is that the test holds a "source include/wait_for_slave_to_stop.inc", which will wait for both the I/O thread and the SQL thread to stop. However, the test set the debug flag STOP_SLAVE_after_first_Rows_event, which will only stop the SQL thread (by setting the rli->abort_slave = 1). Since only one of the threads has stopped, this wait will not terminate, causing the failure.

The test is already changed so that this error does not occur any more.

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:mats@mysql.com-20080708162102-qbyxyqv4g1kc5seg) (merge vers: 5.1.28) (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)