BUG#18385953 - RPL_GTID_STRESS_FAILOVER FAILS WITH "ERROR IN SYNC_WITH_MASTER.INC"

Sven Sandberg · Sven Sandberg · commit ad5bbb385a2d · 2014-08-18T14:29:06.000+02:00
This test failed sporadically in the cleanup code.
The cleanup code contained this:

  for each server:
    DROP DATABASE
    --source include/stop_slave.inc
    CHANGE MASTER TO MASTER_AUTO_POSITION = 0;
    --source include/start_slave.inc

The problem is that CHANGE MASTER will drop the relay logs.  If the IO
thread was ahead of the SQL thread at this point, received and
not-yet-executed transactions in the relay log would be lost.  Since it
does not use the auto-position protocol when it does the
start_slave.inc, replication would resume after the lost transaction
rather than retransmit it.

This caused two types of failures:
 1. The IO thread could be stopped in the middle of a transaction, when
    the SQL thread had processed only up to the last complete transaction.
    Here all transactions consist of two events: Gtid followed by Query.
    Thus, the last received transaction was a Gtid and after
    start_slave.inc the slave would receive a Query. The slave SQL thread
    would then see a Query without Gtid. This looks like an anonymous
    transaction, which is not allowed when GTID_MODE = ON. So the SQL thread
    would stop with error 1782: "Error '@@SESSION.GTID_NEXT cannot be set to
    ANONYMOUS when @@GLOBAL.GTID_MODE = ON.' on query. Default database: 
    'db_3'. Query: 'DROP DATABASE db_3'".
 2. The IO thread could be stopped between transactions, when the SQL
    thread had processed only up to the second-last transaction.
    Then the entire transaction would get lost. Later, in rpl_sync.inc,
    the GTID would not be received at all by the slave, so the sync would
    fail with a timeout.

Fixed by dropping the databases and syncing all servers before stopping
all the slave threads and executing CHANGE MASTER.
diff --git a/mysql-test/include/begin_include_file.inc b/mysql-test/include/begin_include_file.inc
@@ -34,6 +34,7 @@
 #
 # # At the beginning of include/my_file.inc:
 # --let $include_filename= my_file.inc
+# [--let $include_silent= 1]
 # [--let $rpl_debug= 1]
 # --source include/begin_include_file.inc
 #
diff --git a/mysql-test/include/save_io_thread_pos.inc b/mysql-test/include/save_io_thread_pos.inc
@@ -28,7 +28,7 @@
 
 if ($use_gtids)
 {
-  --let $_saved_gtids= query_get_value(SHOW SLAVE STATUS, Retrieved_Gtid_set, 1)
+  --let $_saved_gtids= query_get_value(SHOW SLAVE STATUS, Retrieved_Gtid_Set, 1)
   if ($rpl_debug)
   {
     --echo save_io_thread_pos.inc saved gtid='$_saved_gtids'
diff --git a/mysql-test/include/show_all_binlogs.inc b/mysql-test/include/show_all_binlogs.inc
@@ -0,0 +1,66 @@
+# ==== Purpose ====
+#
+# Print the contents of all binary logs to the result log. This must
+# only be used for debugging.
+#
+# ==== Usage ====
+#
+# [--let $output_file= FILENAME]
+# [--let $append= 1]
+# [--let $rpl_debug= 1]
+# --source include/show_all_binlogs.inc
+#
+# Parameters:
+#
+#   $output_file
+#     By default, output is printed to the result log.  If you need to
+#     print it to a specific file, specify the filename with this
+#     parameter.
+#
+#   $append
+#     By default, if $output_file is specified and the file exists,
+#     this script truncates the file before it writes to it.  If
+#     $append is specified, the file is not truncated and the contents
+#     of the binary log is appended to the end.
+#
+#   $rpl_debug
+#     See rpl_init.inc
+
+--let $include_filename= show_all_binlogs.inc
+--source include/begin_include_file.inc
+
+
+--disable_query_log
+
+if ($output_file == '')
+{
+  --echo DO_NOT_CHECK_IN_THIS_LINE: include/show_all_binlogs.inc should only be used for debugging. Never check in a test that calls it on success.
+}
+
+--let $number= 1
+--let $binlog_file= query_get_value(SHOW BINARY LOGS, Log_name, $number)
+while ($binlog_file != 'No such row')
+{
+  --let $statement= SHOW BINLOG EVENTS IN '$binlog_file'
+  --let $header= ======== $statement ========
+
+  if ($output_file != '')
+  {
+    --let $write_var= $header
+    --let $write_to_file= $output_file
+    --source include/write_var_to_file.inc
+
+    --source include/write_result_to_file.inc
+  }
+  if ($output_file == '')
+  {
+    --echo $header
+    eval $statement;
+  }
+  --inc $number
+
+  --let $binlog_file= query_get_value(SHOW BINARY LOGS, Log_name, $number)
+}
+
+
+--source include/end_include_file.inc
diff --git a/mysql-test/include/show_all_relay_logs.inc b/mysql-test/include/show_all_relay_logs.inc
@@ -0,0 +1,70 @@
+# ==== Purpose ====
+#
+# Print the contents of all relay logs to the result log. This must
+# only be used for debugging.
+#
+# ==== Usage ====
+#
+# [--let $output_file= FILENAME]
+# [--let $append= 1]
+# [--let $rpl_debug= 1]
+# --source include/show_all_binlogs.inc
+#
+# Parameters:
+#
+#   $output_file
+#     By default, output is printed to the result log.  If you need to
+#     print it to a specific file, specify the filename with this
+#     parameter.
+#
+#   $append
+#     By default, if $output_file is specified and the file exists,
+#     this script truncates the file before it writes to it.  If
+#     $append is specified, the file is not truncated and the contents
+#     of the binary log is appended to the end.
+#
+#   $rpl_debug
+#     See rpl_init.inc
+
+--let $include_filename= show_all_relay_logs.inc
+--source include/begin_include_file.inc
+
+
+--disable_query_log
+
+if ($output_file == '')
+{
+  --echo DO_NOT_CHECK_IN_THIS_LINE: include/show_all_relay_logs.inc should only be used for debugging. Never check in a test that calls it on success.
+}
+
+--let $last_relay_log_file= query_get_value(SHOW SLAVE STATUS, Relay_Log_File, 1)
+--let $relay_log_base= `SELECT SUBSTRING_INDEX('$last_relay_log_file', '.', 1)`
+--let $relay_log_count= `SELECT CONCAT('1', SUBSTRING_INDEX('$last_relay_log_file', '.', -1)) - 1000000`
+--let $number= 1
+while ($number <= $relay_log_count)
+{
+  --let $padded_number= `SELECT LPAD('$number', 6, '0')`
+  --let $statement= SHOW RELAYLOG EVENTS IN '$relay_log_base.$padded_number'
+  --let $header= ======== $statement ========
+
+  if ($output_file != '')
+  {
+    --let $write_to_file= $output_file
+    --let $write_var= $header
+    --let $allow_error= 1
+    --source include/write_var_to_file.inc
+
+    --source include/write_result_to_file.inc
+  }
+  if ($output_file == '')
+  {
+    --echo $header
+    --error 0, 1220 # 1220 = ER_ERROR_WHEN_EXECUTING_COMMAND
+    eval $statement;
+  }
+
+  --inc $number
+}
+
+
+--source include/end_include_file.inc
diff --git a/mysql-test/include/write_result_to_file.inc b/mysql-test/include/write_result_to_file.inc
@@ -12,6 +12,8 @@
 # --let $statement= <STATEMENT>
 # --let $output_file= {<FILE>|GENERATE}
 # [--let $dont_print_statement= 1]
+# [--let $allow_error= 1]
+# [--let $append= 1]
 # --source include/write_result_to_file.inc
 #
 # Parameters:
@@ -27,6 +29,14 @@
 #     By default, the statement is echoed to the result log.  If the
 #     statement contains non-deterministic output, set this variable
 #     to suppress it.
+#
+#   $allow_error
+#     By default, this script causes the test to fail if the statement
+#     generates an error.  If $allow_error is set, errors are ignored.
+#
+#   $append
+#     By default, any existing file is overwritten. If $append is
+#     specified, and the file exists, it appends to the file.
 
 # Get the port and socket used by mysqld on current connection
 --let _WRTF_SERVER_PORT= `SELECT @@PORT`
@@ -58,19 +68,37 @@ if ($output_file == GENERATE)
 }
 --let _WRTF_OUTPUT_FILE= $output_file
 
+if ($allow_error)
+{
+  --let _WRTF_ALLOW_ERROR= 1
+}
+if (!$allow_error)
+{
+  --let _WRTF_ALLOW_ERROR= 0
+}
+if ($append)
+{
+  --let _WRTF_APPEND= 1
+}
+if (!$append)
+{
+  --let _WRTF_APPEND= 0
+}
+
 perl;
   use strict;
   my $stmt= $ENV{'_WRTF_STATEMENT'};
   # Connecting mysql to same mysqld as current connectiona
   # by overriding port and socket
-  my $mysql = $ENV{'MYSQL'};
+  my $mysql= $ENV{'MYSQL'};
   my $server_port= $ENV{'_WRTF_SERVER_PORT'};
   my $server_socket= $ENV{'_WRTF_SERVER_SOCKET'};
+  my $redirection_type= $ENV{'_WRTF_APPEND'} ? '>>' : '>';
   $mysql .= " --port=$server_port --socket=$server_socket";
   my $outfile = $ENV{'_WRTF_OUTPUT_FILE'};
-  open MYSQL, "| $mysql > $outfile" or die "Failed to open MYSQL pipe: '$mysql > $outfile'";
+  open MYSQL, "| $mysql $redirection_type $outfile" or die "Failed to open MYSQL pipe: '$mysql > $outfile'";
   print MYSQL $stmt, ';' or die "Error printing statement to MYSQL pipe: $!";
-  close MYSQL or die "Error closing MYSQL pipe: $!";
+  close MYSQL or $ENV{'_WRTF_ALLOW_ERROR'} or die "Error closing MYSQL pipe: $!";
 EOF
 
 --let $include_filename= write_result_to_file.inc [$write_result_msg]
diff --git a/mysql-test/suite/rpl/r/rpl_gtid_stress_failover.result b/mysql-test/suite/rpl/r/rpl_gtid_stress_failover.result
@@ -15,4 +15,5 @@ Check that GTID_EXECUTED is equal on all servers.
 Check that database state is equal on all servers.
 include/diff_servers.inc [servers=1 2 3 4 5 ]
 ==== Clean up ====
+include/rpl_sync.inc
 include/rpl_end.inc
diff --git a/mysql-test/suite/rpl/t/rpl_gtid_stress_failover.test b/mysql-test/suite/rpl/t/rpl_gtid_stress_failover.test
@@ -1,5 +1,3 @@
-#Want to skip this test from daily Valgrind execution
---source include/no_valgrind_without_big.inc
 # ==== Purpose ====
 #
 # Test that it is possible to change the topology completely randomly,
@@ -79,8 +77,13 @@
 #
 # ==== References ====
 #
-# Created as part of WL#3584: Global Transaction Identifiers
+# WL#3584: Global Transaction Identifiers
+# - Created as part of this worklog
+# BUG#18385953: RPL_GTID_STRESS_FAILOVER FAILS WITH "ERROR IN SYNC_WITH_MASTER.INC"
+# - fixed bug in cleanup code
 
+#Want to skip this test from daily Valgrind execution
+--source include/no_valgrind_without_big.inc
 --source include/big_test.inc
 --source include/have_gtid.inc
 
@@ -97,7 +100,10 @@
 
 --echo ==== Configure ====
 
---let $max_seconds= 300
+if ($max_seconds == '')
+{
+  --let $max_seconds= 300
+}
 if ($max_iterations == '')
 {
   --let $max_iterations= 10000
@@ -394,7 +400,7 @@ while ($server <= $n_servers)
     {
       --source include/show_rpl_debug_info.inc
       --echo ERROR: GTID_EXECUTED differs between server 1 and server $server
-      --echo ERROR: GTID_EXECUTED on server 1: '$saved_gtid_executed'
+      --echo ERROR: GTID_EXECUTED on server 1: '$last_gtid_executed'
       --echo ERROR: GTID_EXECUTED on server $server: '$gtid_executed'
       --die GTID_EXECUTED differs between two servers
     }
@@ -410,15 +416,22 @@ while ($server <= $n_servers)
 
 --echo ==== Clean up ====
 
+# drop database
 --connection default
 --let $server= 1
 while ($server <= $n_servers)
 {
-  --connection default
   eval DROP DATABASE db_$server;
+  --inc $server
+}
+--source include/rpl_sync.inc
 
-  # restoring the AUTO_POSITION 
+# restore AUTO_POSITION
+--let $server= 1
+while ($server <= $n_servers)
+{
   --connection server_$server
+
   --let $include_silent=1
   --source include/stop_slave.inc
   CHANGE MASTER TO MASTER_AUTO_POSITION=0;

Original file line number	Diff line number	Diff line change
`@@ -34,6 +34,7 @@`
`34`	`34`	`#`
`35`	`35`	`# # At the beginning of include/my_file.inc:`
`36`	`36`	`# --let $include_filename= my_file.inc`
	`37`	`+# [--let $include_silent= 1]`
`37`	`38`	`# [--let $rpl_debug= 1]`
`38`	`39`	`# --source include/begin_include_file.inc`
`39`	`40`	`#`
Original file line number	Diff line number	Diff line change
`@@ -28,7 +28,7 @@`
`28`	`28`
`29`	`29`	`if ($use_gtids)`
`30`	`30`	`{`
`31`		`- --let $_saved_gtids= query_get_value(SHOW SLAVE STATUS, Retrieved_Gtid_set, 1)`
	`31`	`+ --let $_saved_gtids= query_get_value(SHOW SLAVE STATUS, Retrieved_Gtid_Set, 1)`
`32`	`32`	`if ($rpl_debug)`
`33`	`33`	`{`
`34`	`34`	`--echo save_io_thread_pos.inc saved gtid='$_saved_gtids'`