MDEV-29293 MariaDB stuck on starting commit state

The problem seems to be a deadlock between KILL command execution
and BF abort issued by an applier, where:
* KILL has locked victim's LOCK_thd_kill and LOCK_thd_data.
* Applier has innodb side global lock mutex and victim trx mutex.
* KILL is calling innobase_kill_query, and is blocked by innodb
  global lock mutex.
* Applier is in wsrep_innobase_kill_one_trx and is blocked by
  victim's LOCK_thd_kill.

The fix in this commit removes the TOI replication of KILL command
and makes KILL execution less intrusive operation. Aborting the
victim happens now by using awake_no_mutex() and ha_abort_transaction().
If the KILL happens when the transaction is committing, the
KILL operation is postponed to happen after the statement
has completed in order to avoid KILL to interrupt commit
processing.

Notable changes in this commit:
* wsrep client connections's error state may remain sticky after
  client connection is closed. This error message will then pop
  up for the next client session issuing first SQL statement.
  This problem raised with test galera.galera_bf_kill.
  The fix is to reset wsrep client error state, before a THD is
  reused for next connetion.
* Release THD locks in wsrep_abort_transaction when locking
  innodb mutexes. This guarantees same locking order as with applier
  BF aborting.
* BF abort from MDL was changed to do BF abort on server/wsrep-lib
  side first, and only then do the BF abort on InnoDB side. This
  removes the need to call back from InnoDB for BF aborts which originate
  from MDL and simplifies the locking.
* Removed wsrep_thd_set_wsrep_aborter() from service_wsrep.h.
  The manipulation of the wsrep_aborter can be done solely on
  server side. Moreover, it is now debug only variable and
  could be excluded from optimized builds.
* Remove LOCK_thd_kill from wsrep_thd_LOCK/UNLOCK to allow more
  fine grained locking for SR BF abort which may require locking
  of victim LOCK_thd_kill. Added explicit call for
  wsrep_thd_kill_LOCK/UNLOCK where appropriate.
* Wsrep-lib was updated to version which allows external
  locking for BF abort calls.

Changes to MTR tests:
* Disable galera_bf_abort_group_commit. This test is going to
  be removed (MDEV-30855).
* Record galera_gcache_recover_manytrx as result file was incomplete.
  Trivial change.
* Make galera_create_table_as_select more deterministic:
  Wait until CTAS execution has reached MDL wait for multi-master
  conflict case. Expected error from multi-master conflict is
  ER_QUERY_INTERRUPTED. This is because CTAS does not yet have open
  wsrep transaction when it is waiting for MDL, query gets interrupted
  instead of BF aborted. This should be addressed in separate task.
* A new test galera_kill_group_commit to verify correct behavior
  when KILL is executed while the transaction is committing.

Co-authored-by: Seppo Jaakola <seppo.jaakola@iki.fi>
Co-authored-by: Jan Lindström <jan.lindstrom@galeracluster.com>
Signed-off-by: Julius Goryavsky <julius.goryavsky@mariadb.com>

Author: 3 people

include/mysql/service_wsrep.h

@@ -57,6 +57,7 @@ extern struct wsrep_service_st {
   my_bool                     (*wsrep_on_func)(const MYSQL_THD thd);
   bool                        (*wsrep_prepare_key_for_innodb_func)(MYSQL_THD thd, const unsigned char*, size_t, const unsigned char*, size_t, struct wsrep_buf*, size_t*);
   void                        (*wsrep_thd_LOCK_func)(const MYSQL_THD thd);
+  int                         (*wsrep_thd_TRYLOCK_func)(const MYSQL_THD thd);
   void                        (*wsrep_thd_UNLOCK_func)(const MYSQL_THD thd);
   const char *                (*wsrep_thd_query_func)(const MYSQL_THD thd);
   int                         (*wsrep_thd_retry_counter_func)(const MYSQL_THD thd);
@@ -86,7 +87,6 @@ extern struct wsrep_service_st {
   ulong                       (*wsrep_OSU_method_get_func)(const MYSQL_THD thd);
   my_bool                     (*wsrep_thd_has_ignored_error_func)(const MYSQL_THD thd);
   void                        (*wsrep_thd_set_ignored_error_func)(MYSQL_THD thd, my_bool val);
-  bool                        (*wsrep_thd_set_wsrep_aborter_func)(MYSQL_THD bf_thd, MYSQL_THD thd);
   void                        (*wsrep_report_bf_lock_wait_func)(const MYSQL_THD thd,
                                                                 unsigned long long trx_id);
   void                        (*wsrep_thd_kill_LOCK_func)(const MYSQL_THD thd);
@@ -108,6 +108,7 @@ extern struct wsrep_service_st {
 #define wsrep_on(thd) (thd) && WSREP_ON && wsrep_service->wsrep_on_func(thd)
 #define wsrep_prepare_key_for_innodb(A,B,C,D,E,F,G) wsrep_service->wsrep_prepare_key_for_innodb_func(A,B,C,D,E,F,G)
 #define wsrep_thd_LOCK(T) wsrep_service->wsrep_thd_LOCK_func(T)
+#define wsrep_thd_TRYLOCK(T) wsrep_service->wsrep_thd_TRYLOCK_func(T)
 #define wsrep_thd_UNLOCK(T) wsrep_service->wsrep_thd_UNLOCK_func(T)
 #define wsrep_thd_kill_LOCK(T) wsrep_service->wsrep_thd_kill_LOCK_func(T)
 #define wsrep_thd_kill_UNLOCK(T) wsrep_service->wsrep_thd_kill_UNLOCK_func(T)
@@ -136,7 +137,6 @@ extern struct wsrep_service_st {
 #define wsrep_OSU_method_get(T) wsrep_service->wsrep_OSU_method_get_func(T)
 #define wsrep_thd_has_ignored_error(T) wsrep_service->wsrep_thd_has_ignored_error_func(T)
 #define wsrep_thd_set_ignored_error(T,V) wsrep_service->wsrep_thd_set_ignored_error_func(T,V)
-#define wsrep_thd_set_wsrep_aborter(T) wsrep_service->wsrep_thd_set_wsrep_aborter_func(T1, T2)
 #define wsrep_report_bf_lock_wait(T,I) wsrep_service->wsrep_report_bf_lock_wait(T,I)
 #define wsrep_thd_set_PA_unsafe(T) wsrep_service->wsrep_thd_set_PA_unsafe_func(T)
 #else
@@ -170,6 +170,8 @@ void wsrep_set_data_home_dir(const char *data_dir);
 extern "C" my_bool wsrep_on(const MYSQL_THD thd);
 /* Lock thd wsrep lock */
 extern "C" void wsrep_thd_LOCK(const MYSQL_THD thd);
+/* Try thd wsrep lock. Return non-zero if lock could not be taken. */
+extern "C" int wsrep_thd_TRYLOCK(const MYSQL_THD thd);
 /* Unlock thd wsrep lock */
 extern "C" void wsrep_thd_UNLOCK(const MYSQL_THD thd);
 
@@ -192,8 +194,6 @@ extern "C" my_bool wsrep_thd_is_local(const MYSQL_THD thd);
 /* Return true if thd is in high priority mode */
 /* todo: rename to is_high_priority() */
 extern "C" my_bool wsrep_thd_is_applying(const MYSQL_THD thd);
-/* set wsrep_aborter for the target THD */
-extern "C" bool wsrep_thd_set_wsrep_aborter(MYSQL_THD bf_thd, MYSQL_THD victim_thd);
 /* Return true if thd is in TOI mode */
 extern "C" my_bool wsrep_thd_is_toi(const MYSQL_THD thd);
 /* Return true if thd is in replicating TOI mode */
@@ -237,7 +237,6 @@ extern "C" my_bool wsrep_thd_is_applying(const MYSQL_THD thd);
 extern "C" ulong wsrep_OSU_method_get(const MYSQL_THD thd);
 extern "C" my_bool wsrep_thd_has_ignored_error(const MYSQL_THD thd);
 extern "C" void wsrep_thd_set_ignored_error(MYSQL_THD thd, my_bool val);
-extern "C" bool wsrep_thd_set_wsrep_aborter(MYSQL_THD bf_thd, MYSQL_THD victim_thd);
 extern "C" void wsrep_report_bf_lock_wait(const THD *thd,
                                           unsigned long long trx_id);
 /* declare parallel applying unsafety for the THD */

mysql-test/suite/galera/disabled.def

@@ -22,3 +22,5 @@ MDEV-26575 : MDEV-29878 Galera test failure on MDEV-26575
 galera_bf_abort_shutdown : MDEV-29918 Assertion failure on galera_bf_abort_shutdown
 galera_wan : [ERROR] WSREP: /home/buildbot/buildbot/build/gcs/src/gcs_state_msg.cpp:gcs_state_msg_get_quorum():947: Failed to establish quorum.
 galera_var_ignore_apply_errors : 28: "Server did not transition to READY state"
+MDEV-27713 : test is using get_lock(), which is now rejected in cluster
+galera_bf_abort_group_commit : MDEV-30855 PR to remove the test exists

mysql-test/suite/galera/r/MDEV-29293.result

@@ -0,0 +1,21 @@
+connection node_2;
+connection node_1;
+connect node_1a, 127.0.0.1, root, , test, $NODE_MYPORT_1;
+connect node_1b, 127.0.0.1, root, , test, $NODE_MYPORT_1;
+set wsrep_sync_wait = 0;
+CREATE TABLE t1(a int not null primary key auto_increment, b int) engine=InnoDB;
+INSERT INTO t1 VALUES (1,2);
+connection node_1a;
+BEGIN;
+UPDATE t1 SET b=3 WHERE a=1;
+connection node_1;
+set debug_sync='wsrep_kill_before_awake_no_mutex SIGNAL before_kill WAIT_FOR continue';
+connection node_1b;
+set debug_sync= 'now WAIT_FOR before_kill';
+connection node_2;
+UPDATE t1 SET b=7 WHERE a=1;
+connection node_1b;
+set debug_sync= 'now SIGNAL continue';
+connection node_1;
+DROP TABLE t1;
+SET DEBUG_SYNC= 'RESET';

mysql-test/suite/galera/r/galera_create_table_as_select.result

@@ -82,6 +82,7 @@ connect node_1a, 127.0.0.1, root, , test, $NODE_MYPORT_1;
 LOCK TABLE t2 WRITE;
 connection node_1;
 CREATE TABLE t1 AS SELECT * FROM t2;;
+connection node_1a;
 connection node_2;
 SELECT COUNT(*) = 5 FROM t2;
 COUNT(*) = 5

mysql-test/suite/galera/r/galera_gcache_recover_manytrx.result

@@ -134,6 +134,3 @@ connection node_1;
 call mtr.add_suppression("Error in Log_event::read_log_event():.*");
 CALL mtr.add_suppression("conflict state 7 after post commit");
 CALL mtr.add_suppression("Skipped GCache ring buffer recovery");
-connection node_2;
-call mtr.add_suppression("Error in Log_event::read_log_event():.*");
-CALL mtr.add_suppression("Skipped GCache ring buffer recovery");

mysql-test/suite/galera/r/galera_kill_group_commit.result

@@ -0,0 +1,27 @@
+connection node_2;
+connection node_1;
+connect node_1_kill, 127.0.0.1, root, , test, $NODE_MYPORT_1;
+connect node_1_ctrl, 127.0.0.1, root, , test, $NODE_MYPORT_1;
+SET SESSION wsrep_sync_wait = 0;
+connect node_1_follower, 127.0.0.1, root, , test, $NODE_MYPORT_1;
+SET SESSION wsrep_sync_wait = 0;
+connection node_1;
+CREATE TABLE t1 (f1 INT PRIMARY KEY) ENGINE=InnoDB;
+SET SESSION DEBUG_SYNC = "commit_before_enqueue SIGNAL leader_before_enqueue_reached WAIT_FOR leader_before_enqueue_continue";
+INSERT INTO t1 VALUES (1);
+connection node_1_ctrl;
+SET DEBUG_SYNC = "now WAIT_FOR leader_before_enqueue_reached";
+connection node_1_follower;
+INSERT INTO t1 VALUES (2);;
+connection node_1_ctrl;
+connection node_1_kill;
+# Execute KILL QUERY for group commit follower
+SET DEBUG_SYNC = "now SIGNAL leader_before_enqueue_continue";
+connection node_1_follower;
+connection node_1;
+SELECT * FROM t1;
+f1
+1
+2
+SET DEBUG_SYNC = "RESET";
+DROP TABLE t1;

mysql-test/suite/galera/t/MDEV-29293.test

@@ -0,0 +1,41 @@
+--source include/galera_cluster.inc
+--source include/have_innodb.inc
+--source include/have_debug_sync.inc
+--source include/galera_have_debug_sync.inc
+
+--connect node_1a, 127.0.0.1, root, , test, $NODE_MYPORT_1
+--connect node_1b, 127.0.0.1, root, , test, $NODE_MYPORT_1
+set wsrep_sync_wait = 0;
+
+CREATE TABLE t1(a int not null primary key auto_increment, b int) engine=InnoDB;
+INSERT INTO t1 VALUES (1,2); 
+
+--connection node_1a
+--let $victim_id = `SELECT CONNECTION_ID()`
+BEGIN;
+UPDATE t1 SET b=3 WHERE a=1;
+
+--connection node_1
+set debug_sync='wsrep_kill_before_awake_no_mutex SIGNAL before_kill WAIT_FOR continue';
+--disable_query_log
+--disable_result_log
+--send_eval KILL CONNECTION $victim_id 
+--enable_result_log
+--enable_query_log
+
+--connection node_1b
+set debug_sync= 'now WAIT_FOR before_kill';
+
+--connection node_2
+UPDATE t1 SET b=7 WHERE a=1;
+
+--connection node_1b 
+--let $wait_condition = SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE User = 'system user' AND  State LIKE 'Update_rows_log_event%'; 
+--source include/wait_condition.inc
+set debug_sync= 'now SIGNAL continue'; 
+
+--connection node_1
+--reap 
+DROP TABLE t1;
+SET DEBUG_SYNC= 'RESET';
+

mysql-test/suite/galera/t/galera_create_table_as_select.test

@@ -113,6 +113,10 @@ LOCK TABLE t2 WRITE;
 --connection node_1
 --send CREATE TABLE t1 AS SELECT * FROM t2;
 
+--connection node_1a
+--let $wait_condition = SELECT COUNT(*) = 1 FROM information_schema.processlist WHERE STATE LIKE 'Waiting for table metadata lock%'
+--source include/wait_condition.inc
+
 --connection node_2
 SELECT COUNT(*) = 5 FROM t2;
 CREATE TABLE t1 AS SELECT * FROM t2;
@@ -121,7 +125,7 @@ CREATE TABLE t1 AS SELECT * FROM t2;
 UNLOCK TABLES;
 
 --connection node_1
---error ER_TABLE_EXISTS_ERROR,ER_LOCK_DEADLOCK
+--error ER_TABLE_EXISTS_ERROR,ER_QUERY_INTERRUPTED
 --reap
 
 DROP TABLE t1, t2;

mysql-test/suite/galera/t/galera_kill_group_commit.cnf

@@ -0,0 +1,5 @@
+!include ../galera_2nodes.cnf
+
+[mysqld]
+log-bin
+log-slave-updates

mysql-test/suite/galera/t/galera_kill_group_commit.test

@@ -0,0 +1,69 @@
+#
+# Verify that transaction which has reached group commit queue
+# cannot be killed. If the kill succeeds, assertion for
+# wsrep transaction state will fail.
+#
+# If the bug is present, i.e. wsrep transaction gets killed during
+# group commit wait, this test is enough to reproduce the crash
+# most of the time.
+#
+
+--source include/have_innodb.inc
+--source include/have_debug_sync.inc
+--source include/galera_cluster.inc
+
+# Connection for KILL commands
+--connect node_1_kill, 127.0.0.1, root, , test, $NODE_MYPORT_1
+# Connection for sync point control
+--connect node_1_ctrl, 127.0.0.1, root, , test, $NODE_MYPORT_1
+SET SESSION wsrep_sync_wait = 0;
+# Connection for group commit follower
+--connect node_1_follower, 127.0.0.1, root, , test, $NODE_MYPORT_1
+# Need to disable sync wait to reach commit queue when leader
+# is blocked.
+SET SESSION wsrep_sync_wait = 0;
+--let $follower_id = `SELECT CONNECTION_ID()`
+
+--connection node_1
+CREATE TABLE t1 (f1 INT PRIMARY KEY) ENGINE=InnoDB;
+
+SET SESSION DEBUG_SYNC = "commit_before_enqueue SIGNAL leader_before_enqueue_reached WAIT_FOR leader_before_enqueue_continue";
+--send INSERT INTO t1 VALUES (1)
+
+--connection node_1_ctrl
+SET DEBUG_SYNC = "now WAIT_FOR leader_before_enqueue_reached";
+
+--connection node_1_follower
+# SET SESSION DEBUG_SYNC = "group_commit_waiting_for_prior SIGNAL follower_waiting_for_prior_reached WAIT_FOR follower_waiting_for_prior_continue";
+--send INSERT INTO t1 VALUES (2);
+
+--connection node_1_ctrl
+# TODO: Is it possible to use sync points to enforce group commit to happen?
+# The leader will hold commit monitor in commit_before_enqueue sync point,
+# which prevents the follower to reach the group commit wait state.
+# We now sleep and expect the follower to reach group commit, but this
+# may cause false negatives.
+--sleep 1
+
+--connection node_1_kill
+--echo # Execute KILL QUERY for group commit follower
+--disable_query_log
+--disable_result_log
+# Because it is currently impossible to verify that the
+# follower has reached group commit queue, the KILL may
+# sometimes return success.
+--error 0,ER_KILL_DENIED_ERROR
+--eval KILL QUERY $follower_id
+--enable_result_log
+--enable_query_log
+
+SET DEBUG_SYNC = "now SIGNAL leader_before_enqueue_continue";
+--connection node_1_follower
+--reap
+
+--connection node_1
+--reap
+SELECT * FROM t1;
+
+SET DEBUG_SYNC = "RESET";
+DROP TABLE t1;

sql/handler.cc

@@ -7599,6 +7599,9 @@ Compare_keys handler::compare_key_parts(const Field &old_field,
   concurrent accesses. And it's an overkill to take LOCK_plugin and
   iterate the whole installed_htons[] array every time.
 
+  @note Object victim_thd is not guaranteed to exist after this
+        function returns.
+
   @param bf_thd       brute force THD asking for the abort
   @param victim_thd   victim THD to be aborted
 
@@ -7612,6 +7615,8 @@ int ha_abort_transaction(THD *bf_thd, THD *victim_thd, my_bool signal)
   if (!WSREP(bf_thd) &&
       !(bf_thd->variables.wsrep_OSU_method == WSREP_OSU_RSU &&
         wsrep_thd_is_toi(bf_thd))) {
+    mysql_mutex_unlock(&victim_thd->LOCK_thd_data);
+    mysql_mutex_unlock(&victim_thd->LOCK_thd_kill);
     DBUG_RETURN(0);
   }
 
@@ -7623,6 +7628,8 @@ int ha_abort_transaction(THD *bf_thd, THD *victim_thd, my_bool signal)
   else
   {
     WSREP_WARN("Cannot abort InnoDB transaction");
+    mysql_mutex_unlock(&victim_thd->LOCK_thd_data);
+    mysql_mutex_unlock(&victim_thd->LOCK_thd_kill);
   }
 
   DBUG_RETURN(0);

sql/service_wsrep.cc

@@ -29,14 +29,17 @@ extern "C" my_bool wsrep_on(const THD *thd)
 
 extern "C" void wsrep_thd_LOCK(const THD *thd)
 {
-  mysql_mutex_lock(&thd->LOCK_thd_kill);
   mysql_mutex_lock(&thd->LOCK_thd_data);
 }
 
+extern "C" int wsrep_thd_TRYLOCK(const THD *thd)
+{
+  return mysql_mutex_trylock(&thd->LOCK_thd_data);
+}
+
 extern "C" void wsrep_thd_UNLOCK(const THD *thd)
 {
   mysql_mutex_unlock(&thd->LOCK_thd_data);
-  mysql_mutex_unlock(&thd->LOCK_thd_kill);
 }
 
 extern "C" void wsrep_thd_kill_LOCK(const THD *thd)
@@ -248,21 +251,12 @@ extern "C" my_bool wsrep_thd_bf_abort(THD *bf_thd, THD *victim_thd,
 
   if ((ret || !wsrep_on(victim_thd)) && signal)
   {
-    if (victim_thd->wsrep_aborter && victim_thd->wsrep_aborter != bf_thd->thread_id)
-    {
-      WSREP_DEBUG("victim is killed already by %llu, skipping awake",
-                  victim_thd->wsrep_aborter);
-      wsrep_thd_UNLOCK(victim_thd);
-      return false;
-    }
-
-    victim_thd->wsrep_aborter= bf_thd->thread_id;
     victim_thd->awake_no_mutex(KILL_QUERY_HARD);
   }
   else
-    WSREP_DEBUG("wsrep_thd_bf_abort skipped awake for %llu", thd_get_thread_id(victim_thd));
+    WSREP_DEBUG("wsrep_thd_bf_abort skipped awake for %llu",
+                thd_get_thread_id(victim_thd));
 
-  wsrep_thd_UNLOCK(victim_thd);
   return ret;
 }
 
@@ -385,25 +379,6 @@ extern "C" ulong wsrep_OSU_method_get(const MYSQL_THD thd)
     return(global_system_variables.wsrep_OSU_method);
 }
 
-extern "C" bool wsrep_thd_set_wsrep_aborter(THD *bf_thd, THD *victim_thd)
-{
-  mysql_mutex_assert_owner(&victim_thd->LOCK_thd_data);
-  if (!bf_thd)
-  {
-    victim_thd->wsrep_aborter= 0;
-    WSREP_DEBUG("wsrep_thd_set_wsrep_aborter resetting wsrep_aborter");
-    return false;
-  }
-  if (victim_thd->wsrep_aborter && victim_thd->wsrep_aborter != bf_thd->thread_id)
-  {
-    return true;
-  }
-  victim_thd->wsrep_aborter= bf_thd->thread_id;
-  WSREP_DEBUG("wsrep_thd_set_wsrep_aborter setting wsrep_aborter %u",
-              victim_thd->wsrep_aborter);
-  return false;
-}
-
 extern "C" void wsrep_report_bf_lock_wait(const THD *thd,
                                           unsigned long long trx_id)
 {