[MDEV-6749] Deadlock between GRANT/REVOKE, SELECT FROM I_S.COLUMNS, SET slow_query_log and failed connection attempt Created: 2014-09-17  Updated: 2014-10-01  Resolved: 2014-10-01

Status: Closed
Project: MariaDB Server
Component/s: OTHER
Affects Version/s: 5.5.39
Fix Version/s: 5.5.40

Type: Bug Priority: Major
Reporter: Sergey Vojtovich Assignee: Sergey Vojtovich
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
PartOf
is part of MDEV-5089 possible deadlocks between rwlocks an... Closed

 Description   

Deadlock chain:

wrlock(LOCK_grant)                 -> lock(acl_cache->lock)               GRANT/REVOKE CREATE/DROP USER
lock(LOCK_open)                    -> rdlock(LOCK_grant)                  SELECT * FROM INFORMATION_SCHEMA.COLUMNS
wrlock(LOCK_logger)                -> lock(LOCK_open)                     SET @@global.slow_query_log='ON'
lock(acl_cache->lock)              -> rdlock(LOCK_logger)                 Failed connection

MTR test to reproduce this deadlock:

--source include/have_plugin_auth.inc
--source include/have_debug_sync.inc
 
SET @@global.slow_query_log='OFF';
CREATE USER plug_user IDENTIFIED WITH test_plugin_server AS 'plug_dest';
CREATE USER plug_dest IDENTIFIED BY 'plug_dest_passwd';
GRANT PROXY ON plug_dest TO plug_user;
RENAME USER plug_dest TO new_dest;
 
connect(con1, localhost, root,,);
connect(con2, localhost, root,,);
connect(con3, localhost, root,,);
 
connection con1;
SET debug_sync='mysql_grant SIGNAL ready1 WAIT_FOR go1';
SET debug_dbug='+d,mysql_grant';
send REVOKE ALL ON *.* FROM no_such_user@localhost;
 
connection con2;
SET debug_sync='now WAIT_FOR ready1';
SET debug_sync='fill_schema_table_from_frm SIGNAL ready2 WAIT_FOR go2';
send SELECT COUNT(*) FROM INFORMATION_SCHEMA.COLUMNS;
 
connection con3;
SET debug_sync='now WAIT_FOR ready2';
SET debug_sync='activate_log_handler SIGNAL ready3 WAIT_FOR go3';
SET debug_dbug='+d,activate_log_handler';
send SET @@global.slow_query_log='ON';
 
connection default;
SET debug_sync='now WAIT_FOR ready3';
--error 1
--exec $MYSQL -S $MASTER_MYSOCK -u plug_user --password=plug_dest -e "SELECT 1;"
 
connection con1;
--error 1141
reap;
disconnect con1;
 
connection con2;
reap;
disconnect con2;
 
connection con3;
reap;
disconnect con3;
 
connection default;
DROP USER plug_user, new_dest;
SET debug_sync='RESET';

Debug sync points:

=== modified file 'sql/log.cc'
--- sql/log.cc	2014-08-02 19:26:16 +0000
+++ sql/log.cc	2014-09-18 15:16:51 +0000
@@ -1400,7 +1400,12 @@ bool LOGGER::activate_log_handler(THD* t
 {
   MYSQL_QUERY_LOG *file_log;
   bool res= FALSE;
+  DEBUG_SYNC(thd, "activate_log_handler");
   lock_exclusive();
+  DBUG_EXECUTE_IF("activate_log_handler",
+  {
+    debug_sync_set_action(thd, STRING_WITH_LEN("now SIGNAL ready3"));
+  };);
   switch (log_type) {
   case QUERY_LOG_SLOW:
     if (!opt_slow_log)
 
=== modified file 'sql/sql_acl.cc'
--- sql/sql_acl.cc	2014-08-02 19:26:16 +0000
+++ sql/sql_acl.cc	2014-09-18 15:18:52 +0000
@@ -53,6 +53,7 @@
 #include "sql_array.h"
 
 #include "sql_plugin_compat.h"
+#include "debug_sync.h"
 
 bool mysql_user_table_is_in_short_password_format= false;
 
@@ -4142,8 +4143,13 @@ bool mysql_grant(THD *thd, const char *d
   if (!revoke_grant)
     create_new_users= test_if_create_new_users(thd);
 
+  DEBUG_SYNC(thd, "mysql_grant");
   /* go through users in user_list */
   mysql_rwlock_wrlock(&LOCK_grant);
+  DBUG_EXECUTE_IF("mysql_grant",
+  {
+    debug_sync_set_action(thd, STRING_WITH_LEN("now SIGNAL ready1"));
+  };);
   mysql_mutex_lock(&acl_cache->lock);
   grant_version++;
 
@@ -9225,7 +9231,12 @@ bool acl_authenticate(THD *thd, uint con
       if (!acl_proxy_user)
       {
         if (!thd->is_error())
+        {
+          debug_sync_set_action(thd, STRING_WITH_LEN("now SIGNAL go1 WAIT_FOR ready1"));
+          debug_sync_set_action(thd, STRING_WITH_LEN("now SIGNAL go2"));
+          debug_sync_set_action(thd, STRING_WITH_LEN("now SIGNAL go3 WAIT_FOR ready3"));
           login_failed_error(thd);
+        }
         mysql_mutex_unlock(&acl_cache->lock);
         DBUG_RETURN(1);
       }
 
=== modified file 'sql/sql_show.cc'
--- sql/sql_show.cc	2014-08-31 17:55:11 +0000
+++ sql/sql_show.cc	2014-09-18 15:07:47 +0000
@@ -4244,6 +4244,7 @@ static int fill_schema_table_from_frm(TH
   key_length= create_table_def_key(thd, key, &table_list, 0);
   hash_value= my_calc_hash(&table_def_cache, (uchar*) key, key_length);
   mysql_mutex_lock(&LOCK_open);
+  DEBUG_SYNC(thd, "fill_schema_table_from_frm");
   share= get_table_share(thd, &table_list, key,
                          key_length, OPEN_VIEW, &not_used, hash_value);
   if (!share)



 Comments   
Comment by Sergey Vojtovich [ 2014-09-18 ]

Sergei, please review fix for this bug. Even though 10.0 is most probably not affect, I'd recommend to have this fix merged: the less relationships between locks - the better.

Comment by Sergei Golubchik [ 2014-09-30 ]

ok to push, thanks!

Comment by Sergey Vojtovich [ 2014-10-01 ]

Fixed in 5.5.40:

revno: 4296
revision-id: svoj@mariadb.org-20140918154506-24bkasfcnmww3w03
parent: sergii@pisem.net-20140923213735-ftfychfk52moan4e
committer: Sergey Vojtovich <svoj@mariadb.org>
branch nick: 5.5
timestamp: Thu 2014-09-18 19:45:06 +0400
message:
  MDEV-6749 - Deadlock between GRANT/REVOKE, SELECT FROM I_S.COLUMNS,
              SET slow_query_log and failed connection attempt
 
  A very subtle though valid deadlock. Deadlock chain:
  wrlock(LOCK_grant)    -> lock(acl_cache->lock) GRANT/REVOKE CREATE/DROP USER
  lock(LOCK_open)       -> rdlock(LOCK_grant)    SELECT * FROM I_S.COLUMNS
  wrlock(LOCK_logger)   -> lock(LOCK_open)       SET @@global.slow_query_log='ON'
  lock(acl_cache->lock) -> rdlock(LOCK_logger)   Failed connection
 
  Fixed by removing relationship between acl_cache->lock and LOCK_logger
  during failed connection attempt.

Generated at Thu Feb 08 07:14:18 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.