MDEV-13437 InnoDB fails to return error for XA COMMIT or XA ROLLBACK in read-only mode

Assertions failed due to incorrect handling of the --tc-heuristic-recover
option when InnoDB is in read-only mode either due to innodb_read_only=1
or innodb_force_recovery>3. InnoDB failed to refuse a XA COMMIT or
XA ROLLBACK operation, and there were errors in the error handling in
the upper layer.

This was fixed by making InnoDB XA operations respect the
high_level_read_only flag. The InnoDB part of the fix and
parts of the test main.tc_heuristic_recover were provided
by Marko Mäkelä.

LOCK_log mutex lock/unlock had to be added to fix MDEV-13438.
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: When merging to 10.2, the file search_pattern_in_file++.inc
should be replaced with the pre-existing search_pattern_in_file.inc.

mysql-test/include/fail_start_mysqld.inc

+# ==== 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

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

mysql-test/include/search_pattern_in_file++.inc

+# 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

mysql-test/include/shutdown_mysqld.inc

+# ==== 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
 

mysql-test/mysql-test-run.pl

@@ -5573,6 +5573,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;
 }
 

mysql-test/r/tc_heuristic_recover.result

+call mtr.add_suppression("Can't init tc log");
+call mtr.add_suppression("Found 1 prepared transactions!");
+call mtr.add_suppression("Aborting");
+set debug_sync='RESET';
+CREATE TABLE t1 (i INT) ENGINE=InnoDB;
+SET GLOBAL innodb_flush_log_at_trx_commit=1;
+FLUSH TABLES;
+set debug_sync='ha_commit_trans_after_prepare WAIT_FOR go';
+INSERT INTO t1 VALUES (1);;
+# Prove that no COMMIT or ROLLBACK occurred yet.
+SELECT * FROM t1;
+i
+SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
+SELECT * FROM t1;
+i
+1
+# Kill the server
+FOUND 1 /was in the XA prepared state/ in mysqld.1.err
+FOUND 1 /Found 1 prepared transactions!/ in mysqld.1.err
+NOT FOUND /\[ERROR\] Can\'t init tc log/ in mysqld.1.err
+FOUND 2 /was in the XA prepared state/ in mysqld.1.err
+FOUND 1 /Found 1 prepared transactions!/ in mysqld.1.err
+FOUND 1 /\[ERROR\] Can\'t init tc log/ in mysqld.1.err
+FOUND 1 /Please restart mysqld without --tc-heuristic-recover/ in mysqld.1.err
+FOUND 3 /was in the XA prepared state/ in mysqld.1.err
+FOUND 1 /Found 1 prepared transactions!/ in mysqld.1.err
+FOUND 2 /\[ERROR\] Can\'t init tc log/ in mysqld.1.err
+FOUND 2 /Please restart mysqld without --tc-heuristic-recover/ in mysqld.1.err
+FOUND 3 /was in the XA prepared state/ in mysqld.1.err
+FOUND 1 /Found 1 prepared transactions!/ in mysqld.1.err
+SET TRANSACTION ISOLATION LEVEL READ COMMITTED;
+SELECT * FROM t1;
+i
+SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
+SELECT * FROM t1;
+i
+DROP TABLE t1;

mysql-test/t/tc_heuristic_recover.test

+# The test verifies a few server/engine recovery option combinations.
+# Specifically, MDEV-13437,13438 are concerned with no crashes
+# due to InnoDB being read-only during --tc-heuristic-recover=ROLLBACK|COMMIT.
+#
+# Initially the test commits a transaction and in the following proceeds
+# throughout some 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 rollback of the transaction.
+#
+--source include/have_innodb.inc
+# The test logics really requires --log-bin.
+--source include/have_binlog_format_mixed.inc
+--source include/have_debug_sync.inc
+--source include/not_embedded.inc
+
+call mtr.add_suppression("Can't init tc log");
+call mtr.add_suppression("Found 1 prepared transactions!");
+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;
+SET GLOBAL innodb_flush_log_at_trx_commit=1;
+FLUSH TABLES; # we need the table post crash-restart, see MDEV-8841.
+
+# 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);
+
+--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
+
+--echo # Prove that no COMMIT or ROLLBACK occurred yet.
+SELECT * FROM t1;
+SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
+SELECT * FROM t1;
+
+# TODO: MDEV-12700 Allow innodb_read_only startup without prior slow shutdown.
+--source include/kill_mysqld.inc
+--let $restart_parameters= --innodb-force-recovery=4
+--source include/fail_start_mysqld.inc
+
+--let SEARCH_PATTERN= was in the XA prepared state
+--source include/search_pattern_in_file++.inc
+--let SEARCH_PATTERN= Found 1 prepared transactions!
+--source include/search_pattern_in_file++.inc
+--let SEARCH_PATTERN= \\[ERROR\\] Can\\'t init tc log
+--source include/search_pattern_in_file++.inc
+
+--let $restart_parameters= --innodb-force-recovery=4 --tc-heuristic-recover=COMMIT
+--source include/fail_start_mysqld.inc
+--let SEARCH_PATTERN= was in the XA prepared state
+--source include/search_pattern_in_file++.inc
+--let SEARCH_PATTERN= Found 1 prepared transactions!
+--source include/search_pattern_in_file++.inc
+--let SEARCH_PATTERN= \\[ERROR\\] Can\\'t init tc log
+--source include/search_pattern_in_file++.inc
+--let SEARCH_PATTERN= Please restart mysqld without --tc-heuristic-recover
+--source include/search_pattern_in_file++.inc
+
+--let $restart_parameters= --tc-heuristic-recover=ROLLBACK
+--source include/fail_start_mysqld.inc
+
+--let SEARCH_PATTERN= was in the XA prepared state
+--source include/search_pattern_in_file++.inc
+--let SEARCH_PATTERN= Found 1 prepared transactions!
+--source include/search_pattern_in_file++.inc
+--let SEARCH_PATTERN= \\[ERROR\\] Can\\'t init tc log
+--source include/search_pattern_in_file++.inc
+--let SEARCH_PATTERN= Please restart mysqld without --tc-heuristic-recover
+--source include/search_pattern_in_file++.inc
+
+--let $restart_parameters=
+--source include/start_mysqld.inc
+
+--let SEARCH_PATTERN= was in the XA prepared state
+--source include/search_pattern_in_file++.inc
+--let SEARCH_PATTERN= Found 1 prepared transactions!
+--source include/search_pattern_in_file++.inc
+
+SET TRANSACTION ISOLATION LEVEL READ COMMITTED;
+SELECT * FROM t1;
+SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
+SELECT * FROM t1;
+#
+# Cleanup
+#
+DROP TABLE t1;

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 @@ int ha_initialize_handlerton(st_plugin_int *plugin)
     (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);

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;
   }

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);

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);