MDEV-13437 InnoDB: Failing assertion: !srv_read_only_mode in mtr0mtr.cc:322bb-10.0-mdev_13437-andrei

The assert was caused due to incorrect handling of --tc-heuristic-recover=ROLLBACK
and --innodb-read-only=1 option combination. Innodb attempted
rollback of a prepared transaction having no right to do so because of
the latter option.

Fixed with making Innodb to respect the read-only flag by
innobase_{commit,rollback}_by_xid (Marko's contribution).
LOCK_log mutex lock/unlock had to be added to cover MDEV-1438 "child" issue.
The measure is confirmed by mysql sources as well.

For testing of the conflicting option combination, mysql-test-run is
made to export a new $MYSQLD_LAST_CMD. It holds the very last value
generated by mtr.mysqld_start().  Even though the options have been
also always stored in $mysqld->{'started_opts'} there were no access
to them beyond the automatic server restart by mtr through the expect
file interface.

Effectively therefore $MYSQLD_LAST_CMD represents a more general interface to
$mysqld->{'started_opts'} which can be used in wider scopes including
server launch with incompatible options.

Notice another existing method to restart the server with incompatible
options relying on $MYSQLD_CMD is is aware of $mysqld->{'started_opts'} (the actual
options that the server is launched by mtr). In order to use this
method they would have to be provided manually.

Note, at merging to 10.2 an added search++ macro should be renamed
"back" to normal. It's being backparted to 10.0 "temporarily".

11 files changed, 307 insertions, 13 deletions

diff --git a/mysql-test/include/fail_start_mysqld.inc b/mysql-test/include/fail_start_mysqld.inc
new file mode 100644
index 00000000000..bb1085b5dd7
--- /dev/null
+++ b/mysql-test/include/fail_start_mysqld.inc
@@ -0,0 +1,18 @@
+# ==== Usage ====
+#
+# [--let $restart_parameters= --innodb-force-recovery=0 --innodb-read-only=1]
+# [--let $mysqld_stub_cmd= $MYSQLD_LAST_CMD]
+# [--let $error_log= $MYSQLTEST_VARDIR/log/mysqld.1.err]
+# --source include/fail_restart_mysqld.inc
+
+# Evaluate the default of $error_log
+if (!$error_log)
+{
+  --let $error_log= $MYSQLTEST_VARDIR/log/mysqld.1.err
+}
+
+--error 1
+--exec $mysqld_stub_cmd $restart_parameters >> $error_log  2>&1
+
+# As the server is stopped
+--disable_reconnect
diff --git a/mysql-test/include/restart_mysqld.inc b/mysql-test/include/restart_mysqld.inc
index dcaf47c55a2..940e081c431 100644
--- a/mysql-test/include/restart_mysqld.inc
+++ b/mysql-test/include/restart_mysqld.inc
@@ -31,7 +31,7 @@ if ($shutdown_timeout == 0)
 --exec echo "wait" > $_expect_file_name
 
 # Send shutdown to the connected server and give
-# it 10 seconds to die before zapping it
+# it an opted number of seconds to die before zapping it
 shutdown_server $server_shutdown_timeout;
 
 # Write file to make mysql-test-run.pl start up the server again
diff --git a/mysql-test/include/search_pattern_in_file++.inc b/mysql-test/include/search_pattern_in_file++.inc
new file mode 100644
index 00000000000..3c5529989bb
--- /dev/null
+++ b/mysql-test/include/search_pattern_in_file++.inc
@@ -0,0 +1,80 @@
+# Purpose:
+#    Simple search with Perl for a pattern in some file.
+#
+#    The advantages compared to thinkable auxiliary constructs using the
+#    mysqltest language and SQL are:
+#    1. We do not need a running MySQL server.
+#    2. SQL causes "noise" during debugging and increases the size of logs.
+#       Perl code does not disturb at all.
+#
+#    The environment variables SEARCH_FILE and SEARCH_PATTERN must be set
+#    before sourcing this routine.
+#
+#    Optionally, SEARCH_RANGE can be set to the max number of bytes of the file
+#    to search. If negative, it will search that many bytes at the end of the
+#    file. By default the search happens from the last CURRENT_TEST:
+#    marker till the end of file (appropriate for searching error logs).
+#
+#    Optionally, SEARCH_ABORT can be set to "FOUND" or "NOT FOUND" and this
+#    will abort if the search result doesn't match the requested one.
+#
+#    In case of
+#    - SEARCH_FILE and/or SEARCH_PATTERN is not set
+#    - SEARCH_FILE cannot be opened
+#    the test will abort immediate.
+#
+# Typical use case (check invalid server startup options):
+#    let $error_log= $MYSQLTEST_VARDIR/log/my_restart.err;
+#    --error 0,1
+#    --remove_file $error_log
+#    let SEARCH_FILE= $error_log;
+#    # Stop the server
+#    let $restart_file= $MYSQLTEST_VARDIR/tmp/mysqld.1.expect;
+#    --exec echo "wait" > $restart_file
+#    --shutdown_server 10
+#    --source include/wait_until_disconnected.inc
+#
+#    --error 1
+#    --exec $MYSQLD_CMD <whatever wrong setting> > $error_log 2>&1
+#    # The server restart aborts
+#    let SEARCH_PATTERN= \[ERROR\] Aborting;
+#    --source include/search_pattern_in_file.inc
+#
+# Created: 2011-11-11 mleich
+#
+
+perl;
+    use strict;
+    die "SEARCH_FILE not set" unless $ENV{SEARCH_FILE};
+    my @search_files= glob($ENV{SEARCH_FILE});
+    my $search_pattern= $ENV{SEARCH_PATTERN} or die "SEARCH_PATTERN not set";
+    my $search_range=   $ENV{SEARCH_RANGE};
+    my $content;
+    foreach my $search_file (@search_files) {
+        open(FILE, '<', $search_file) || die("Can't open file $search_file: $!");
+        my $file_content;
+        if ($search_range > 0) {
+           read(FILE, $file_content, $search_range, 0);
+        } elsif ($search_range < 0) {
+           my $size= -s $search_file;
+           $search_range = -$size if $size > -$search_range;
+           seek(FILE, $search_range, 2);
+           read(FILE, $file_content, -$search_range, 0);
+        } else {
+          while(<FILE>) { # error log
+            if (/^CURRENT_TEST:/) {
+              $content='';
+            } else {
+              $content.=$_;
+            }
+          }
+        }
+        close(FILE);
+        $content.= $file_content;
+    }
+    my @matches=($content =~ m/$search_pattern/gs);
+    my $res=@matches ? "FOUND " . scalar(@matches) : "NOT FOUND";
+    $ENV{SEARCH_FILE} =~ s{^.*?([^/\\]+)$}{$1};
+    print "$res /$search_pattern/ in $ENV{SEARCH_FILE}\n";
+    exit $ENV{SEARCH_ABORT} && $res =~ /^$ENV{SEARCH_ABORT}/;
+EOF
diff --git a/mysql-test/include/shutdown_mysqld.inc b/mysql-test/include/shutdown_mysqld.inc
index 54bba1318e7..e28f3c244ca 100644
--- a/mysql-test/include/shutdown_mysqld.inc
+++ b/mysql-test/include/shutdown_mysqld.inc
@@ -1,3 +1,17 @@
+# ==== Usage ====
+#
+# [--let $shutdown_timeout= 30]
+# [--let $allow_rpl_inited= 1]
+# --source include/shutdown_mysqld.inc
+
+# The default value is empty
+--let $server_shutdown_timeout=
+
+if ($shutdown_timeout)
+{
+  --let $server_shutdown_timeout= $shutdown_timeout
+}
+
 # This is the first half of include/restart_mysqld.inc.
 if ($rpl_inited)
 {
@@ -13,6 +27,6 @@ if ($rpl_inited)
 --exec echo "wait" > $_expect_file_name
 
 # Send shutdown to the connected server
---shutdown_server
+--shutdown_server $server_shutdown_timeout
 --source include/wait_until_disconnected.inc
 
diff --git a/mysql-test/mysql-test-run.pl b/mysql-test/mysql-test-run.pl
index 6b0c3b370de..8960685df76 100755
--- a/mysql-test/mysql-test-run.pl
+++ b/mysql-test/mysql-test-run.pl
@@ -5568,6 +5568,11 @@ sub mysqld_start ($$) {
   # Remember options used when starting
   $mysqld->{'started_opts'}= $extra_opts;
 
+  # "Dynamic" version of MYSQLD_CMD is reevaluated with each mysqld_start.
+  # Use it to restart the server at testing a failing server start (e.g
+  # due to incompatible options).
+  $ENV{'MYSQLD_LAST_CMD'}= "$exe  @$args";
+
   return;
 }
 
diff --git a/mysql-test/r/tc_heuristic_recover.result b/mysql-test/r/tc_heuristic_recover.result
new file mode 100644
index 00000000000..ec353f5d069
--- /dev/null
+++ b/mysql-test/r/tc_heuristic_recover.result
@@ -0,0 +1,25 @@
+call mtr.add_suppression("Can't init tc log");
+call mtr.add_suppression("Aborting");
+set debug_sync='RESET';
+CREATE TABLE t1 (i INT) ENGINE=InnoDB;
+FLUSH TABLES;
+SET @@global.innodb_flush_log_at_trx_commit=1;
+set debug_sync='ha_commit_trans_after_prepare WAIT_FOR go';
+INSERT INTO t1 VALUES (1);;
+*** (1) the server is killed and (2) restarted with --innodb-force-recovery=3
+*** (3)  Shut down
+SET GLOBAL innodb_fast_shutdown=0;
+FOUND 1 /was in the XA prepared state/ in mysqld.1.err
+*** (4) restart with conflicing recovery options: --innodb-force-recovery=0 --innodb-read-only=1 --tc-heuristic-recover=ROLLBACK --debug=d,info.
+FOUND 1 /\[ERROR\] Can\'t init tc log/ in mysqld.1.err
+*** the following search MUST report NOT FOUND into the result file!
+NOT FOUND /info: rollback xid/ in mysqld.1.err
+*** (5) restart with non-conflicing recovery options: --innodb-force-recovery=0 --innodb-read-only=0 --tc-heuristic-recover=ROLLBACK --debug=d,info
+FOUND 2 /\[ERROR\] Can\'t init tc log/ in mysqld.1.err
+*** the following search MUST report YES FOUND into the result file!
+FOUND 1 /info: rollback xid/ in mysqld.1.err
+*** (6) The server restarts with --innodb-force-recovery=0 and stably now.
+*** Table must be empty:
+SELECT * FROM t1;
+i
+DROP TABLE t1;
diff --git a/mysql-test/t/tc_heuristic_recover.test b/mysql-test/t/tc_heuristic_recover.test
new file mode 100644
index 00000000000..9aa009b02ca
--- /dev/null
+++ b/mysql-test/t/tc_heuristic_recover.test
@@ -0,0 +1,111 @@
+# The test verifies a few server/engine recovery option combinations.
+# Specifically, MDEV-13437,13438 are concerned with no crashes
+# due to a pair of --innodb-read-only=1 --tc-heuristic-recover=ROLLBACK.
+#
+# The whole test consists of 6 phases, see (lables) echoed.
+# Initially the test commits a transaction and in the following proceeds
+# throughout the 6 phases.
+# Within them the server is shut  down and attempted to restart, to succeed
+# that in the end.
+# All this proves no crashes and effective uncommit of the transaction
+# which is asserted.
+#
+--source include/have_innodb.inc
+# The test logics really requires --log-bin.
+--source include/have_binlog_format_mixed.inc
+--source include/have_debug.inc
+--source include/have_debug_sync.inc
+
+call mtr.add_suppression("Can't init tc log");
+call mtr.add_suppression("Aborting");
+
+# Now take a shapshot of the last time server options.
+#
+# The "restart" expect-file facility can't be engaged because the server
+#  having conflicting options may not succeed to boot up.
+# Also notice $MYSQLD_CMD is too "static" being unaware of the actual options
+# of the last (before shutdown or kill) server run.
+# That's why $MYSQLD_LAST_CMD that allows for the server new start
+# with more options appended to a stub set which is settled at this very point.
+--let $mysqld_stub_cmd= $MYSQLD_LAST_CMD
+--let $error_log= $MYSQLTEST_VARDIR/log/mysqld.1.err
+--let SEARCH_FILE= $error_log
+set debug_sync='RESET';
+
+CREATE TABLE t1 (i INT) ENGINE=InnoDB;
+FLUSH TABLES; # we need the table post crash-restart, see MDEV-8841.
+SET @@global.innodb_flush_log_at_trx_commit=1;
+
+# Run transaction in a separate "prey" connection
+--connect (con1,localhost,root,,)
+# The signal won't arrive though
+set debug_sync='ha_commit_trans_after_prepare WAIT_FOR go';
+--send INSERT INTO t1 VALUES (1);
+
+--let $restart_parameters= --innodb-force-recovery=3
+--echo *** (1) the server is killed and (2) restarted with $restart_parameters
+
+--connection default
+--let $table= information_schema.processlist
+--let $where= where state = 'debug sync point: ha_commit_trans_after_prepare'
+--let $wait_condition= SELECT count(*) = 1 FROM $table $where
+--source include/wait_condition.inc
+
+--let $shutdown_timeout= 0
+--source include/restart_mysqld.inc
+
+#
+# Stop and try to restart the server with $restart_parameters, which
+# will neither succeed not conduct any rollback because of read-only true.
+# FIXME: MDEV-12700 Allow innodb_read_only_mode startup without prior
+# slow shutdown.
+--echo *** (3)  Shut down
+SET GLOBAL innodb_fast_shutdown=0;
+--let $shutdown_timeout=
+--source include/shutdown_mysqld.inc
+
+# the --innodb-force-recovery=3 restart above must leave the following trace:
+--let SEARCH_PATTERN= was in the XA prepared state
+--source include/search_pattern_in_file++.inc
+
+--let $restart_parameters= --innodb-force-recovery=0 --innodb-read-only=1 --tc-heuristic-recover=ROLLBACK --debug=d,info
+--echo *** (4) restart with conflicing recovery options: $restart_parameters.
+--source include/fail_start_mysqld.inc
+
+--let SEARCH_PATTERN= \[ERROR\] Can\'t init tc log
+--source include/search_pattern_in_file++.inc
+
+# The transaction is left intact which can be proved in the dbug mode with
+ --echo *** the following search MUST report NOT FOUND into the result file!
+--let SEARCH_PATTERN= info: rollback xid
+--source include/search_pattern_in_file++.inc
+
+
+--let $restart_parameters= --innodb-force-recovery=0 --innodb-read-only=0 --tc-heuristic-recover=ROLLBACK --debug=d,info
+--echo *** (5) restart with non-conflicing recovery options: $restart_parameters
+--source include/fail_start_mysqld.inc
+
+# Check that the server won't complete initialization due to the
+# heuristic option.
+--let SEARCH_PATTERN= \[ERROR\] Can\'t init tc log
+--source include/search_pattern_in_file++.inc
+
+# Conversely, in dbug mode this time the log witnesses the transaction
+# is rolled back.
+--echo *** the following search MUST report YES FOUND into the result file!
+--let SEARCH_PATTERN= info: rollback xid
+--source include/search_pattern_in_file++.inc
+
+
+--let $restart_parameters= --innodb-force-recovery=0
+--echo *** (6) The server restarts with $restart_parameters and stably now.
+--source include/start_mysqld.inc
+
+# Another prove of (5) rollback
+--echo *** Table must be empty:
+SELECT * FROM t1;
+
+#
+# Cleanup
+#
+DROP TABLE t1;
diff --git a/sql/handler.cc b/sql/handler.cc
index 2696d69bfcf..174034a7eb5 100644
--- a/sql/handler.cc
+++ b/sql/handler.cc
@@ -69,6 +69,14 @@ KEY_CREATE_INFO default_key_create_info=
 ulong total_ha= 0;
 /* number of storage engines (from handlertons[]) that support 2pc */
 ulong total_ha_2pc= 0;
+#ifndef DBUG_OFF
+/*
+  Number of non-mandatory 2pc handlertons whose initialization failed
+  to estimate total_ha_2pc value under supposition of the failures
+  have not occcured.
+*/
+ulong failed_ha_2pc= 0;
+#endif
 /* size of savepoint storage area (see ha_init) */
 ulong savepoint_alloc_size= 0;
 
@@ -641,6 +649,10 @@ err_deinit:
     (void) plugin->plugin->deinit(NULL);
           
 err:
+#ifndef DBUG_OFF
+  if (hton->prepare && hton->state == SHOW_OPTION_YES)
+    failed_ha_2pc++;
+#endif
   my_free(hton);
 err_no_hton_memory:
   plugin->data= NULL;
@@ -1823,7 +1835,7 @@ static my_bool xarecover_handlerton(THD *unused, plugin_ref plugin,
         {
 #ifndef DBUG_OFF
           char buf[XIDDATASIZE*4+6]; // see xid_to_str
-          sql_print_information("ignore xid %s", xid_to_str(buf, info->list+i));
+          DBUG_PRINT("info", ("ignore xid %s", xid_to_str(buf, info->list+i)));
 #endif
           xid_cache_insert(info->list+i, XA_PREPARED);
           info->found_foreign_xids++;
@@ -1840,19 +1852,31 @@ static my_bool xarecover_handlerton(THD *unused, plugin_ref plugin,
             tc_heuristic_recover == TC_HEURISTIC_RECOVER_COMMIT)
         {
 #ifndef DBUG_OFF
-          char buf[XIDDATASIZE*4+6]; // see xid_to_str
-          sql_print_information("commit xid %s", xid_to_str(buf, info->list+i));
+          int rc=
+#endif
+            hton->commit_by_xid(hton, info->list+i);
+#ifndef DBUG_OFF
+          if (rc == 0)
+          {
+            char buf[XIDDATASIZE*4+6]; // see xid_to_str
+            DBUG_PRINT("info", ("commit xid %s", xid_to_str(buf, info->list+i)));
+          }
 #endif
-          hton->commit_by_xid(hton, info->list+i);
         }
         else
         {
 #ifndef DBUG_OFF
-          char buf[XIDDATASIZE*4+6]; // see xid_to_str
-          sql_print_information("rollback xid %s",
-                                xid_to_str(buf, info->list+i));
+          int rc=
+#endif
+            hton->rollback_by_xid(hton, info->list+i);
+#ifndef DBUG_OFF
+          if (rc == 0)
+          {
+            char buf[XIDDATASIZE*4+6]; // see xid_to_str
+            DBUG_PRINT("info", ("rollback xid %s",
+                                xid_to_str(buf, info->list+i)));
+          }
 #endif
-          hton->rollback_by_xid(hton, info->list+i);
         }
       }
       if (got < info->len)
@@ -1874,7 +1898,8 @@ int ha_recover(HASH *commit_list)
   /* commit_list and tc_heuristic_recover cannot be set both */
   DBUG_ASSERT(info.commit_list==0 || tc_heuristic_recover==0);
   /* if either is set, total_ha_2pc must be set too */
-  DBUG_ASSERT(info.dry_run || total_ha_2pc>(ulong)opt_bin_log);
+  DBUG_ASSERT(info.dry_run ||
+              (failed_ha_2pc + total_ha_2pc) > (ulong)opt_bin_log);
 
   if (total_ha_2pc <= (ulong)opt_bin_log)
     DBUG_RETURN(0);
diff --git a/sql/log.cc b/sql/log.cc
index ee92f22adb8..7a24e3743c0 100644
--- a/sql/log.cc
+++ b/sql/log.cc
@@ -8960,8 +8960,10 @@ int TC_LOG_BINLOG::open(const char *opt_name)
 
   if (using_heuristic_recover())
   {
+    mysql_mutex_lock(&LOCK_log);
     /* generate a new binlog to mask a corrupted one */
     open(opt_name, LOG_BIN, 0, WRITE_CACHE, max_binlog_size, 0, TRUE);
+    mysql_mutex_unlock(&LOCK_log);
     cleanup();
     return 1;
   }
diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc
index 526836646d2..b9a89b289f8 100644
--- a/storage/innobase/handler/ha_innodb.cc
+++ b/storage/innobase/handler/ha_innodb.cc
@@ -14446,6 +14446,10 @@ innobase_commit_by_xid(
 
 	DBUG_ASSERT(hton == innodb_hton_ptr);
 
+	if (high_level_read_only) {
+		return(XAER_RMFAIL);
+	}
+
 	trx = trx_get_trx_by_xid(xid);
 
 	if (trx) {
@@ -14473,8 +14477,11 @@ innobase_rollback_by_xid(
 
 	DBUG_ASSERT(hton == innodb_hton_ptr);
 
-	trx = trx_get_trx_by_xid(xid);
+	if (high_level_read_only) {
+		return(XAER_RMFAIL);
+	}
 
+	trx = trx_get_trx_by_xid(xid);
 	if (trx) {
 		int	ret = innobase_rollback_trx(trx);
 		trx_free_for_background(trx);
diff --git a/storage/xtradb/handler/ha_innodb.cc b/storage/xtradb/handler/ha_innodb.cc
index e4238af7747..68664562f97 100644
--- a/storage/xtradb/handler/ha_innodb.cc
+++ b/storage/xtradb/handler/ha_innodb.cc
@@ -15395,6 +15395,10 @@ innobase_commit_by_xid(
 
 	DBUG_ASSERT(hton == innodb_hton_ptr);
 
+	if (high_level_read_only) {
+		return(XAER_RMFAIL);
+	}
+
 	trx = trx_get_trx_by_xid(xid);
 
 	if (trx) {
@@ -15422,8 +15426,11 @@ innobase_rollback_by_xid(
 
 	DBUG_ASSERT(hton == innodb_hton_ptr);
 
-	trx = trx_get_trx_by_xid(xid);
+	if (high_level_read_only) {
+		return(XAER_RMFAIL);
+	}
 
+	trx = trx_get_trx_by_xid(xid);
 	if (trx) {
 		int	ret = innobase_rollback_trx(trx);
 		trx_free_for_background(trx);