[MDEV-25248] SET GLOBAL server_audit_logging=ON deadlock due to LOCK_global_system_variables Created: 2021-03-25  Updated: 2023-11-28

Status: Open
Project: MariaDB Server
Component/s: Plugins
Affects Version/s: 10.4.8, 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10
Fix Version/s: 10.4, 10.5, 10.6

Type: Bug Priority: Major
Reporter: jinmh Assignee: Sergei Golubchik
Resolution: Unresolved Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-19665 Server hangs on client connection wit... Open
relates to MDEV-22647 Assertion `!check_audit_mask(mysql_gl... Closed
relates to MDEV-29557 Assertion failure or server crash in ... Open

 Description   

INSTALL PLUGIN server_audit SONAME 'server_audit.so';
SET GLOBAL server_audit_logging=ON;

#0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
 
#1  0x00007ffa57d4ae01 in _L_lock_1093 () from /usr/lib64/libpthread.so.0
 
#2  0x00007ffa57d4ada2 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x7ffa59800600 <LOCK_global_system_variables>) at ../nptl/pthread_mutex_lock.c:133
 
#3  0x00007ffa587ad083 in inline_mysql_mutex_lock (src_file=0x7ffa58ead250 "/data01/jinmh/mdb_4.0/mariadb-10.4.8/sql/sql_plugin.cc", src_line=3037, 
    that=<optimized out>) at /data01/jinmh/mdb_4.0/mariadb-10.4.8/include/mysql/psi/mysql_thread.h:712
 
#4  sync_dynamic_session_variables (thd=thd@entry=0x7ff8c0002ea8, global_lock=global_lock@entry=true)
 
    at /data01/jinmh/mdb_4.0/mariadb-10.4.8/sql/sql_plugin.cc:3037
 
#5  0x00007ffa587ad12c in intern_sys_var_ptr (thd=0x7ff8c0002ea8, offset=128, global_lock=<optimized out>)
 
    at /data01/jinmh/mdb_4.0/mariadb-10.4.8/sql/sql_plugin.cc:3104
 
#6  0x00007ff9901f3d25 in get_loc_info (thd=0x7ff8c0002ea8) at /data01/jinmh/mdb_4.0/mariadb-10.4.8/plugin/server_audit/server_audit.c:953
 
#7  mark_always_logged (thd=0x7ff8c0002ea8) at /data01/jinmh/mdb_4.0/mariadb-10.4.8/plugin/server_audit/server_audit.c:2594
 
#8  update_logging (thd=0x7ff8c0002ea8, var=<optimized out>, var_ptr=<optimized out>, save=<optimized out>)
 
    at /data01/jinmh/mdb_4.0/mariadb-10.4.8/plugin/server_audit/server_audit.c:2864
 
#9  0x00007ffa587ad84b in sys_var_pluginvar::global_update (this=0x7ff90c0fbf58, thd=0x7ff8c0002ea8, var=0x7ff8c000acc8)
 
    at /data01/jinmh/mdb_4.0/mariadb-10.4.8/sql/sql_plugin.cc:3567
 
#10 0x00007ffa58703033 in sys_var::update (this=0x7ff90c0fbf58, thd=0x7ff8c0002ea8, var=0x7ff8c000acc8)
 
    at /data01/jinmh/mdb_4.0/mariadb-10.4.8/sql/set_var.cc:208
 
#11 0x00007ffa58703567 in set_var::update (this=<optimized out>, thd=<optimized out>) at /data01/jinmh/mdb_4.0/mariadb-10.4.8/sql/set_var.cc:837
 
#12 0x00007ffa587048c9 in sql_set_variables (thd=thd@entry=0x7ff8c0002ea8, var_list=0x7ff8c000a018, var_list@entry=0x0, free=free@entry=true)
 
    at /data01/jinmh/mdb_4.0/mariadb-10.4.8/sql/set_var.cc:740
 
#13 0x00007ffa587a2a87 in mysql_execute_command (thd=thd@entry=0x7ff8c0002ea8) at /data01/jinmh/mdb_4.0/mariadb-10.4.8/sql/sql_parse.cc:4964
 
#14 0x00007ffa587b25f8 in Execute_sql_statement::execute_server_code (this=<optimized out>, thd=0x7ff8c0002ea8)
 
    at /data01/jinmh/mdb_4.0/mariadb-10.4.8/sql/sql_prepare.cc:3757
 
#15 0x00007ffa587b6141 in Prepared_statement::execute_server_runnable (this=this@entry=0x7ff8ca7f75a0, 
    server_runnable=server_runnable@entry=0x7ff8ca7f7990) at /data01/jinmh/mdb_4.0/mariadb-10.4.8/sql/sql_prepare.cc:4452
 
#16 0x00007ffa587b6ff3 in Ed_connection::execute_direct (this=this@entry=0x7ff8ca7f8260, server_runnable=server_runnable@entry=0x7ff8ca7f7990)
 
    at /data01/jinmh/mdb_4.0/mariadb-10.4.8/sql/sql_prepare.cc:5041
 
#17 0x00007ffa587b70cf in Ed_connection::execute_direct (this=this@entry=0x7ff8ca7f8260, sql_text=...)
 
    at /data01/jinmh/mdb_4.0/mariadb-10.4.8/sql/sql_prepare.cc:5009
 
#18 0x00007ff9a9d40223 in mdb::Mdb_inner_caller::execute_query (this=0x7ff8c0000f40, sql_text=..., result=result@entry=0x7ff8ca7f86b0, 
    errmsg=errmsg@entry=0x7ff8ca7f86d0) at /data01/jinmh/mdb_4.0/mariadb-10.4.8/storage/mdb/src/handler/mdb_inner_caller.cc:269
 
#19 0x00007ff9a9ea6223 in mdb::CMiscWorker::exec_dmdb_sql (param=param@entry=0x7ff9cc1fa900)
 
    at /data01/jinmh/mdb_4.0/mariadb-10.4.8/storage/mdb/src/rpl/mdb_misc_worker.cpp:192
 
#20 0x00007ff9a9eb32ee in mdb::handle_forward_sql (p=0x7ff9cc1fa900)
 
    at /data01/jinmh/mdb_4.0/mariadb-10.4.8/storage/mdb/src/session/mdb_session_service.cc:81
 
#21 0x00007ffa57d48dd5 in start_thread (arg=0x7ff8ca7f9700) at pthread_create.c:307
 
#22 0x00007ffa55855ead in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111



 Comments   
Comment by Alice Sherepa [ 2021-03-25 ]

It is probably a duplicate of MDEV-22647, with the concurrent setting of audit variable.
In a way, that was described - (just install + set) it works as expected.

Comment by Elena Stepanova [ 2022-09-16 ]

MDEV-22647 fixed an assertion failure described there; the other part of the problem, the mutex issue (apparently unrelated to the assertion failure) still exists, and may well be related to the failure described here.
Here is a test case. It is obviously non-deterministic (don't put it into the regression suite!), but it fails well for me on a debug build.

I couldn't however rr it within the whole 100K cycles, even though without rr it fails within seconds.

--connect (con1,localhost,root,,)
 
--let $conid= `select connection_id()`
 
--delimiter $
 
--send
 
  LOOP
 
    INSTALL SONAME 'server_audit';
 
    UNINSTALL SONAME 'server_audit';
 
  END LOOP $
 
--delimiter ;
 
 
 
--connection default
 
--let $run= 100000
 
--disable_query_log
 
while ($run)
 
{
 
  --error 0,ER_UNKNOWN_SYSTEM_VARIABLE
 
  SET GLOBAL SERVER_AUDIT_LOGGING = ON;
 
  --error 0,ER_UNKNOWN_SYSTEM_VARIABLE
 
  SET GLOBAL SERVER_AUDIT_LOGGING = OFF;
 
  --dec $run
 
}
 
--enable_query_log
 
 
 
# Cleanup
 
eval KILL $conid;
 
--error 0,ER_SP_DOES_NOT_EXIST
 
UNINSTALL SONAME 'server_audit';

10.3 debug 32bab2ce

 
safe_mutex: Trying to lock mutex at /data/src/10.3/sql/sql_plugin.cc, line 3017, when the mutex was already locked at /data/src/10.3/sql/sys_vars_shared.h, line 56 in thread T@6
 
220916 17:41:45 [ERROR] mysqld got signal 6 ;
 
 
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#5  0x00007f76c8215537 in __GI_abort () at abort.c:79
 
#6  0x000055f761a35def in safe_mutex_lock (mp=0x55f7624c41c0 <LOCK_global_system_variables>, my_flags=0, file=0x55f761ad44b0 "/data/src/10.3/sql/sql_plugin.cc", line=3017) at /data/src/10.3/mysys/thr_mutex.c:265
 
#7  0x000055f760eadcc8 in inline_mysql_mutex_lock (that=0x55f7624c41c0 <LOCK_global_system_variables>, src_file=0x55f761ad44b0 "/data/src/10.3/sql/sql_plugin.cc", src_line=3017) at /data/src/10.3/include/mysql/psi/mysql_thread.h:702
 
#8  0x000055f760eb6877 in sync_dynamic_session_variables (thd=0x7f76b0000d90, global_lock=true) at /data/src/10.3/sql/sql_plugin.cc:3017
 
#9  0x000055f760eb6c33 in intern_sys_var_ptr (thd=0x7f76b0000d90, offset=104, global_lock=true) at /data/src/10.3/sql/sql_plugin.cc:3084
 
#10 0x000055f760eb6d9d in mysql_sys_var_str (thd=0x7f76b0000d90, offset=104) at /data/src/10.3/sql/sql_plugin.cc:3131
 
#11 0x00007f76c8bfb6ce in get_loc_info (thd=0x7f76b0000d90) at /data/src/10.3/plugin/server_audit/server_audit.c:953
 
#12 0x00007f76c8bffa1b in mark_always_logged (thd=0x7f76b0000d90) at /data/src/10.3/plugin/server_audit/server_audit.c:2699
 
#13 0x00007f76c8c005bf in update_logging (thd=0x7f76b0000d90, var=0x7f76c8c05460 <mysql_sysvar_logging>, var_ptr=0x7f76c8c07294 <logging>, save=0x7f76b0012c58) at /data/src/10.3/plugin/server_audit/server_audit.c:2969
 
#14 0x000055f760eb85a8 in sys_var_pluginvar::global_update (this=0x7f76a4026fd0, thd=0x7f76b0000d90, var=0x7f76b0012c38) at /data/src/10.3/sql/sql_plugin.cc:3545
 
#15 0x000055f760d8e159 in sys_var::update (this=0x7f76a4026fd0, thd=0x7f76b0000d90, var=0x7f76b0012c38) at /data/src/10.3/sql/set_var.cc:208
 
#16 0x000055f760d8ff1c in set_var::update (this=0x7f76b0012c38, thd=0x7f76b0000d90) at /data/src/10.3/sql/set_var.cc:837
 
#17 0x000055f760d8fbb5 in sql_set_variables (thd=0x7f76b0000d90, var_list=0x7f76b0005a78, free=true) at /data/src/10.3/sql/set_var.cc:740
 
#18 0x000055f760e9c751 in mysql_execute_command (thd=0x7f76b0000d90) at /data/src/10.3/sql/sql_parse.cc:4934
 
#19 0x000055f760ea63f2 in mysql_parse (thd=0x7f76b0000d90, rawbuf=0x7f76b0012ad8 "SET GLOBAL SERVER_AUDIT_LOGGING = ON", length=36, parser_state=0x7f76c224b5b0, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7871
 
#20 0x000055f760e92c27 in dispatch_command (command=COM_QUERY, thd=0x7f76b0000d90, packet=0x7f76b0008f31 "SET GLOBAL SERVER_AUDIT_LOGGING = ON", packet_length=36, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1852
 
#21 0x000055f760e915e5 in do_command (thd=0x7f76b0000d90) at /data/src/10.3/sql/sql_parse.cc:1398
 
#22 0x000055f76100ef08 in do_handle_one_connection (connect=0x55f7648f92e0) at /data/src/10.3/sql/sql_connect.cc:1403
 
#23 0x000055f76100ec73 in handle_one_connection (arg=0x55f7648f92e0) at /data/src/10.3/sql/sql_connect.cc:1308
 
#24 0x000055f7619bf81c in pfs_spawn_thread (arg=0x55f7649f9b30) at /data/src/10.3/storage/perfschema/pfs.cc:1869
 
#25 0x00007f76c83bdea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#26 0x00007f76c82eddef in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Generated at Thu Feb 08 09:36:16 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.