Merge lp:~vlad-lesin/percona-server/5.5-bugs-1268729-1268735 into lp:percona-server/5.5

[Vlad Lesin]

The fix for bug #1268735.

Process the network error during setting @master_heartbeat_period in
get_master_version_and_clock() correctly.

The fix for bug #1268729:
Slave I/O thread won't attempt to automatically reconnect to the master.

The fix is in including ER_NET_READ_INTERRUPTED error code to the set of
network related error codes in is_network_error() function.

The test case tests a couple of cases when get_master_version_and_clock()
fails due to ER_NET_READ_INTERRUPTED network error.

http://jenkins.percona.com/view/PS%205.5/job/percona-server-5.5-param/940

[Laurynas Biveinis (laurynas-biveinis)]

    - It is possible to make the code changes for error injection
      less invasive and IMHO easier to read. Instead of

      // Inject ER_NET_READ_INTERRUPTED network error for testing.
      DBUG_EXECUTE_IF("get_master_version.timestamp.ER_NET_READ_INTERRUPTED",
                      mysql->net.last_errno= ER_NET_READ_INTERRUPTED;);
      if (DBUG_EVALUATE_IF("get_master_version.timestamp.ER_NET_READ_INTERRUPTED",
                           false, true) &&
          !mysql_real_query(mysql, STRING_WITH_LEN("SELECT
      UNIX_TIMESTAMP()")) &&

      you can push down the ER_NET_READ_INTERRUPTED injection deeper
      all the way to e.g. my_net_read, and make it one-shot:

      ...
      DBUG_EXECUTE_IF("inject_ER_NET_READ_INTERRUPTED",
                      {
                         ...whatever action..., e.g. net->last_error= ER_NET...
                         DBUG_SET("-d,inject_ER_NET_READ_INTERRUPTED");
                         ...early return or whatever...
                      });

      and in the three original injection points you just prime the
      above injection:

      DBUG_EXECUTE_IF("get_master_version.timestamp.ER_NET_READ_INTERRUPTED",
                      DBUG_SET("+d,inject_ER_NET_READ_INTERRUPTED"););
      if (!mysql_real_query ...

      and the surrounding code (the mysql_real_query call) itself is
      not touched.

    - The debug sync points and all their support code are not
      required. Even if START SLAVE is async (cannot recall at the
      moment whether it really is), you can use MTR include file
      start_slave_io.inc (I guess I/O thread is enough), which will
      wait until slave is up and running, and so the error injection
      point has passed.

    - Instead of own log grepper in Perl use one already provided:
      include/search_pattern.inc or search_pattern_in_file.inc,
      depending on whether you prefer testcase abort or a result file
      mismatch in case of the pattern not found. (s_p_in_file.inc
      exists in both 5.5 and 5.6, s_p.inc only in 5.6. In case you
      want that one, just bzr add it with the correct file id to
      5.5).

    - 58: s/binglog/binlog

    - 188, 259: spurious whitespace change

review: Needs Fixing

[Laurynas Biveinis (laurynas-biveinis)]

ST 38489

[Vlad Lesin (vlad-lesin)]

> - It is possible to make the code changes for error injection
> less invasive and IMHO easier to read. Instead of
>
> // Inject ER_NET_READ_INTERRUPTED network error for testing.
> DBUG_EXECUTE_IF("get_master_version.timestamp.ER_NET_READ_INTERRUPTED",
> mysql->net.last_errno= ER_NET_READ_INTERRUPTED;);
> if
> (DBUG_EVALUATE_IF("get_master_version.timestamp.ER_NET_READ_INTERRUPTED",
> false, true) &&
> !mysql_real_query(mysql, STRING_WITH_LEN("SELECT
> UNIX_TIMESTAMP()")) &&
>
> you can push down the ER_NET_READ_INTERRUPTED injection deeper
> all the way to e.g. my_net_read, and make it one-shot:
>
> ...
> DBUG_EXECUTE_IF("inject_ER_NET_READ_INTERRUPTED",
> {
> ...whatever action..., e.g. net->last_error=
> ER_NET...
> DBUG_SET("-d,inject_ER_NET_READ_INTERRUPTED");
> ...early return or whatever...
> });
>
> and in the three original injection points you just prime the
> above injection:
>
> DBUG_EXECUTE_IF("get_master_version.timestamp.ER_NET_READ_INTERRUPTED",
> DBUG_SET("+d,inject_ER_NET_READ_INTERRUPTED"););
> if (!mysql_real_query ...
>
> and the surrounding code (the mysql_real_query call) itself is
> not touched.
>
> - The debug sync points and all their support code are not
> required. Even if START SLAVE is async (cannot recall at the
> moment whether it really is), you can use MTR include file
> start_slave_io.inc (I guess I/O thread is enough), which will
> wait until slave is up and running, and so the error injection
> point has passed.

No, this does not work. wait_for_slave_io_to_start invokes wait_for_slave_param. wait_for_slave_param polls "show slave status" periodically expecting Slave_IO_Running field equals to 'Yes'. Slave_IO_Running does not equal to 'Yes' if connection to master is not established. When get_master_version_and_clock() returns "network error" handle_slave_io() tries to reconnect. As @global.debug was set to "get_master_version.timestamp.ER_NET_READ_INTERRUPTED" or any other value for testing get_master_version_and_clock() returns "network error" again and again and connection can not be established. So we need to reset @global.debug when get_master_version_and_clock() is finished. That is why debug sync points are currently used. We could reset @global.debug in mysql_real_query() (or my_net_read() as you have suggested) in DBUG_EXECUTE_IF("inject_ER_NET_READ_INTERRUPTED", {...}) block but I don't think this is a good idea to place specific code which must test only get_master_version_and_clock() function to more common function. How do you think?

[Laurynas Biveinis (laurynas-biveinis)]

IMHO there's no problem with placing a ER_NET_READ_INTERRUPTED-injecting block into my_net_read even though it's a common function. Such injection is not linked to the particular bug scenario, could be reused in testing some other code path, and is similar to the already-existing simulate_net_write_failure in my_net_write.

[Vlad Lesin (vlad-lesin)]

> IMHO there's no problem with placing a ER_NET_READ_INTERRUPTED-injecting block
> into my_net_read even though it's a common function. Such injection is not
> linked to the particular bug scenario, could be reused in testing some other
> code path, and is similar to the already-existing simulate_net_write_failure
> in my_net_write.

Sure, but I did not mean ER_NET_READ_INTERRUPTED in my previous comment.

We set @global.debug to certain values in test for DBUG_SET("+d,inject_ER_NET_READ_INTERRUPTED") being executed in certain places of get_master_version_and_clock(). For example we set:

SET @@global.debug="+d,get_master_version.timestamp.ER_NET_READ_INTERRUPTED"

to execute DBUG_SET("+d,inject_ER_NET_READ_INTERRUPTED") just before timestamp is gotten from master. And then we must reset get_master_version.timestamp.ER_NET_READ_INTERRUPTED to avoid execution of DBUG_SET("+d,inject_ER_NET_READ_INTERRUPTED") at the same place on reconnect. We can do this in mysql_real_query() what is not good because we place the certain test-specific code in common function. Or we can do this at the end of get_master_version_and_clock() in three places as this function has three end points and in this case some macros will be used to avoid copy-paste. But as I understood right the main idea of your comment was in removing such macros from get_master_version_and_clock().

[Laurynas Biveinis (laurynas-biveinis)]

Can we just make the high-level injections one shot too?

      DBUG_EXECUTE_IF("get_master_version.timestamp.ER_NET_READ_INTERRUPTED",
                      DBUG_SET("+d,inject_ER_NET_READ_INTERRUPTED");
                      DBUG_SET("-d,get_master_version.timestamp.ER_NET_READ_INTERRUPTED"););

Or this would not work?

[Vlad Lesin (vlad-lesin)]

> Can we just make the high-level injections one shot too?
...
> Or this would not work?

Yes, this works, thanks.

[Vlad Lesin (vlad-lesin)]

> - Instead of own log grepper in Perl use one already provided:
> include/search_pattern.inc or search_pattern_in_file.inc,
> depending on whether you prefer testcase abort or a result file
> mismatch in case of the pattern not found. (s_p_in_file.inc
> exists in both 5.5 and 5.6, s_p.inc only in 5.6. In case you
> want that one, just bzr add it with the correct file id to
> 5.5).

I have not found include/search_pattern.inc in both 5.5 and 5.6, so include/log_grep.inc is used instead it.

[Laurynas Biveinis (laurynas-biveinis)]

>
> > - Instead of own log grepper in Perl use one already provided:
> > include/search_pattern.inc or search_pattern_in_file.inc,
> > depending on whether you prefer testcase abort or a result file
> > mismatch in case of the pattern not found. (s_p_in_file.inc
> > exists in both 5.5 and 5.6, s_p.inc only in 5.6. In case you
> > want that one, just bzr add it with the correct file id to
> > 5.5).
>
> I have not found include/search_pattern.inc in both 5.5 and 5.6, so
> include/log_grep.inc is used instead it.

There is search_pattern_in_file.inc. log_grep.inc is OK too, except that it would be nice to remove it from the 5.7 port.

[Vlad Lesin (vlad-lesin)]

> There is search_pattern_in_file.inc. log_grep.inc is OK too, except that it
> would be nice to remove it from the 5.7 port.

search_pattern_in_file.inc dies when pattern is not found. So it can be used only if we want to check if the pattern is in file. But my case is checking if error messages are NOT in file. log_grep.inc count the number of pattern occurrences, that is why it suits for this case. If we want to get rid log_grep.inc in 5.7, I can add one more parameter in search_pattern_in_file.inc to check pattern absence.

[Vlad Lesin (vlad-lesin)]

http://jenkins.percona.com/view/PS%205.5/job/percona-server-5.5-param/958/

[Laurynas Biveinis (laurynas-biveinis)]

review: Approve

=== added file 'mysql-test/suite/rpl/r/rpl_percona_gmvac_net_err.result'
--- mysql-test/suite/rpl/r/rpl_percona_gmvac_net_err.result	1970-01-01 00:00:00 +0000
+++ mysql-test/suite/rpl/r/rpl_percona_gmvac_net_err.result	2014-02-27 16:19:30 +0000
@@ -0,0 +1,30 @@
+include/master-slave.inc
+[connection master]
+call mtr.add_suppression("Slave I/O: Get master clock failed with error: , Error_code: 1159");
+call mtr.add_suppression("Get master SERVER_ID failed with error: , Error_code: 1159");
+call mtr.add_suppression("Slave I/O: SET @master_heartbeat_period to master failed with error: , Error_code: 1159");
+call mtr.add_suppression("Slave I/O: Master command COM_REGISTER_SLAVE failed: .*");
+call mtr.add_suppression("Slave SQL.*Request to stop slave SQL Thread received while applying a group that has non-transactional changes; waiting for completion of the group");
+SET @debug_saved=@@global.debug;
+include/stop_slave.inc
+SET @@global.debug="+d,get_master_version.heartbeat.ER_NET_READ_INTERRUPTED";
+START SLAVE;
+include/wait_for_slave_io_to_start.inc
+[log_grep.inc] file:  pattern: The slave I/O thread stops because SET @master_heartbeat_period on master failed.
+[log_grep.inc] lines:   0
+include/stop_slave.inc
+SET @@global.debug="+d,get_master_version.serverid.ER_NET_READ_INTERRUPTED";
+START SLAVE;
+include/wait_for_slave_io_to_start.inc
+[log_grep.inc] file:  pattern: fatal error is encountered when it try to get the value of SERVER_ID variable from master
+[log_grep.inc] lines:   0
+include/stop_slave.inc
+SET @@global.debug="+d,get_master_version.timestamp.ER_NET_READ_INTERRUPTED";
+START SLAVE;
+include/wait_for_slave_io_to_start.inc
+[log_grep.inc] file:  pattern: "SELECT UNIX_TIMESTAMP.." failed on master, do not trust column
+[log_grep.inc] lines:   0
+include/stop_slave.inc
+SET @@global.debug='';
+include/start_slave.inc
+include/rpl_end.inc
 
=== added file 'mysql-test/suite/rpl/t/rpl_percona_gmvac_net_err.test'
--- mysql-test/suite/rpl/t/rpl_percona_gmvac_net_err.test	1970-01-01 00:00:00 +0000
+++ mysql-test/suite/rpl/t/rpl_percona_gmvac_net_err.test	2014-02-27 16:19:30 +0000
@@ -0,0 +1,67 @@
+# Bug #1268735:
+# Slave I/O thread won't attempt to automatically reconnect to the master
+# on ER_NET_READ_INTERRUPTED network error.
+#
+# The bug is in get_master_version_and_clock(). There are two places in this
+# function where the bug takes place. The first one is getting master server id
+# and the second one is getting master time. The error was injected to the code
+# to test the bug fix.
+
+source include/master-slave.inc;
+# The error injection works only with debug facilities.
+source include/have_debug.inc;
+source include/have_debug_sync.inc;
+# The test is not supposed to have any binglog affairs.
+# Hence it's enough it to run only with one binlog format
+source include/have_binlog_format_mixed.inc;
+
+call mtr.add_suppression("Slave I/O: Get master clock failed with error: , Error_code: 1159");
+call mtr.add_suppression("Get master SERVER_ID failed with error: , Error_code: 1159");
+call mtr.add_suppression("Slave I/O: SET @master_heartbeat_period to master failed with error: , Error_code: 1159");
+call mtr.add_suppression("Slave I/O: Master command COM_REGISTER_SLAVE failed: .*");
+call mtr.add_suppression("Slave SQL.*Request to stop slave SQL Thread received while applying a group that has non-transactional changes; waiting for completion of the group");
+
+let log_file_full_path= `SELECT @@GLOBAL.log_error`;
+if(!$log_file_full_path)
+{
+  # MySQL Server on windows is started with --console and thus
+  # does not know the location of its .err log, use default location
+  let log_file_full_path = $MYSQLTEST_VARDIR/log/mysqld.2.err;
+}
+
+connection slave;
+SET @debug_saved=@@global.debug;
+
+# i=1 for activating injected error during getting timestamp from master
+# i=2 for activating injected error during getting server id from master
+# i=3 for activating injected error during setting @master_heartbeat_period 
+let i=3;
+
+connection slave;
+source include/stop_slave.inc;
+let old_debug=`SELECT @@global.debug`;
+
+while($i)
+{
+  let debug_name=`SELECT CASE $i WHEN 1 THEN 'get_master_version.timestamp.ER_NET_READ_INTERRUPTED' WHEN 2 THEN 'get_master_version.serverid.ER_NET_READ_INTERRUPTED' WHEN 3 THEN 'get_master_version.heartbeat.ER_NET_READ_INTERRUPTED' END`;
+
+  # Stop slave and set debug variables
+  eval SET @@global.debug="+d,$debug_name";
+
+  START SLAVE;
+  # Crash if error during slave starting takes place
+  let $rpl_allow_error= 0;
+  source include/wait_for_slave_io_to_start.inc;
+
+  let grep_pattern=`SELECT CASE $i WHEN 1 THEN '"SELECT UNIX_TIMESTAMP.." failed on master, do not trust column' WHEN 2 THEN 'fatal error is encountered when it try to get the value of SERVER_ID variable from master' WHEN 3 THEN 'The slave I/O thread stops because SET @master_heartbeat_period on master failed.' END`;
+
+  source include/log_grep.inc;
+
+  source include/stop_slave.inc;
+  dec $i;
+}
+
+eval SET @@global.debug='$old_debug';
+
+source include/start_slave.inc;
+source include/rpl_end.inc;
 
=== modified file 'sql-common/client.c'
--- sql-common/client.c	2013-12-16 08:19:34 +0000
+++ sql-common/client.c	2014-02-27 16:19:30 +0000
@@ -3912,6 +3912,12 @@
   DBUG_ENTER("mysql_real_query");
   DBUG_PRINT("enter",("handle: 0x%lx", (long) mysql));
   DBUG_PRINT("query",("Query = '%-.4096s'",query));
+  DBUG_EXECUTE_IF("inject_ER_NET_READ_INTERRUPTED",
+		   {
+                     mysql->net.last_errno= ER_NET_READ_INTERRUPTED;
+                     DBUG_SET("-d,inject_ER_NET_READ_INTERRUPTED");
+                     DBUG_RETURN(1);
+                   });
 
   if (mysql_send_query(mysql,query,length))
     DBUG_RETURN(1);
 
=== modified file 'sql/slave.cc'
--- sql/slave.cc	2014-02-03 04:39:37 +0000
+++ sql/slave.cc	2014-02-27 16:19:30 +0000
@@ -1209,7 +1209,8 @@
       errorno == CR_SERVER_GONE_ERROR ||
       errorno == CR_SERVER_LOST ||
       errorno == ER_CON_COUNT_ERROR ||
-      errorno == ER_SERVER_SHUTDOWN)
+      errorno == ER_SERVER_SHUTDOWN ||
+      errorno == ER_NET_READ_INTERRUPTED)
     return TRUE;
 
   return FALSE;   
@@ -1325,6 +1326,12 @@
                   };);
 
   master_res= NULL;
+  DBUG_EXECUTE_IF("get_master_version.timestamp.ER_NET_READ_INTERRUPTED",
+		  {
+		     DBUG_SET("+d,inject_ER_NET_READ_INTERRUPTED");
+		     DBUG_SET("-d,get_master_version.timestamp."
+			      "ER_NET_READ_INTERRUPTED");
+		  });
   if (!mysql_real_query(mysql, STRING_WITH_LEN("SELECT UNIX_TIMESTAMP()")) &&
       (master_res= mysql_store_result(mysql)) &&
       (master_row= mysql_fetch_row(master_res)))
@@ -1375,6 +1382,12 @@
                   };);
   master_res= NULL;
   master_row= NULL;
+  DBUG_EXECUTE_IF("get_master_version.server_id.ER_NET_READ_INTERRUPTED",
+		  {
+                    DBUG_SET("+d,inject_ER_NET_READ_INTERRUPTED");
+                    DBUG_SET("-d,get_master_version.server_id."
+                             "ER_NET_READ_INTERRUPTED");
+		  });
   if (!mysql_real_query(mysql,
                         STRING_WITH_LEN("SHOW VARIABLES LIKE 'SERVER_ID'")) &&
       (master_res= mysql_store_result(mysql)) &&
@@ -1564,17 +1577,31 @@
     */
     llstr((ulonglong) (mi->heartbeat_period*1000000000UL), llbuf);
     sprintf(query, query_format, llbuf);
+    DBUG_EXECUTE_IF("get_master_version.heartbeat.ER_NET_READ_INTERRUPTED",
+		    {
+		      DBUG_SET("+d,inject_ER_NET_READ_INTERRUPTED");
+		      DBUG_SET("-d,get_master_version.heartbeat."
+			       "ER_NET_READ_INTERRUPTED");
+		    });
+    if (mysql_real_query(mysql, query, strlen(query))) {
+      if (is_network_error(mysql_errno(mysql)))
+      {
+        mi->report(WARNING_LEVEL, mysql_errno(mysql),
+                   "SET @master_heartbeat_period to master failed with error: %s",
+                   mysql_error(mysql));
+        mysql_free_result(mysql_store_result(mysql));
+        goto network_err;
+      }
+      else if (!check_io_slave_killed(mi->io_thd, mi, NULL)) {
+        errmsg= "The slave I/O thread stops because SET @master_heartbeat_period "
+          "on master failed.";
+        err_code= ER_SLAVE_FATAL_ERROR;
+        sprintf(err_buff, "%s Error: %s", errmsg, mysql_error(mysql));
+        mysql_free_result(mysql_store_result(mysql));
+        goto err;
+      }
+    }
 
-    if (mysql_real_query(mysql, query, strlen(query))
-        && !check_io_slave_killed(mi->io_thd, mi, NULL))
-    {
-      errmsg= "The slave I/O thread stops because SET @master_heartbeat_period "
-        "on master failed.";
-      err_code= ER_SLAVE_FATAL_ERROR;
-      sprintf(err_buff, "%s Error: %s", errmsg, mysql_error(mysql));
-      mysql_free_result(mysql_store_result(mysql));
-      goto err;
-    }
     mysql_free_result(mysql_store_result(mysql));
   }