Bug #40927 rpl.rpl_relay_space_falcon fails when binlog-format is explicitly set to mixed
Submitted: 21 Nov 2008 15:40 Modified: 11 Dec 2008 14:26
Reporter: John Embretsen Email Updates:
Status: Closed Impact on me:
None 
Category:Tests: Replication Severity:S7 (Test Cases)
Version:6.0.9-bzr OS:Any
Assigned to: John Embretsen CPU Architecture:Any
Tags: falcon, pushbuild, test failure

[21 Nov 2008 15:40] John Embretsen
Description:
The test rpl_relay_space_falcon in the rpl test suite fails in Pushbuild (first edition) in certain special configurations.

Example:

COMMAND: SPAWN perl ./mysql-test-run.pl --tmpdir=/dev/shm/pbtmp-n_mix-100 --vardir=/dev/shm/var-n_mix-100 --timer --force --mysqld=--binlog-format=mixed

(...)

rpl.rpl_relay_space_falcon 'stmt' [ fail ]

=== SHOW MASTER STATUS ===
---- 1. ----
File	slave-bin.000001
Position	344
Binlog_Do_DB	
Binlog_Ignore_DB	
==========================

=== SHOW SLAVE STATUS ===
---- 1. ----
Slave_IO_State	Waiting for master to send event
Master_Host	127.0.0.1
Master_User	root
Master_Port	11000
Connect_Retry	1
Master_Log_File	master-bin.000001
Read_Master_Log_Pos	1017
Relay_Log_File	slave-relay-bin.000002
Relay_Log_Pos	381
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	1598
Last_Error	Error 'Binary logging not possible. Message: Statement-based format required for this statement, but not allowed by this combination of engines' on opening tables
Skip_Counter	0
Exec_Master_Log_Pos	234
Relay_Log_Space	1320
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	1598
Last_SQL_Error	Error 'Binary logging not possible. Message: Statement-based format required for this statement, but not allowed by this combination of engines' on opening tables
=========================

mysqltest: In included file "./extra/rpl_tests/rpl_sv_relay_space.test": At line 29: could not sync with master ('select master_pos_wait('master-bin.000001', 1017)' returned NULL)

The result from queries just before the failure was:
stop slave;
drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
reset master;
reset slave;
drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
start slave;
SHOW VARIABLES LIKE 'relay_log_space_limit';
Variable_name	Value
relay_log_space_limit	0
CREATE TABLE t1 (name varchar(64), age smallint(3))ENGINE=Falcon;
INSERT INTO t1 SET name='Andy', age=31;
INSERT INTO t1 SET name='Jacob', age=2;
INSERT INTO t1 SET name='Caleb', age=1;
ALTER TABLE t1 ADD id int(8) ZEROFILL AUTO_INCREMENT PRIMARY KEY;
SELECT * FROM t1 ORDER BY id;
name	age	id
Andy	31	00000001
Jacob	2	00000002
Caleb	1	00000003

More results from queries before failure can be found in /dev/shm/var-n_mix-100/log/rpl_relay_space_falcon.log

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
Restoring snapshot of databases
Resuming Tests

rpl.rpl_relay_space_innodb 'stmt' [ pass ]            252
rpl.rpl_relay_space_myisam 'stmt' [ pass ]            251

--- --- ---

Note that the test seems to only fail in the mysql-test combination [1] 'stmt' when run as part of the rpl suite AND --mysqld=--binlog-format=mixed (cmd line option).

[1]: http://dev.mysql.com/doc/mysqltest/en/writing-tests-binlog-control-global.html

How to repeat:
In mysql-6.0-falcon-team branch, do:

$ cd mysql-test/
$ perl ./mysql-test-run.pl --suite=rpl --force --mysqld=--binlog-format=mixed
[21 Nov 2008 16:30] 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/59573

2915 John H. Embretsen	2008-11-21
      Bug#40926, Bug#40927, Bug#40930: Disabling rpl falcon tests that fail in Pushbuild 
      until failures have been properly analyzed and possibly fixed.
      
      rpl.rpl_extraCol_falcon: Fails on Windows in Pushbuild 2 during STOP SLAVE (bug 40930).
      rpl.rpl_relay_space_falcon: Fails in Pushbuild due to binlog-format settings (bug 40927).
      rpl.rpl_truncate_falcon: Fails in Pushbuild due to binlog-format settings (bug 40926).
[24 Nov 2008 13:33] John Embretsen
This test failure seems to be (at least in part) caused by missing cleanup in a previous test, most likely rpl.rpl_rbr_to_sbr.

The test fails when all of the following conditions are satisifed:
 - combination from suite's combinations file sets --binlog-format=stmt
 - cmd line option: --mysqld=--binlog-format=mixed
 - rpl_rbr_to_sbr does not revert binlog setting modifications (mixed)

The following change makes the rpl_rbr_to_sbr clean up after itself:
http://lists.mysql.com/commits/49805
This change is present in current rpl code branches, but it has not been merged to mysql-6.0, aka. "main" (yet).

If the cleanup patch is applied, the rpl_relay_space_falcon test passes, but the rpl_rbr_to_sbr test fails due to an extra logged event on the slave (probably due to other diffs between rpl branches and the main branch, not sure what to do about that at this time):

 SHOW BINLOG EVENTS;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
 slave-bin.000001	#	Format_desc	2	#	Server ver: VERSION, Binlog ver: 4
+slave-bin.000001	#	Query	2	#	use `test`; drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9
 slave-bin.000001	#	Query	1	#	use `test`; CREATE TABLE t1 (a INT, b LONG)
 slave-bin.000001	#	Query	1	#	use `test`; INSERT INTO t1 VALUES (1,1), (2,2)
 slave-bin.000001	#	Query	1	#	use `test`; BEGIN

mysqltest: Result content mismatch

Some more analysis is needed to understand exactly why binlog format on the slave is set to 'stmt' (while and the check for 'row' or 'mixed' in the beginning of the test does not cause the test to be skipped).
[27 Nov 2008 10:09] John Embretsen
Adding cleanup code to the rpl_rbr_to_sbr test will most likely resolve this issue (see diff below).

Workaround: Do not run rpl suite with combinations enabled *and* cmd line option --mysqld=--binlog-format=mixed in Pushbuild.

Note that this fix is already present in mysql-6.0-rpl branch (original 5.1 push mail: http://lists.mysql.com/commits/49806). I see the following alternative approaches to fixing this:

1) Check in cleanup fix to mysql-6.0-falcon-team branch (merged regularly into main). Potential merge conflicts(?) to be handled later, when rpl branches are merged to 6.0 main.

2) Remove test from mysql-6.0-falcon-team branch and add it to mysql-6.0-rpl branch instead (not merged regularly into main).

3) Keep test disabled until mysql-6.0-rpl testfixes are merged into main.

I will proceed with alternative 1) unless anyone objects.

------ Cleanup diff start -------

=== modified file 'mysql-test/suite/rpl/r/rpl_rbr_to_sbr.result'
--- mysql-test/suite/rpl/r/rpl_rbr_to_sbr.result	2008-04-02 13:14:23 +0000
+++ mysql-test/suite/rpl/r/rpl_rbr_to_sbr.result	2008-11-27 08:49:07 +0000
@@ -4,6 +4,7 @@ reset master;
 reset slave;
 drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
 start slave;
+SET @old_binlog_format= @@global.binlog_format;
 SET BINLOG_FORMAT=MIXED;
 SET GLOBAL BINLOG_FORMAT=MIXED;
 SELECT @@GLOBAL.BINLOG_FORMAT, @@SESSION.BINLOG_FORMAT;
@@ -73,3 +74,4 @@ slave-bin.000001	#	Table_map	1	#	table_i
 slave-bin.000001	#	Write_rows	1	#	table_id: # flags: STMT_END_F
 slave-bin.000001	#	Query	1	#	use `test`; COMMIT
 DROP TABLE IF EXISTS t1;
+SET @@global.binlog_format= @old_binlog_format;

=== modified file 'mysql-test/suite/rpl/t/rpl_rbr_to_sbr.test'
--- mysql-test/suite/rpl/t/rpl_rbr_to_sbr.test	2007-06-27 12:29:10 +0000
+++ mysql-test/suite/rpl/t/rpl_rbr_to_sbr.test	2008-11-27 08:44:08 +0000
@@ -5,6 +5,8 @@
 # Test that the slave temporarily switches to ROW when seeing binrow
 # events when it is in STATEMENT or MIXED mode
 
+SET @old_binlog_format= @@global.binlog_format;
+
 SET BINLOG_FORMAT=MIXED;
 SET GLOBAL BINLOG_FORMAT=MIXED;
 SELECT @@GLOBAL.BINLOG_FORMAT, @@SESSION.BINLOG_FORMAT;
@@ -33,6 +35,7 @@ SHOW BINLOG EVENTS;
 
 connection master;
 DROP TABLE IF EXISTS t1;
+SET @@global.binlog_format= @old_binlog_format;
 
 # Let's compare. Note: If they match test will pass, if they do not match
 # the test will show that the diff statement failed and not reject file

------ Cleanup diff end -------
[27 Nov 2008 15:36] 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/60071

2920 John H. Embretsen	2008-11-27
      Fix for Bug#40927 - rpl.rpl_relay_space_falcon fails when binlog-format is explicitly set to mixed.
        
      Test failed due to BINLOG_FORMAT being set in a previous test (rpl.rpl_rbr_to_sbr), which effectively 'disabled' the check for correct binlog format in rpl.rpl_relay_space_falcon under certain circumstances (Pushbuild).
      This patch makes sure that rpl.rpl_rbr_to_sbr cleans up after itself (stores and re-sets the original binlog-format value).
[1 Dec 2008 8:15] John Embretsen
Patch pushed to mysql-6.0-falcon-team bzr branch.
Date: 2008-11-28 13:56:05 UTC 
Revision: john.embretsen@sun.com-20081127153329-9i4hliwkv1sivq7r
[11 Dec 2008 14:20] Bugs System
Pushed into 6.0.9-alpha  (revid:john.embretsen@sun.com-20081127153329-9i4hliwkv1sivq7r) (version source revid:hky@sun.com-20081205164847-vbocpvlyf6fbxkkj) (pib:5)
[11 Dec 2008 14:26] Paul DuBois
Test case changes. No changelog entry needed.