Bug #31554 rpl_truncate_2myisam,rpl_truncate_3innodb tests failure: wrong binlog index
Submitted: 12 Oct 2007 6:54 Modified: 27 Nov 2007 18:47
Reporter: Timothy Smith Email Updates:
Status: Closed
Category:Server: Tests Severity:S2 (Serious)
Version:5.1, 5.2 OS:Microsoft Windows
Assigned to: Andrei Elkin Target Version:5.1+
Tags: pbfail, binlog_delete_nt

[12 Oct 2007 6:54] Timothy Smith 
Description:
rpl.rpl_truncate_2myisam       [ fail ]

---
e:/pb/mysql-5.2-maint/18/mysql-5.2.6-alpha-pb18/mysql-test/suite/rpl/r/rpl_truncate_2myisam.result	2007-10-12
03:25:47.000000000 +0300
+++
e:\pb\mysql-5.2-maint\18\mysql-5.2.6-alpha-pb18\mysql-test\suite\rpl\r\rpl_truncate_2myisam.reject	2007-10-12
04:32:00.177750000 +0300
@@ -31,10 +31,10 @@
 DROP TABLE t1;
 show binlog events from <binlog_start>;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
-master-bin.000001	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT, b LONG) ENGINE=MyISAM
-master-bin.000001	#	Query	#	#	use `test`; INSERT INTO t1 VALUES (1,1), (2,2)
-master-bin.000001	#	Query	#	#	use `test`; TRUNCATE TABLE t1
-master-bin.000001	#	Query	#	#	use `test`; DROP TABLE t1
+master-bin.000002	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT, b LONG) ENGINE=MyISAM
+master-bin.000002	#	Query	#	#	use `test`; INSERT INTO t1 VALUES (1,1), (2,2)
+master-bin.000002	#	Query	#	#	use `test`; TRUNCATE TABLE t1
+master-bin.000002	#	Query	#	#	use `test`; DROP TABLE t1
 **** On Master ****
 SET SESSION BINLOG_FORMAT=MIXED;
 SET GLOBAL  BINLOG_FORMAT=MIXED;
@@ -62,10 +62,10 @@
 DROP TABLE t1;
 show binlog events from <binlog_start>;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
-master-bin.000001	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT, b LONG) ENGINE=MyISAM
-master-bin.000001	#	Query	#	#	use `test`; INSERT INTO t1 VALUES (1,1), (2,2)
-master-bin.000001	#	Query	#	#	use `test`; TRUNCATE TABLE t1
-master-bin.000001	#	Query	#	#	use `test`; DROP TABLE t1
+master-bin.000002	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT, b LONG) ENGINE=MyISAM
+master-bin.000002	#	Query	#	#	use `test`; INSERT INTO t1 VALUES (1,1), (2,2)
+master-bin.000002	#	Query	#	#	use `test`; TRUNCATE TABLE t1
+master-bin.000002	#	Query	#	#	use `test`; DROP TABLE t1
 **** On Master ****
 SET SESSION BINLOG_FORMAT=ROW;
 SET GLOBAL  BINLOG_FORMAT=ROW;
@@ -93,11 +93,11 @@
 DROP TABLE t1;
 show binlog events from <binlog_start>;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
-master-bin.000001	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT, b LONG) ENGINE=MyISAM
-master-bin.000001	#	Table_map	#	#	table_id: # (test.t1)
-master-bin.000001	#	Write_rows	#	#	table_id: # flags: STMT_END_F
-master-bin.000001	#	Query	#	#	use `test`; TRUNCATE TABLE t1
-master-bin.000001	#	Query	#	#	use `test`; DROP TABLE t1
+master-bin.000002	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT, b LONG) ENGINE=MyISAM
+master-bin.000002	#	Table_map	#	#	table_id: # (test.t1)
+master-bin.000002	#	Write_rows	#	#	table_id: # flags: STMT_END_F
+master-bin.000002	#	Query	#	#	use `test`; TRUNCATE TABLE t1
+master-bin.000002	#	Query	#	#	use `test`; DROP TABLE t1
 **** On Master ****
 SET SESSION BINLOG_FORMAT=STATEMENT;
 SET GLOBAL  BINLOG_FORMAT=STATEMENT;
@@ -125,10 +125,10 @@
 DROP TABLE t1;
 show binlog events from <binlog_start>;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
-master-bin.000001	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT, b LONG) ENGINE=MyISAM
-master-bin.000001	#	Query	#	#	use `test`; INSERT INTO t1 VALUES (1,1), (2,2)
-master-bin.000001	#	Query	#	#	use `test`; DELETE FROM t1
-master-bin.000001	#	Query	#	#	use `test`; DROP TABLE t1
+master-bin.000002	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT, b LONG) ENGINE=MyISAM
+master-bin.000002	#	Query	#	#	use `test`; INSERT INTO t1 VALUES (1,1), (2,2)
+master-bin.000002	#	Query	#	#	use `test`; DELETE FROM t1
+master-bin.000002	#	Query	#	#	use `test`; DROP TABLE t1
 **** On Master ****
 SET SESSION BINLOG_FORMAT=MIXED;
 SET GLOBAL  BINLOG_FORMAT=MIXED;
@@ -156,10 +156,10 @@
 DROP TABLE t1;
 show binlog events from <binlog_start>;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
-master-bin.000001	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT, b LONG) ENGINE=MyISAM
-master-bin.000001	#	Query	#	#	use `test`; INSERT INTO t1 VALUES (1,1), (2,2)
-master-bin.000001	#	Query	#	#	use `test`; DELETE FROM t1
-master-bin.000001	#	Query	#	#	use `test`; DROP TABLE t1
+master-bin.000002	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT, b LONG) ENGINE=MyISAM
+master-bin.000002	#	Query	#	#	use `test`; INSERT INTO t1 VALUES (1,1), (2,2)
+master-bin.000002	#	Query	#	#	use `test`; DELETE FROM t1
+master-bin.000002	#	Query	#	#	use `test`; DROP TABLE t1
 **** On Master ****
 SET SESSION BINLOG_FORMAT=ROW;
 SET GLOBAL  BINLOG_FORMAT=ROW;
@@ -188,9 +188,9 @@
 DROP TABLE t1;
 show binlog events from <binlog_start>;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
-master-bin.000001	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT, b LONG) ENGINE=MyISAM
-master-bin.000001	#	Table_map	#	#	table_id: # (test.t1)
-master-bin.000001	#	Write_rows	#	#	table_id: # flags: STMT_END_F
-master-bin.000001	#	Table_map	#	#	table_id: # (test.t1)
-master-bin.000001	#	Delete_rows	#	#	table_id: # flags: STMT_END_F
-master-bin.000001	#	Query	#	#	use `test`; DROP TABLE t1
+master-bin.000002	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT, b LONG) ENGINE=MyISAM
+master-bin.000002	#	Table_map	#	#	table_id: # (test.t1)
+master-bin.000002	#	Write_rows	#	#	table_id: # flags: STMT_END_F
+master-bin.000002	#	Table_map	#	#	table_id: # (test.t1)
+master-bin.000002	#	Delete_rows	#	#	table_id: # flags: STMT_END_F
+master-bin.000002	#	Query	#	#	use `test`; DROP TABLE t1

mysqltest: Result content mismatch

Stopping All Servers
Restoring snapshot of databases

How to repeat:
PushBuild shows this happening in MySQL 5.1 and MySQL 5.2.

https://intranet.mysql.com/secure/pushbuild/xref.pl?startdate=&enddate=&dir=&plat=&testtyp...

The first instance of it is in mysql-5.1-win on 2006-11-15:

https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=mysql-5.1-win&order=18

The vast majority of failures are on Windows hosts, but there are a few powermacg5  
failures as well.

Suggested fix:
Remove the race condition.
[24 Oct 2007 10:42] Andrei Elkin 
From the first glance the promblems are the name of a binlog file plus its index seems is
non-deterministic.
[24 Oct 2007 11:25] Andrei Elkin 
Sorry. Just the index is wrong.
[25 Oct 2007 14:26] Andrei Elkin 
I only can contribute with stressing that having bug#31689 does not help to
find out any log for analysis of this bug.
It might be eventually a wrong hit but it can be that there is something similar with Bug
#19208 Test 'rpl000017' hangs on Windows.

Code witnesses the deletion of old binlog files 
  for (;;)
  {
    my_delete_allow_opened(linfo.log_file_name, MYF(MY_WME));
    ...

in the loop does not check the error. So it might be that windows fail
to delete master.000001 for some reason and master.000002 is opened because of that.
[26 Oct 2007 10:53] 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/36425

ChangeSet@1.2584, 2007-10-26 13:52:54+03:00, aelkin@koti.dsl.inet.fi +2 -0
  Bug #31554  	rpl.rpl_truncate_2myisam test failure: wrong master binlog file name
  
  Actually, the failure happened with 3innodb as well. Most probably the reason is in
failing to
  delete a binlog file on __NT__.
  The test results hide valueable warning that windows could generate about that.
  
  The scope of this fix is to make sure we have such warning and
  to lessen chances for binlog file being held at time of closing.
  The dump thread is getting a good chance to leave and 
  release the file for its successful deletion.
[2 Nov 2007 12:00] 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/36982

ChangeSet@1.2584, 2007-11-02 14:00:38+02:00, aelkin@koti.dsl.inet.fi +3 -0
  Bug #31554  	rpl.rpl_truncate_2myisam test failure: wrong master binlog file name
  
  Actually, the failure happened with 3innodb as well. Most probably
  the reason is in failing to delete a binlog file on __NT__ so that
  that master increments the index of the binlog file.
  The test results hide valueable warning that windows could generate
  about that.
  
  The scope of this fix is to make sure we have such warning and
  to lessen chances for binlog file being held at time of closing.
  The dump thread is getting a good chance to leave and 
  release the file for its successful deletion.
  
  We shall watch over the two tests as regression is not excluded.
  In that case we would have an extra info possibly explaining why
  __NT__ env can not close/delete the file.
  However, regardless of that reason, there is alwasy workaround to mask out
  non-deterministic binlog index number.
[27 Nov 2007 10:51] Bugs System 
Pushed into 5.1.23-rc
[27 Nov 2007 10:53] Bugs System 
Pushed into 6.0.4-alpha
[27 Nov 2007 18:47] Paul DuBois 
Test case change. No changelog entry needed.