Bug #59444 rpl_row_show_relaylog_events fails on daily-5.5 test runs
Submitted: 12 Jan 2011 12:28 Modified: 28 Jan 2011 12:23
Reporter: Luis Soares Email Updates:
Status: Closed Impact on me:
None 
Category:Tests: Replication Severity:S3 (Non-critical)
Version: OS:Any
Assigned to: Luis Soares CPU Architecture:Any

[12 Jan 2011 12:28] Luis Soares
Description:
rpl_row_show_relaylog_events fails on daily runs with the following
symptom:

rpl.rpl_row_show_relaylog_events w1 [ fail ]
        Test ended at 2011-01-12 00:23:09

CURRENT_TEST: rpl.rpl_row_show_relaylog_events
--- /export/home2/pb2/test/sb_1-2776615-1294787190.01/mysql-5.5.9-linux-x86_64-test/mysql-test/suite/rpl/r/rpl_row_show_relaylog_events.result	2011-01-11 18:58:51.000000000 +0300
+++ /export/home2/pb2/test/sb_1-2776615-1294787190.01/mysql-5.5.9-linux-x86_64-test/mysql-test/suite/rpl/r/rpl_row_show_relaylog_events.reject	2011-01-12 02:23:09.000000000 +0300
@@ -146,51 +146,51 @@
 slave-bin.000001	#	Write_rows	#	#	table_id: # flags: STMT_END_F
 slave-bin.000001	#	Query	#	#	COMMIT
[SLAVE] ********* SOW RELAYLOG EVENTS IN ... *********
-show relaylog events in 'slave-relay-bin.000002' from <binlog_start>;
+show relaylog events in 'slave-relay-bin.000003' from <binlog_start>;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
-slave-relay-bin.000002	#	Rotate	#	#	master-bin.000001;pos=4
-slave-relay-bin.000002	#	Format_desc	#	#	SERVER_VERSION, BINLOG_VERSION
-slave-relay-bin.000002	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT)
-slave-relay-bin.000002	#	Query	#	#	BEGIN
-slave-relay-bin.000002	#	Table_map	#	#	table_id: # (test.t1)
-slave-relay-bin.000002	#	Write_rows	#	#	table_id: # flags: STMT_END_F
-slave-relay-bin.000002	#	Query	#	#	COMMIT
-slave-relay-bin.000002	#	Query	#	#	BEGIN
-slave-relay-bin.000002	#	Table_map	#	#	table_id: # (test.t1)
-slave-relay-bin.000002	#	Write_rows	#	#	table_id: # flags: STMT_END_F
-slave-relay-bin.000002	#	Query	#	#	COMMIT
-slave-relay-bin.000002	#	Query	#	#	BEGIN
-slave-relay-bin.000002	#	Table_map	#	#	table_id: # (test.t1)
-slave-relay-bin.000002	#	Write_rows	#	#	table_id: # flags: STMT_END_F
-slave-relay-bin.000002	#	Query	#	#	COMMIT
-slave-relay-bin.000002	#	Query	#	#	BEGIN
-slave-relay-bin.000002	#	Table_map	#	#	table_id: # (test.t1)
-slave-relay-bin.000002	#	Write_rows	#	#	table_id: # flags: STMT_END_F
-slave-relay-bin.000002	#	Query	#	#	COMMIT
-slave-relay-bin.000002	#	Query	#	#	BEGIN
-slave-relay-bin.000002	#	Table_map	#	#	table_id: # (test.t1)
-slave-relay-bin.000002	#	Write_rows	#	#	table_id: # flags: STMT_END_F
-slave-relay-bin.000002	#	Query	#	#	COMMIT
-slave-relay-bin.000002	#	Query	#	#	BEGIN
-slave-relay-bin.000002	#	Table_map	#	#	table_id: # (test.t1)
-slave-relay-bin.000002	#	Write_rows	#	#	table_id: # flags: STMT_END_F
-slave-relay-bin.000002	#	Query	#	#	COMMIT
+slave-relay-bin.000003	#	Rotate	#	#	master-bin.000001;pos=4
+slave-relay-bin.000003	#	Format_desc	#	#	SERVER_VERSION, BINLOG_VERSION
+slave-relay-bin.000003	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT)
+slave-relay-bin.000003	#	Query	#	#	BEGIN
+slave-relay-bin.000003	#	Table_map	#	#	table_id: # (test.t1)
+slave-relay-bin.000003	#	Write_rows	#	#	table_id: # flags: STMT_END_F
+slave-relay-bin.000003	#	Query	#	#	COMMIT
+slave-relay-bin.000003	#	Query	#	#	BEGIN
+slave-relay-bin.000003	#	Table_map	#	#	table_id: # (test.t1)
+slave-relay-bin.000003	#	Write_rows	#	#	table_id: # flags: STMT_END_F
+slave-relay-bin.000003	#	Query	#	#	COMMIT
+slave-relay-bin.000003	#	Query	#	#	BEGIN
+slave-relay-bin.000003	#	Table_map	#	#	table_id: # (test.t1)
+slave-relay-bin.000003	#	Write_rows	#	#	table_id: # flags: STMT_END_F
+slave-relay-bin.000003	#	Query	#	#	COMMIT
+slave-relay-bin.000003	#	Query	#	#	BEGIN
+slave-relay-bin.000003	#	Table_map	#	#	table_id: # (test.t1)
+slave-relay-bin.000003	#	Write_rows	#	#	table_id: # flags: STMT_END_F
+slave-relay-bin.000003	#	Query	#	#	COMMIT
+slave-relay-bin.000003	#	Query	#	#	BEGIN
+slave-relay-bin.000003	#	Table_map	#	#	table_id: # (test.t1)
+slave-relay-bin.000003	#	Write_rows	#	#	table_id: # flags: STMT_END_F
+slave-relay-bin.000003	#	Query	#	#	COMMIT
+slave-relay-bin.000003	#	Query	#	#	BEGIN
+slave-relay-bin.000003	#	Table_map	#	#	table_id: # (test.t1)
+slave-relay-bin.000003	#	Write_rows	#	#	table_id: # flags: STMT_END_F
+slave-relay-bin.000003	#	Query	#	#	COMMIT
[SLAVE] ********* SOW RELAYLOG EVENTS *********
 show relaylog events from <binlog_start>;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
-slave-relay-bin.000001	#	Rotate	#	#	slave-relay-bin.000002;pos=4
+slave-relay-bin.000002	#	Rotate	#	#	slave-relay-bin.000003;pos=4
[MASTER] ********* SOW RELAYLOG EVENTS ... LIMIT rows *********
-show relaylog events in 'slave-relay-bin.000002' from <binlog_start> limit 3;
+show relaylog events in 'slave-relay-bin.000003' from <binlog_start> limit 3;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
-slave-relay-bin.000002	#	Rotate	#	#	master-bin.000001;pos=4
-slave-relay-bin.000002	#	Format_desc	#	#	SERVER_VERSION, BINLOG_VERSION
-slave-relay-bin.000002	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT)
+slave-relay-bin.000003	#	Rotate	#	#	master-bin.000001;pos=4
+slave-relay-bin.000003	#	Format_desc	#	#	SERVER_VERSION, BINLOG_VERSION
+slave-relay-bin.000003	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT)
[MASTER] ********* SOW RELAYLOG EVENTS ... LIMIT offset,rows *********
-show relaylog events in 'slave-relay-bin.000002' from <binlog_start> limit 1,3;
+show relaylog events in 'slave-relay-bin.000003' from <binlog_start> limit 1,3;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
-slave-relay-bin.000002	#	Format_desc	#	#	SERVER_VERSION, BINLOG_VERSION
-slave-relay-bin.000002	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT)
-slave-relay-bin.000002	#	Query	#	#	BEGIN
+slave-relay-bin.000003	#	Format_desc	#	#	SERVER_VERSION, BINLOG_VERSION
+slave-relay-bin.000003	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT)
+slave-relay-bin.000003	#	Query	#	#	BEGIN
 FLUSH LOGS;
 FLUSH LOGS;
 DROP TABLE t1;
@@ -263,11 +263,11 @@
[SLAVE] ********* SOW RELAYLOG EVENTS IN ... *********
 show relaylog events from <binlog_start>;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
-slave-relay-bin.000004	#	Rotate	#	#	master-bin.000002;pos=4
-slave-relay-bin.000004	#	Rotate	#	#	slave-relay-bin.000005;pos=4
+slave-relay-bin.000005	#	Rotate	#	#	master-bin.000002;pos=4
+slave-relay-bin.000005	#	Rotate	#	#	slave-relay-bin.000006;pos=4
[SLAVE] ********* SOW RELAYLOG EVENTS *********
 show relaylog events from <binlog_start>;
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
-slave-relay-bin.000004	#	Rotate	#	#	master-bin.000002;pos=4
-slave-relay-bin.000004	#	Rotate	#	#	slave-relay-bin.000005;pos=4
+slave-relay-bin.000005	#	Rotate	#	#	master-bin.000002;pos=4
+slave-relay-bin.000005	#	Rotate	#	#	slave-relay-bin.000006;pos=4
 include/rpl_end.inc

It started to fail on Dec. 20th, suggesting that it might be a side-effect
of BUG#49978 replication tests changes.

How to repeat:
Check PB2, for example: 

http://pb2.norway.sun.com/?action=archive_download&archive_id=2778863&pretty=please

Suggested fix:
.
[12 Jan 2011 13:06] 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/128508

3238 Luis Soares	2011-01-12
      BUG#59444: rpl_row_show_relaylog_events fails on daily-5.5 test runs
      
      The test started failing on the same day patch for BUG 49978 was
      pushed. BUG 49978 changed part of the replication testing
      infrastructure in mysql-test-run. This caused the test to fail
      sporadically with result differences on relay log file
      names. When the test fails the relay-log filenames are shifted by
      one, eg:
      
      -show relaylog events in 'slave-relay-bin.000002' from <binlog_start>;
      +show relaylog events in 'slave-relay-bin.000003' from <binlog_start>;
      
      We fix this by deploying a call to rpl_reset.inc (which resets
      both master and slave, including log files) before actually
      running the test case.
      
      Appart from this, we also fix an unrelated issue with the test
      itself. In some cases, the test was not setting the log file name
      to use when it should.
     @ mysql-test/extra/rpl_tests/rpl_show_relaylog_events.inc
        Added call to rpl_reset.inc (fix for BUG#59444)
        Deployed missing instructions to get the binlog file name 
        before including show_relaylog/binlog_events.inc
[12 Jan 2011 18: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/128556

3238 Luis Soares	2011-01-12
      BUG#59444: rpl_row_show_relaylog_events fails on daily-5.5 test runs
      
      The test started failing on the same day patch for BUG 49978 was
      pushed. BUG 49978 changed part of the replication testing
      infrastructure in mysql-test-run. This caused the test to fail
      sporadically with result differences on relay log file
      names. When the test fails the relay-log filenames are shifted by
      one, eg:
      
      -show relaylog events in 'slave-relay-bin.000002' from <binlog_start>;
      +show relaylog events in 'slave-relay-bin.000003' from <binlog_start>;
      
      The problem was caused by a bad cleanup when using the include
      files:
      
        - include/setup_fake_relay_log.inc
        - include/cleanup_fake_relay_log.inc
      
      Which would leave a spurious relay-log file around (not listed in
      slave-relay-bin.index), causing the server to shift the name of
      the relay logs by one, even if cleaning up with RESET SLAVE.
      
      We fix this by removing the relay-log file when it is not needed
      anymore, ie at setup time and after recreating the fake relay-log
      index.
      
      Additionally, to make the affected test more resilient, we
      deployed a call to rpl_reset.inc (which resets both master and
      slave, including log files) before actually running the test
      case.
      
      Finally, appart from the reported bug, we also fix: (a) an
      unrelated issue with the failing test itself - in some cases, the
      test was not setting the log file name to use when it should; 
      (b) one typo.
     @ mysql-test/extra/rpl_tests/rpl_show_relaylog_events.inc
        Added call to rpl_reset.inc.
        Deployed missing instructions to get the binlog file name 
        before including show_relaylog/binlog_events.inc
[13 Jan 2011 12: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/128646

3239 Luis Soares	2011-01-13
      BUG#59444
      
      Refactoring effort on test case rpl_show_relaylog_events
      requested by reviewers.
[13 Jan 2011 14:33] 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/128662

3240 Luis Soares	2011-01-13
      BUG#59444
      
      Added comments to rpl_show_relaylog_events as requested by 
      reviewer.
[14 Jan 2011 11:17] Luis Soares
Queued in mysql-5.5 and merged to mysql-trunk.
[14 Jan 2011 11:17] Bugs System
Pushed into mysql-trunk 5.6.2 (revid:luis.soares@oracle.com-20110114111525-a4iysmoo4uk76ji6) (version source revid:luis.soares@oracle.com-20110114111525-a4iysmoo4uk76ji6) (merge vers: 5.6.2) (pib:24)
[14 Jan 2011 11:17] Bugs System
Pushed into mysql-5.5 5.5.10 (revid:luis.soares@oracle.com-20110114111401-83o6y6bz3h11j5eo) (version source revid:luis.soares@oracle.com-20110114111401-83o6y6bz3h11j5eo) (merge vers: 5.5.10) (pib:24)
[24 Jan 2011 16:01] Jon Stephens
Test codes changes only; no changes to document for users. Closed.
[28 Jan 2011 12:23] Jon Stephens
Returning to Closed state; see comments above.