Bug #50442 MTR check for rpl_sync fails
Submitted: 19 Jan 2010 12:15 Modified: 25 Mar 2010 1:24
Reporter: Alexander Nozdrin Email Updates:
Status: Closed Impact on me:
None 
Category:Tests: Replication Severity:S7 (Test Cases)
Version:5.5.2, Celosia (M3) OS:Any
Assigned to: Luis Manuel Oliveira Soares CPU Architecture:Any

[19 Jan 2010 12:15] Alexander Nozdrin
Description:
rpl.rpl_sync 'mix'                       [ pass ]   2305

MTR's internal check of the test case 'rpl.rpl_sync' failed.
This means that the test case does not preserve the state that existed
before the test case was executed.  Most likely the test case did not
do a proper clean-up.
This is the diff of the states of the servers before and after the
test case was executed:
mysqltest: Logging to '/mnt/raid/alik/MySQL/bzr/00.builds/mysql-next-mr/mysql-test/var/tmp/check-mysqld_2.log'.
mysqltest: Results saved in '/mnt/raid/alik/MySQL/bzr/00.builds/mysql-next-mr/mysql-test/var/tmp/check-mysqld_2.result'.
mysqltest: Connecting to server localhost:13001 (socket /mnt/raid/alik/MySQL/bzr/00.builds/mysql-next-mr/mysql-test/var/tmp/mysqld.2.sock) as 'root', connection 'default', attempt 0 ...
mysqltest: ... Connected.
mysqltest: Start processing test commands from './include/check-testcase.test' ...
mysqltest: ... Done processing test commands.
--- /mnt/raid/alik/MySQL/bzr/00.builds/mysql-next-mr/mysql-test/var/tmp/check-mysqld_2.result   2010-01-19 15:12:04.286002651 +0300
+++ /mnt/raid/alik/MySQL/bzr/00.builds/mysql-next-mr/mysql-test/var/tmp/check-mysqld_2.reject   2010-01-19 15:12:06.866001740 +0300
@@ -82,7 +82,7 @@
 INNODB_DOUBLEWRITE     ON
 INNODB_FAST_SHUTDOWN   1
 INNODB_FILE_FORMAT     Antelope
-INNODB_FILE_FORMAT_CHECK       Antelope
+INNODB_FILE_FORMAT_CHECK       Barracuda
 INNODB_FILE_PER_TABLE  OFF
 INNODB_FLUSH_LOG_AT_TRX_COMMIT 1
 INNODB_FLUSH_METHOD

mysqltest: Result content mismatch

How to repeat:
Run the test case.
[19 Jan 2010 12:53] Valeriy Kravchuk
Same problem with 5.5.2 (trunk):

openxs@suse:/home2/openxs/dbs/trunk/mysql-test> ./mtr rpl_sync
Logging: ./mtr  rpl_sync
100426 19:30:54 [Note] Plugin 'FEDERATED' is disabled.
100426 19:30:54 [Note] Plugin 'ndbcluster' is disabled.
MySQL Version 5.5.2
Checking supported features...
 - using ndbcluster when necessary, mysqld supports it
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
 - adding combinations for rpl
vardir: /home2/openxs/dbs/trunk/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/home2/openxs/dbs/trunk/mysql-test/var'...
Installing system database...
Using server port 32769

==============================================================================

TEST                                      RESULT   TIME (ms)
------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
rpl.rpl_sync 'row'                       [ pass ]   7897

MTR's internal check of the test case 'rpl.rpl_sync' failed.
This means that the test case does not preserve the state that existed
before the test case was executed.  Most likely the test case did not
do a proper clean-up.
This is the diff of the states of the servers before and after the
test case was executed:
mysqltest: Logging to '/home2/openxs/dbs/trunk/mysql-test/var/tmp/check-mysqld_2.log'.
mysqltest: Results saved in '/home2/openxs/dbs/trunk/mysql-test/var/tmp/check-mysqld_2.result'.
mysqltest: Connecting to server localhost:13001 (socket /home2/openxs/dbs/trunk/mysql-test/var/tmp/mysqld.2.sock) as 'root', connection 'default', attempt 0 ...
mysqltest: ... Connected.
mysqltest: Start processing test commands from './include/check-testcase.test' ...
mysqltest: ... Done processing test commands.
--- /home2/openxs/dbs/trunk/mysql-test/var/tmp/check-mysqld_2.result  2010-04-26 19:31:07.000000000 +0300
+++ /home2/openxs/dbs/trunk/mysql-test/var/tmp/check-mysqld_2.reject  2010-04-26 19:31:17.000000000 +0300
@@ -84,7 +84,7 @@
 INNODB_DOUBLEWRITE     ON
 INNODB_FAST_SHUTDOWN   1
 INNODB_FILE_FORMAT     Antelope
-INNODB_FILE_FORMAT_CHECK       Antelope
+INNODB_FILE_FORMAT_CHECK       Barracuda
 INNODB_FILE_PER_TABLE  OFF
 INNODB_FLUSH_LOG_AT_TRX_COMMIT 1
 INNODB_FLUSH_METHOD

mysqltest: Result content mismatch

not ok
...
[19 Jan 2010 16:19] Luis Manuel Oliveira Soares
See also: BUG#49792.
[19 Jan 2010 16:54] Luis Manuel Oliveira Soares
I have briefly looked into this. The test case crashes and recovers 
the server twice, and while recovering InnoDB outputs: 

"InnoDB: highest supported file format is Barracuda."

My theory is that the variable changes during recovery
at some point. However it is unclear to me.

The following patch seems to make the original server to start 
with the current highest value ('Barracuda'?) thence, makes the 
warning go away:

=== modified file 'mysql-test/suite/rpl/t/rpl_sync-slave.opt'
--- mysql-test/suite/rpl/t/rpl_sync-slave.opt	2009-09-29 14:40:52 +0000
+++ mysql-test/suite/rpl/t/rpl_sync-slave.opt	2010-01-19 16:32:09 +0000
@@ -1,1 +1,1 @@
---sync-relay-log-info=1 --relay-log-recovery=1
+--sync-relay-log-info=1 --relay-log-recovery=1 --innodb_file_format_check='ON'
[22 Jan 2010 13:13] Luis Manuel Oliveira Soares
The following test case (narrowed down from rpl_sync), triggers the issue. However, if the second part of test (CRASH #2) is removed - ie server just crashes and recovers once and not twice, then there is no issue.

======================================================

--source include/master-slave.inc
--source include/not_embedded.inc
--source include/not_valgrind.inc
--source include/have_debug.inc
--source include/have_innodb.inc

--connection slave
call mtr.add_suppression('Attempting backtrace');
call mtr.add_suppression("Recovery from master pos .* and file master-bin.00000.*");

### CRASH #1

--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.2.expect
SET SESSION debug="d,crash_before_rotate_relaylog";
--error 2013
FLUSH LOGS;
--enable_reconnect
--source include/wait_until_connected_again.inc
start slave;
source include/wait_for_slave_to_start.inc;

### CRASH #2

--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.2.expect
SET SESSION debug="d,crash_before_rotate_relaylog";
--error 2013
FLUSH LOGS;
--enable_reconnect
--source include/wait_until_connected_again.inc
start slave;
source include/wait_for_slave_to_start.inc;

-- exit

======================================================
[22 Jan 2010 14:47] Luis Manuel Oliveira Soares
I can also reproduce by repeating a test case without replication enabled, but crashes and restarts the server. Just start it like this (mind the --repeat=2):

./mtr --repeat=2 crash_commit_before
[10 Mar 2010 12:40] 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/102876

2990 Luis Soares	2010-03-10
      BUG#50442: MTR check for rpl_sync fails
      
      The test case crashes and recovers the server twice, and while 
      recovering InnoDB sets innodb_file_format_check to different
      format on second restart. This makes the test case clean up
      check to fail.
      
      We fix this by deploying the option "--innodb_file_format_check='ON'"
      in slave startup configuration. This makes the innodb_file_format_check
      to not change on secod restart.
[24 Mar 2010 8:15] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100324081249-yfwol7qtcek6dh7w) (version source revid:alik@sun.com-20100324081113-kc7x1iytnplww91u) (merge vers: 6.0.14-alpha) (pib:16)
[24 Mar 2010 8:16] Bugs System
Pushed into 5.5.4-m3 (revid:alik@sun.com-20100324081056-6bndv6f0nrvbblhp) (version source revid:alik@sun.com-20100324081056-6bndv6f0nrvbblhp) (merge vers: 5.5.4-m3) (pib:16)
[24 Mar 2010 8:18] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100324081159-5b8juv8ldiqwce8v) (version source revid:alik@sun.com-20100324081105-y72rautcea375zxm) (pib:16)
[25 Mar 2010 1:24] Paul DuBois
Changes to test suite. No changelog entry needed.