MDEV-21910 Deadlock between BF abort and manual KILL command

When high priority replication slave applier encounters lock conflict in innodb,
it will force the conflicting lock holder transaction (victim) to rollback.
This is a must in multi-master sychronous replication model to avoid cluster lock-up.
This high priority victim abort (aka "brute force" (BF) abort), is started
from innodb lock manager while holding the victim's transaction's (trx) mutex.
Depending on the execution state of the victim transaction, it may happen that the
BF abort will call for THD::awake() to wake up the victim transaction for the rollback.
Now, if BF abort requires THD::awake() to be called, then the applier thread executed
locking protocol of: victim trx mutex -> victim THD::LOCK_thd_data

If, at the same time another DBMS super user issues KILL command to abort the same victim,
it will execute locking protocol of: victim THD::LOCK_thd_data  -> victim trx mutex.
These two locking protocol acquire mutexes in opposite order, hence unresolvable mutex locking
deadlock may occur.

The fix in this commit adds THD::wsrep_aborter flag to synchronize who can kill the victim
This flag is set both when BF is called for from innodb and by KILL command.
Either path of victim killing will bail out if victim's wsrep_killed is already
set to avoid mutex conflicts with the other aborter execution. THD::wsrep_aborter
records the aborter THD's ID. This is needed to preserve the right to kill
the victim from different locations for the same aborter thread.
It is also good error logging, to see who is reponsible for the abort.

A new test case was added in galera.galera_bf_kill_debug.test for scenario where
wsrep applier thread and manual KILL command try to kill same idle victim

include/mysql/service_wsrep.h

@@ -87,6 +87,7 @@ 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);
 } *wsrep_service;
 
 #define MYSQL_SERVICE_WSREP_INCLUDED
@@ -130,6 +131,7 @@ 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)
 #else
 
 #define MYSQL_SERVICE_WSREP_STATIC_INCLUDED
@@ -181,6 +183,8 @@ 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 */
@@ -224,5 +228,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);
 #endif
 #endif /* MYSQL_SERVICE_WSREP_INCLUDED */

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

@@ -69,21 +69,5 @@ select * from t1;
 a	b
 2	1
 disconnect node_2a;
-drop table t1;
-connect node_2a, 127.0.0.1, root, , test, $NODE_MYPORT_2;
-connection node_2a;
-CREATE TABLE t1 (i int primary key);
-SET DEBUG_SYNC = "before_wsrep_ordered_commit SIGNAL bwoc_reached WAIT_FOR bwoc_continue";
-INSERT INTO t1 VALUES (1);
-connection node_2;
-SET DEBUG_SYNC = "now WAIT_FOR bwoc_reached";
-SET DEBUG_SYNC = "now SIGNAL bwoc_continue";
-SET DEBUG_SYNC='RESET';
-connection node_2a;
-connection node_2;
-select * from t1;
-i
-1
-disconnect node_2a;
-connection node_2;
+connection node_1;
 drop table t1;

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

+connection node_2;
+connection node_1;
+connection node_2;
+CREATE TABLE t1(a int not null primary key auto_increment,b int) engine=InnoDB;
+insert into t1 values (NULL,1);
+connect node_2a, 127.0.0.1, root, , test, $NODE_MYPORT_2;
+connection node_2a;
+truncate t1;
+insert into t1 values (1,0);
+begin;
+update t1 set b=2 where a=1;
+connection node_2;
+set session wsrep_sync_wait=0;
+connect node_2b, 127.0.0.1, root, , test, $NODE_MYPORT_2;
+connection node_2b;
+SET GLOBAL debug_dbug = "d,sync.before_wsrep_thd_abort";
+connection node_1;
+select * from t1;
+a	b
+1	0
+update t1 set b= 1 where a=1;
+connection node_2b;
+SET SESSION DEBUG_SYNC = "now WAIT_FOR sync.before_wsrep_thd_abort_reached";
+connection node_2;
+SET DEBUG_SYNC= 'before_awake_no_mutex SIGNAL awake_reached WAIT_FOR continue_kill';
+connection node_2b;
+SET DEBUG_SYNC='now WAIT_FOR awake_reached';
+SET GLOBAL debug_dbug = "";
+SET DEBUG_SYNC = "now SIGNAL signal.before_wsrep_thd_abort";
+SET DEBUG_SYNC = "now SIGNAL continue_kill";
+connection node_2;
+connection node_2a;
+select * from t1;
+connection node_2;
+SET DEBUG_SYNC = "RESET";
+drop table t1;
+disconnect node_2a;
+connect node_2a, 127.0.0.1, root, , test, $NODE_MYPORT_2;
+connection node_2a;
+CREATE TABLE t1 (i int primary key);
+SET DEBUG_SYNC = "before_wsrep_ordered_commit SIGNAL bwoc_reached WAIT_FOR bwoc_continue";
+INSERT INTO t1 VALUES (1);
+connection node_2;
+SET DEBUG_SYNC = "now WAIT_FOR bwoc_reached";
+SET DEBUG_SYNC = "now SIGNAL bwoc_continue";
+SET DEBUG_SYNC='RESET';
+connection node_2a;
+connection node_2;
+select * from t1;
+i
+1
+disconnect node_2a;
+connection node_1;
+drop table t1;

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

 connection node_2;
 connection node_1;
+connection node_2;
+call mtr.add_suppression("WSREP: Trying to continue unpaused monitor");
 connection node_1;
 call mtr.add_suppression("WSREP: Trying to continue unpaused monitor");
 CREATE TABLE t1 ENGINE=InnoDB select 1 as a, 1 as b union select 2, 2;

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

 --source include/galera_cluster.inc
 --source include/have_innodb.inc
---source include/have_debug.inc
---source include/have_debug_sync.inc
 
 #
 # Test case 1: Start a transaction on node_2a and kill it
@@ -135,56 +133,9 @@ update t1 set a =5, b=2;
 --eval KILL $k_thread
 --enable_query_log
 
-
 select * from t1;
 
 --disconnect node_2a
 
+--connection node_1
 drop table t1;
-
-
-#
-# Test case 7:
-# run a transaction in node 2, and set a sync point to pause the transaction
-# in commit phase.
-# Through another connection to node 2, kill the committing transaction by
-# KILL QUERY command
-#
-
---connect node_2a, 127.0.0.1, root, , test, $NODE_MYPORT_2
---connection node_2a
---let $connection_id = `SELECT CONNECTION_ID()`
-
-CREATE TABLE t1 (i int primary key);
-
-# Set up sync point
-SET DEBUG_SYNC = "before_wsrep_ordered_commit SIGNAL bwoc_reached WAIT_FOR bwoc_continue";
-
-# Send insert which will block in the sync point above
---send INSERT INTO t1 VALUES (1)
-
---connection node_2
-SET DEBUG_SYNC = "now WAIT_FOR bwoc_reached";
-
---disable_query_log
---disable_result_log
-# victim has passed the point of no return, kill is not possible anymore
---eval KILL QUERY $connection_id
---enable_result_log
---enable_query_log
-
-SET DEBUG_SYNC = "now SIGNAL bwoc_continue";
-SET DEBUG_SYNC='RESET';
---connection node_2a
---error 0,1213
---reap
-
---connection node_2
-# victim was able to complete the INSERT
-select * from t1;
-
---disconnect node_2a
-
---connection node_2
-drop table t1;
-

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

+!include ../galera_2nodes.cnf
+
+[mysqld.1]
+wsrep-debug=SERVER
+
+[mysqld.2]
+wsrep-debug=SERVER

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

+--source include/galera_cluster.inc
+--source include/have_innodb.inc
+--source include/have_debug.inc
+--source include/have_debug_sync.inc
+
+#
+# Test case 7:
+# 1. Start a transaction on node_2,
+#    and leave it pending while holding a row locked
+# 2. set sync point pause applier
+# 3. send a conflicting write on node_1, it will pause
+#    at the sync point
+# 4. though another connection to node_2, kill the local
+#    transaction
+#
+
+--connection node_2
+CREATE TABLE t1(a int not null primary key auto_increment,b int) engine=InnoDB;
+insert into t1 values (NULL,1);
+
+#
+# connection node_2a runs a local transaction, that is victim of BF abort
+# and victim of KILL command by connection node_2
+#
+--connect node_2a, 127.0.0.1, root, , test, $NODE_MYPORT_2
+--connection node_2a
+truncate t1;
+insert into t1 values (1,0);
+
+# start a transaction that will conflict with later applier
+begin;
+update t1 set b=2 where a=1;
+
+--connection node_2
+set session wsrep_sync_wait=0;
+--let $wait_condition = SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE USER = 'root' AND COMMAND = 'Sleep' LIMIT 1
+--source include/wait_condition.inc
+
+--let $k_thread = `SELECT ID FROM INFORMATION_SCHEMA.PROCESSLIST WHERE USER = 'root' AND COMMAND = 'Sleep' LIMIT 1`
+
+# connection node_2b is for controlling debug syn points
+# first set a sync point for applier, to pause during BF aborting
+# and before THD::awake would be called
+#
+--connect node_2b, 127.0.0.1, root, , test, $NODE_MYPORT_2
+--connection node_2b
+SET GLOBAL debug_dbug = "d,sync.before_wsrep_thd_abort";
+
+#
+# replicate an update, which will BF abort the victim node_2a
+# however, while applier in node 2 is handling the abort,
+# it will pause in sync point set by node_2b
+#
+--connection node_1
+select * from t1;
+update t1 set b= 1 where a=1;
+
+#
+# wait until the applying of above update has reached the sync point
+# in node 2
+#
+--connection node_2b
+SET SESSION DEBUG_SYNC = "now WAIT_FOR sync.before_wsrep_thd_abort_reached";
+
+--connection node_2
+#
+# pause KILL execution before awake
+#
+SET DEBUG_SYNC= 'before_awake_no_mutex SIGNAL awake_reached WAIT_FOR continue_kill';
+--disable_query_log
+--send_eval KILL $k_thread
+--enable_query_log
+
+
+--connection node_2b
+SET DEBUG_SYNC='now WAIT_FOR awake_reached';
+
+# release applier and KILL operator
+SET GLOBAL debug_dbug = "";
+SET DEBUG_SYNC = "now SIGNAL signal.before_wsrep_thd_abort";
+SET DEBUG_SYNC = "now SIGNAL continue_kill";
+
+--connection node_2
+--reap
+
+--connection node_2a
+--error 0,1213
+select * from t1;
+
+--connection node_2
+SET DEBUG_SYNC = "RESET";
+
+drop table t1;
+
+--disconnect node_2a
+#
+# Test case 7:
+# run a transaction in node 2, and set a sync point to pause the transaction
+# in commit phase.
+# Through another connection to node 2, kill the committing transaction by
+# KILL QUERY command
+#
+
+--connect node_2a, 127.0.0.1, root, , test, $NODE_MYPORT_2
+--connection node_2a
+--let $connection_id = `SELECT CONNECTION_ID()`
+
+CREATE TABLE t1 (i int primary key);
+
+# Set up sync point
+SET DEBUG_SYNC = "before_wsrep_ordered_commit SIGNAL bwoc_reached WAIT_FOR bwoc_continue";
+
+# Send insert which will block in the sync point above
+--send INSERT INTO t1 VALUES (1)
+
+--connection node_2
+SET DEBUG_SYNC = "now WAIT_FOR bwoc_reached";
+
+--disable_query_log
+--disable_result_log
+# victim has passed the point of no return, kill is not possible anymore
+--eval KILL QUERY $connection_id
+--enable_result_log
+--enable_query_log
+
+SET DEBUG_SYNC = "now SIGNAL bwoc_continue";
+SET DEBUG_SYNC='RESET';
+--connection node_2a
+--error 0,1213
+--reap
+
+--connection node_2
+# victim was able to complete the INSERT
+select * from t1;
+
+--disconnect node_2a
+
+--connection node_1
+drop table t1;
+

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

@@ -2,8 +2,10 @@
 --source include/have_innodb.inc
 --source include/big_test.inc
 
---connection node_1
+--connection node_2
+call mtr.add_suppression("WSREP: Trying to continue unpaused monitor");
 
+--connection node_1
 call mtr.add_suppression("WSREP: Trying to continue unpaused monitor");
 
 CREATE TABLE t1 ENGINE=InnoDB select 1 as a, 1 as b union select 2, 2;

sql/service_wsrep.cc

@@ -199,6 +199,16 @@ extern "C" void wsrep_handle_SR_rollback(THD *bf_thd,
 extern "C" my_bool wsrep_thd_bf_abort(THD *bf_thd, THD *victim_thd,
                                       my_bool signal)
 {
+  DBUG_EXECUTE_IF("sync.before_wsrep_thd_abort",
+                 {
+                   const char act[]=
+                     "now "
+                     "SIGNAL sync.before_wsrep_thd_abort_reached "
+                     "WAIT_FOR signal.before_wsrep_thd_abort";
+                   DBUG_ASSERT(!debug_sync_set_action(bf_thd,
+                                                      STRING_WITH_LEN(act)));
+                 };);
+
   my_bool ret= wsrep_bf_abort(bf_thd, victim_thd);
   /*
     Send awake signal if victim was BF aborted or does not
@@ -210,10 +220,22 @@ extern "C" my_bool wsrep_thd_bf_abort(THD *bf_thd, THD *victim_thd,
     mysql_mutex_assert_not_owner(&victim_thd->LOCK_thd_data);
     mysql_mutex_assert_not_owner(&victim_thd->LOCK_thd_kill);
     mysql_mutex_lock(&victim_thd->LOCK_thd_data);
+
+    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);
+      mysql_mutex_unlock(&victim_thd->LOCK_thd_data);
+      return false;
+    }
+
     mysql_mutex_lock(&victim_thd->LOCK_thd_kill);
+    victim_thd->wsrep_aborter= bf_thd->thread_id;
     victim_thd->awake_no_mutex(KILL_QUERY);
     mysql_mutex_unlock(&victim_thd->LOCK_thd_kill);
     mysql_mutex_unlock(&victim_thd->LOCK_thd_data);
+  } else {
+    WSREP_DEBUG("wsrep_thd_bf_abort skipped awake");
   }
   return ret;
 }
@@ -339,3 +361,15 @@ extern "C" ulong wsrep_OSU_method_get(const MYSQL_THD thd)
   else
     return(global_system_variables.wsrep_OSU_method);
 }
+
+extern "C" bool wsrep_thd_set_wsrep_aborter(THD *bf_thd, THD *victim_thd)
+{
+  WSREP_DEBUG("wsrep_thd_set_wsrep_aborter called");
+  mysql_mutex_assert_owner(&victim_thd->LOCK_thd_data);
+  if (victim_thd->wsrep_aborter && victim_thd->wsrep_aborter != bf_thd->thread_id)
+  {
+    return true;
+  }
+  victim_thd->wsrep_aborter = bf_thd->thread_id;
+  return false;
+}
\ No newline at end of file

sql/sql_class.cc

@@ -706,6 +706,7 @@ THD::THD(my_thread_id id, bool is_wsrep_applier)
    wsrep_affected_rows(0),
    wsrep_has_ignored_error(false),
    wsrep_ignore_table(false),
+   wsrep_aborter(0),
 
 /* wsrep-lib */
    m_wsrep_next_trx_id(WSREP_UNDEFINED_TRX_ID),
@@ -1308,6 +1309,7 @@ void THD::init()
   wsrep_rbr_buf           = NULL;
   wsrep_affected_rows     = 0;
   m_wsrep_next_trx_id     = WSREP_UNDEFINED_TRX_ID;
+  wsrep_aborter           = 0;
 #endif /* WITH_WSREP */
 
   if (variables.sql_log_bin)
@@ -2139,11 +2141,19 @@ void THD::reset_killed()
   DBUG_ENTER("reset_killed");
   if (killed != NOT_KILLED)
   {
+    mysql_mutex_assert_not_owner(&LOCK_thd_kill);
     mysql_mutex_lock(&LOCK_thd_kill);
     killed= NOT_KILLED;
     killed_err= 0;
     mysql_mutex_unlock(&LOCK_thd_kill);
   }
+#ifdef WITH_WSREP
+  mysql_mutex_assert_not_owner(&LOCK_thd_data);
+  mysql_mutex_lock(&LOCK_thd_data);
+  wsrep_aborter= 0;
+  mysql_mutex_unlock(&LOCK_thd_data);
+#endif /* WITH_WSREP */
+
   DBUG_VOID_RETURN;
 }
 

sql/sql_class.h

@@ -5013,7 +5013,8 @@ class THD: public THD_count, /* this must be first */
     table updates from being replicated to other nodes via galera replication.
   */
   bool                      wsrep_ignore_table;
-  
+  /* thread who has started kill for this THD protected by LOCK_thd_data*/
+  my_thread_id              wsrep_aborter;
 
   /*
     Transaction id:

sql/sql_parse.cc

@@ -9149,7 +9149,6 @@ kill_one_thread(THD *thd, longlong id, killed_state kill_signal, killed_type typ
   uint error= (type == KILL_TYPE_QUERY ? ER_NO_SUCH_QUERY : ER_NO_SUCH_THREAD);
   DBUG_ENTER("kill_one_thread");
   DBUG_PRINT("enter", ("id: %lld  signal: %u", id, (uint) kill_signal));
-  WSREP_DEBUG("kill_one_thread %llu", thd->thread_id);
   if (id && (tmp= find_thread_by_id(id, type == KILL_TYPE_QUERY)))
   {
     /*
@@ -9182,12 +9181,29 @@ kill_one_thread(THD *thd, longlong id, killed_state kill_signal, killed_type typ
         thd->security_ctx->user_matches(tmp->security_ctx))
 #endif /* WITH_WSREP */
     {
+#ifdef WITH_WSREP
+      DEBUG_SYNC(thd, "before_awake_no_mutex");
+      if (tmp->wsrep_aborter && tmp->wsrep_aborter != thd->thread_id)
+      {
+        /* victim is in hit list already, bail out */
+	WSREP_DEBUG("victim has wsrep aborter: %lu, skipping awake()",
+                    tmp->wsrep_aborter);
+        error= 0;
+      }
+      else
+#endif /* WITH_WSREP */
+      {
+      WSREP_DEBUG("kill_one_thread %llu, victim: %llu wsrep_aborter %llu by signal %d",
+                  thd->thread_id, id, tmp->wsrep_aborter, kill_signal);
         tmp->awake_no_mutex(kill_signal);
-      error=0;
+        WSREP_DEBUG("victim: %llu taken care of", id);
+        error= 0;
+      }
     }
     else
       error= (type == KILL_TYPE_QUERY ? ER_KILL_QUERY_DENIED_ERROR :
                                         ER_KILL_DENIED_ERROR);
+
     if (WSREP(tmp)) mysql_mutex_unlock(&tmp->LOCK_thd_data);
     mysql_mutex_unlock(&tmp->LOCK_thd_kill);
   }

sql/sql_plugin_services.ic

@@ -177,7 +177,8 @@ static struct wsrep_service_st wsrep_handler = {
   wsrep_thd_is_applying,
   wsrep_OSU_method_get,
   wsrep_thd_has_ignored_error,
-  wsrep_thd_set_ignored_error
+  wsrep_thd_set_ignored_error,
+  wsrep_thd_set_wsrep_aborter
 };
 
 static struct thd_specifics_service_st thd_specifics_handler=

sql/wsrep_dummy.cc

@@ -150,3 +150,5 @@ void wsrep_thd_set_ignored_error(THD*, my_bool)
 { }
 ulong wsrep_OSU_method_get(const THD*)
 { return 0;}
+bool wsrep_thd_set_wsrep_aborter(THD*, THD*)
+{ return 0;}
\ No newline at end of file

storage/innobase/handler/ha_innodb.cc

@@ -19020,10 +19020,17 @@ wsrep_innobase_kill_one_trx(THD* bf_thd, trx_t *victim_trx,
 
 	/* Mark transaction as a victim for Galera abort */
 	victim_trx->lock.was_chosen_as_wsrep_victim= true;
+	if (wsrep_thd_set_wsrep_aborter(bf_thd, thd))
+	{
+	  WSREP_DEBUG("innodb kill transaction skipped due to wsrep_aborter set");
+	  wsrep_thd_UNLOCK(thd);
+	  DBUG_RETURN(0);
+	}
 
 	/* Note that we need to release this as it will be acquired
 	below in wsrep-lib */
 	wsrep_thd_UNLOCK(thd);
+	DEBUG_SYNC(bf_thd, "before_wsrep_thd_abort");
 
 	if (wsrep_thd_bf_abort(bf_thd, thd, signal))
 	{