Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-25248

SET GLOBAL server_audit_logging=ON deadlock due to LOCK_global_system_variables

Details

    • Bug
    • Status: Confirmed (View Workflow)
    • Major
    • Resolution: Unresolved
    • 10.4.8, 10.3(EOL), 10.4(EOL), 10.5, 10.6, 10.7(EOL), 10.8(EOL), 10.9(EOL), 10.10(EOL)
    • 10.5, 10.6, 10.11, 11.4
    • Plugins
    • None

    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
      

      Attachments

        Issue Links

          Activity

            alice Alice Sherepa added a comment -

            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.

            alice Alice Sherepa added a comment - 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.
            elenst Elena Stepanova added a comment - - edited

            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
            

            elenst Elena Stepanova added a comment - - edited 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

            People

              serg Sergei Golubchik
              yyjbb jinmh
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.