[MDEV-19672] safe_mutex: Trying to lock mutex, when the mutex was already locked upon concurrent INSTALL SONAME and and SET variable Created: 2019-06-02  Updated: 2023-04-24

Status: Open
Project: MariaDB Server
Component/s: Plugin - Audit
Affects Version/s: 5.5, 10.1, 10.2, 10.3, 10.4
Fix Version/s: 10.4

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Dmitry Shulga
Resolution: Unresolved Votes: 0
Labels: None


 Description   

Note: The scenario that the test implements (by installing/uninstalling the plugin a thousand times) is crazy, but it is just for the better efficiency while reproducing. The original problem is the honest race condition, when one connection was normally installing the plugin just once, and another connection was too hasty at setting a variable for the plugin. It can be reproduced the same way, the probability is about the same or even better than with multiple install/uninstall, but the necessity to restart the server every time makes the test run much slower. You can still do it that way by simply uncommenting restart_mysqld.inc in the test.

Note: It fails fairly quickly for me usually (in the first ~50-100 loops, which means within a few seconds), but it can vary significantly on different machines and builds. Increase the value of $run or run with --repeat if it doesn't fail for you right away.

--let $run= 1000
 
 
 
--enable_reconnect
 
--connect (con1,localhost,root,,test)
 
--enable_reconnect
 
 
 
while ($run)
 
{
 
    --echo # $run attempts left
 
    --connection con1
 
    --send
 
      INSTALL SONAME 'server_audit';
 
    --connection default
 
    SELECT * FROM INFORMATION_SCHEMA.TABLES LIMIT 0;
 
    --error 0,ER_UNKNOWN_SYSTEM_VARIABLE
 
    SET GLOBAL SERVER_AUDIT_SYSLOG_FACILITY = LOG_CRON;
 
 
 
    --connection con1
 
    --reap
 
    UNINSTALL SONAME 'server_audit';
 
    --dec $run
 
#    --source include/restart_mysqld.inc
 
}
 
 
 
--disconnect con1

10.3 e99ed820

 
190602 21:55:41 server_audit: Query cache is enabled with the TABLE events. Some table reads can be veiled.safe_mutex: Trying to lock mutex at /data/src/10.3/sql/sql_plugin.cc, 
line 3000, when the mutex was already locked at /data/src/10.3/sql/sys_vars_shared.h, line 56 in thread T@6
 
190602 21:55:41 [ERROR] mysqld got signal 6 ;
 
 
 
#5  0x00007f8526b6e42a in __GI_abort () at abort.c:89
 
#6  0x0000561ad9026412 in safe_mutex_lock (mp=0x561ad9cb7b40 <LOCK_global_system_variables>, my_flags=0, file=0x561ad90f1b88 "/data/src/10.3/sql/sql_plugin.cc", line=3000) at /data/src/10.3/mysys/thr_mutex.c:265
 
#7  0x0000561ad859453f in inline_mysql_mutex_lock (that=0x561ad9cb7b40 <LOCK_global_system_variables>, src_file=0x561ad90f1b88 "/data/src/10.3/sql/sql_plugin.cc", src_line=3000) at /data/src/10.3/include/mysql/psi/mysql_thread.h:695
 
#8  0x0000561ad859cad0 in sync_dynamic_session_variables (thd=0x7f8510000b00, global_lock=true) at /data/src/10.3/sql/sql_plugin.cc:3000
 
#9  0x0000561ad859cdec in intern_sys_var_ptr (thd=0x7f8510000b00, offset=104, global_lock=true) at /data/src/10.3/sql/sql_plugin.cc:3067
 
#10 0x0000561ad859cf57 in mysql_sys_var_str (thd=0x7f8510000b00, offset=104) at /data/src/10.3/sql/sql_plugin.cc:3114
 
#11 0x00007f8520ac40f0 in get_loc_info (thd=0x7f8510000b00) at /data/src/10.3/plugin/server_audit/server_audit.c:924
 
#12 0x00007f8520ac7ed2 in mark_always_logged (thd=0x7f8510000b00) at /data/src/10.3/plugin/server_audit/server_audit.c:2551
 
#13 0x00007f8520ac87b2 in update_syslog_facility (thd=0x7f8510000b00, var=0x7f8520ccc660 <mysql_sysvar_syslog_facility>, var_ptr=0x7f8520ccd570 <syslog_facility>, save=0x7f8510012a48) at /data/src/10.3/plugin/server_audit/server_audit.c:2776
 
#14 0x0000561ad859e47a in sys_var_pluginvar::global_update (this=0x7f850403d1e8, thd=0x7f8510000b00, var=0x7f8510012a28) at /data/src/10.3/sql/sql_plugin.cc:3530
 
#15 0x0000561ad84837e9 in sys_var::update (this=0x7f850403d1e8, thd=0x7f8510000b00, var=0x7f8510012a28) at /data/src/10.3/sql/set_var.cc:208
 
#16 0x0000561ad8485538 in set_var::update (this=0x7f8510012a28, thd=0x7f8510000b00) at /data/src/10.3/sql/set_var.cc:837
 
#17 0x0000561ad84851c3 in sql_set_variables (thd=0x7f8510000b00, var_list=0x7f85100057b8, free=true) at /data/src/10.3/sql/set_var.cc:740
 
#18 0x0000561ad858433f in mysql_execute_command (thd=0x7f8510000b00) at /data/src/10.3/sql/sql_parse.cc:5154
 
#19 0x0000561ad858d988 in mysql_parse (thd=0x7f8510000b00, rawbuf=0x7f8510012808 "SET GLOBAL SERVER_AUDIT_SYSLOG_FACILITY = LOG_CRON", length=50, parser_state=0x7f8520d645f0, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:8105
 
#20 0x0000561ad857a9ca in dispatch_command (command=COM_QUERY, thd=0x7f8510000b00, packet=0x7f851011de61 "SET GLOBAL SERVER_AUDIT_SYSLOG_FACILITY = LOG_CRON", packet_length=50, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1858
 
#21 0x0000561ad85793ed in do_command (thd=0x7f8510000b00) at /data/src/10.3/sql/sql_parse.cc:1403
 
#22 0x0000561ad86e2133 in do_handle_one_connection (connect=0x561adb986730) at /data/src/10.3/sql/sql_connect.cc:1402
 
#23 0x0000561ad86e1eaa in handle_one_connection (arg=0x561adb986730) at /data/src/10.3/sql/sql_connect.cc:1308
 
#24 0x0000561ad8fba7e0 in pfs_spawn_thread (arg=0x561adb8e1dd0) at /data/src/10.3/storage/perfschema/pfs.cc:1862
 
#25 0x00007f85286da4a4 in start_thread (arg=0x7f8520d65700) at pthread_create.c:456
 
#26 0x00007f8526c22d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

all threads

 
Thread 7 (Thread 0x7f8528af3740 (LWP 15528)):
 
#0  0x00007f8526c198bd in poll () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x0000561ad8463349 in handle_connections_sockets () at /data/src/10.3/sql/mysqld.cc:6758
 
#2  0x0000561ad846260d in mysqld_main (argc=129, argv=0x561adb6793f0) at /data/src/10.3/sql/mysqld.cc:6227
 
#3  0x0000561ad8456a00 in main (argc=6, argv=0x7ffd0a636de8) at /data/src/10.3/sql/main.cc:25
 
 
 
Thread 6 (Thread 0x7f8520d1a700 (LWP 15541)):
 
#0  0x00007f8526c198bd in poll () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x0000561ad9087ae6 in vio_io_wait (vio=0x561adb8c6b30, event=VIO_IO_EVENT_READ, timeout=28800000) at /data/src/10.3/vio/viosocket.c:962
 
#2  0x0000561ad90861e3 in vio_socket_io_wait (vio=0x561adb8c6b30, event=VIO_IO_EVENT_READ) at /data/src/10.3/vio/viosocket.c:119
 
#3  0x0000561ad90863cb in vio_read (vio=0x561adb8c6b30, buf=0x7f8504008c60 "\a", size=4) at /data/src/10.3/vio/viosocket.c:196
 
#4  0x0000561ad846ebe7 in my_real_read (net=0x7f8504000de8, complen=0x7f8520d19d50, header=1 '\001') at /data/src/10.3/sql/net_serv.cc:962
 
#5  0x0000561ad846f46a in my_net_read_packet_reallen (net=0x7f8504000de8, read_from_server=1 '\001', reallen=0x7f8520d19db8) at /data/src/10.3/sql/net_serv.cc:1243
 
#6  0x0000561ad846f41e in my_net_read_packet (net=0x7f8504000de8, read_from_server=1 '\001') at /data/src/10.3/sql/net_serv.cc:1227
 
#7  0x0000561ad8578ec8 in do_command (thd=0x7f8504000b00) at /data/src/10.3/sql/sql_parse.cc:1279
 
#8  0x0000561ad86e2133 in do_handle_one_connection (connect=0x561adb986730) at /data/src/10.3/sql/sql_connect.cc:1402
 
#9  0x0000561ad86e1eaa in handle_one_connection (arg=0x561adb986730) at /data/src/10.3/sql/sql_connect.cc:1308
 
#10 0x0000561ad8fba7e0 in pfs_spawn_thread (arg=0x561adb8e2170) at /data/src/10.3/storage/perfschema/pfs.cc:1862
 
#11 0x00007f85286da4a4 in start_thread (arg=0x7f8520d1a700) at pthread_create.c:456
 
#12 0x00007f8526c22d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 5 (Thread 0x7f8520db0700 (LWP 15536)):
 
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
 
#1  0x0000561ad9026cb3 in safe_cond_wait (cond=0x561ad9cb4b20 <COND_slave_background>, mp=0x561ad9cb7f00 <LOCK_slave_background>, file=0x561ad90c7340 "/data/src/10.3/include/mysql/psi/mysql_thread.h", line=1167) at /data/src/10.3/mysys/thr_mutex.c:492
 
#2  0x0000561ad84887f3 in inline_mysql_cond_wait (that=0x561ad9cb4b20 <COND_slave_background>, mutex=0x561ad9cb7f00 <LOCK_slave_background>, src_file=0x561ad90c7e15 "/data/src/10.3/sql/slave.cc", src_line=513) at /data/src/10.3/include/mysql/psi/mysql_thread.h:1167
 
#3  0x0000561ad8489d1a in handle_slave_background (arg=0x0) at /data/src/10.3/sql/slave.cc:513
 
#4  0x0000561ad8fba7e0 in pfs_spawn_thread (arg=0x561adb8c6b30) at /data/src/10.3/storage/perfschema/pfs.cc:1862
 
#5  0x00007f85286da4a4 in start_thread (arg=0x7f8520db0700) at pthread_create.c:456
 
#6  0x00007f8526c22d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 4 (Thread 0x7f8520dfb700 (LWP 15534)):
 
#0  do_sigwait (set=<optimized out>, set@entry=0x7f8520dfae30, sig=sig@entry=0x7f8520dfae00) at ../sysdeps/unix/sysv/linux/sigwait.c:64
 
#1  0x00007f85286e3d0d in __sigwait (set=0x7f8520dfae30, sig=0x7f8520dfae00) at ../sysdeps/unix/sysv/linux/sigwait.c:96
 
#2  0x0000561ad845d322 in signal_hand (arg=0x0) at /data/src/10.3/sql/mysqld.cc:3554
 
#3  0x0000561ad8fba7e0 in pfs_spawn_thread (arg=0x561adb8da320) at /data/src/10.3/storage/perfschema/pfs.cc:1862
 
#4  0x00007f85286da4a4 in start_thread (arg=0x7f8520dfb700) at pthread_create.c:456
 
#5  0x00007f8526c22d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 3 (Thread 0x7f8522966700 (LWP 15532)):
 
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
 
#1  0x0000561ad9026fbd in safe_cond_timedwait (cond=0x561ada54d0e0 <COND_timer>, mp=0x561ada54d020 <LOCK_timer>, abstime=0x7f8522965eb0, file=0x561ad94401a0 "/data/src/10.3/include/mysql/psi/mysql_thread.h", line=1204) at /data/src/10.3/mysys/thr_mutex.c:546
 
#2  0x0000561ad9027f84 in inline_mysql_cond_timedwait (that=0x561ada54d0e0 <COND_timer>, mutex=0x561ada54d020 <LOCK_timer>, abstime=0x7f8522965eb0, src_file=0x561ad94401d0 "/data/src/10.3/mysys/thr_timer.c", src_line=292) at /data/src/10.3/include/mysql/psi/mysql_thread.h:1204
 
#3  0x0000561ad9028ae9 in timer_handler (arg=0x0) at /data/src/10.3/mysys/thr_timer.c:292
 
#4  0x0000561ad8fba7e0 in pfs_spawn_thread (arg=0x561adb7bfe50) at /data/src/10.3/storage/perfschema/pfs.cc:1862
 
#5  0x00007f85286da4a4 in start_thread (arg=0x7f8522966700) at pthread_create.c:456
 
#6  0x00007f8526c22d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 2 (Thread 0x7f85215fc700 (LWP 15533)):
 
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
 
#1  0x0000561ad9026fbd in safe_cond_timedwait (cond=0x561ada53ba80 <COND_checkpoint>, mp=0x561ada53b9c0 <LOCK_checkpoint>, abstime=0x7f85215fbe00, file=0x561ad9401440 "/data/src/10.3/include/mysql/psi/mysql_thread.h", line=1204) at /data/src/10.3/mysys/thr_mutex.c:546
 
#2  0x0000561ad8e95163 in inline_mysql_cond_timedwait (that=0x561ada53ba80 <COND_checkpoint>, mutex=0x561ada53b9c0 <LOCK_checkpoint>, abstime=0x7f85215fbe00, src_file=0x561ad9401470 "/data/src/10.3/storage/maria/ma_servicethread.c", src_line=116) at /data/src/10.3/include/mysql/psi/mysql_thread.h:1204
 
#3  0x0000561ad8e95688 in my_service_thread_sleep (control=0x561ad9af65c0 <checkpoint_control>, sleep_time=29000000000) at /data/src/10.3/storage/maria/ma_servicethread.c:115
 
#4  0x0000561ad8e89c54 in ma_checkpoint_background (arg=0x1e) at /data/src/10.3/storage/maria/ma_checkpoint.c:707
 
#5  0x0000561ad8fba7e0 in pfs_spawn_thread (arg=0x561adb7d3d80) at /data/src/10.3/storage/perfschema/pfs.cc:1862
 
#6  0x00007f85286da4a4 in start_thread (arg=0x7f85215fc700) at pthread_create.c:456
 
#7  0x00007f8526c22d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 1 (Thread 0x7f8520d65700 (LWP 15538)):
 
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x0000561ad9021645 in my_write_core (sig=6) at /data/src/10.3/mysys/stacktrace.c:481
 
#2  0x0000561ad8879327 in handle_fatal_signal (sig=6) at /data/src/10.3/sql/signal_handler.cc:343
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x00007f8526b6e42a in __GI_abort () at abort.c:89
 
#6  0x0000561ad9026412 in safe_mutex_lock (mp=0x561ad9cb7b40 <LOCK_global_system_variables>, my_flags=0, file=0x561ad90f1b88 "/data/src/10.3/sql/sql_plugin.cc", line=3000) at /data/src/10.3/mysys/thr_mutex.c:265
 
#7  0x0000561ad859453f in inline_mysql_mutex_lock (that=0x561ad9cb7b40 <LOCK_global_system_variables>, src_file=0x561ad90f1b88 "/data/src/10.3/sql/sql_plugin.cc", src_line=3000) at /data/src/10.3/include/mysql/psi/mysql_thread.h:695
 
#8  0x0000561ad859cad0 in sync_dynamic_session_variables (thd=0x7f8510000b00, global_lock=true) at /data/src/10.3/sql/sql_plugin.cc:3000
 
#9  0x0000561ad859cdec in intern_sys_var_ptr (thd=0x7f8510000b00, offset=104, global_lock=true) at /data/src/10.3/sql/sql_plugin.cc:3067
 
#10 0x0000561ad859cf57 in mysql_sys_var_str (thd=0x7f8510000b00, offset=104) at /data/src/10.3/sql/sql_plugin.cc:3114
 
#11 0x00007f8520ac40f0 in get_loc_info (thd=0x7f8510000b00) at /data/src/10.3/plugin/server_audit/server_audit.c:924
 
#12 0x00007f8520ac7ed2 in mark_always_logged (thd=0x7f8510000b00) at /data/src/10.3/plugin/server_audit/server_audit.c:2551
 
#13 0x00007f8520ac87b2 in update_syslog_facility (thd=0x7f8510000b00, var=0x7f8520ccc660 <mysql_sysvar_syslog_facility>, var_ptr=0x7f8520ccd570 <syslog_facility>, save=0x7f8510012a48) at /data/src/10.3/plugin/server_audit/server_audit.c:2776
 
#14 0x0000561ad859e47a in sys_var_pluginvar::global_update (this=0x7f850403d1e8, thd=0x7f8510000b00, var=0x7f8510012a28) at /data/src/10.3/sql/sql_plugin.cc:3530
 
#15 0x0000561ad84837e9 in sys_var::update (this=0x7f850403d1e8, thd=0x7f8510000b00, var=0x7f8510012a28) at /data/src/10.3/sql/set_var.cc:208
 
#16 0x0000561ad8485538 in set_var::update (this=0x7f8510012a28, thd=0x7f8510000b00) at /data/src/10.3/sql/set_var.cc:837
 
#17 0x0000561ad84851c3 in sql_set_variables (thd=0x7f8510000b00, var_list=0x7f85100057b8, free=true) at /data/src/10.3/sql/set_var.cc:740
 
#18 0x0000561ad858433f in mysql_execute_command (thd=0x7f8510000b00) at /data/src/10.3/sql/sql_parse.cc:5154
 
#19 0x0000561ad858d988 in mysql_parse (thd=0x7f8510000b00, rawbuf=0x7f8510012808 "SET GLOBAL SERVER_AUDIT_SYSLOG_FACILITY = LOG_CRON", length=50, parser_state=0x7f8520d645f0, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:8105
 
#20 0x0000561ad857a9ca in dispatch_command (command=COM_QUERY, thd=0x7f8510000b00, packet=0x7f851011de61 "SET GLOBAL SERVER_AUDIT_SYSLOG_FACILITY = LOG_CRON", packet_length=50, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1858
 
#21 0x0000561ad85793ed in do_command (thd=0x7f8510000b00) at /data/src/10.3/sql/sql_parse.cc:1403
 
#22 0x0000561ad86e2133 in do_handle_one_connection (connect=0x561adb986730) at /data/src/10.3/sql/sql_connect.cc:1402
 
#23 0x0000561ad86e1eaa in handle_one_connection (arg=0x561adb986730) at /data/src/10.3/sql/sql_connect.cc:1308
 
#24 0x0000561ad8fba7e0 in pfs_spawn_thread (arg=0x561adb8e1dd0) at /data/src/10.3/storage/perfschema/pfs.cc:1862
 
#25 0x00007f85286da4a4 in start_thread (arg=0x7f8520d65700) at pthread_create.c:456
 
#26 0x00007f8526c22d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Observed on all versions, including 5.5, but it seems to happen more reluctantly on 5.5.
ASAN fails the same way.
Non-debug builds hang instead of crashing.

Note: Possibly related to MDEV-19614 and MDEV-19665. Or not.
Generated at Thu Feb 08 08:53:29 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.