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

Server hangs on client connection with concurrent setting of server audit variable

    Details

    • Type: Bug
    • Status: Open (View Workflow)
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 5.5, 10.1, 10.2, 10.3, 10.4
    • Fix Version/s: 10.2, 10.3, 10.4
    • Component/s: Plugin - Audit
    • Labels:
      None

      Description

      Important: The test case is for reproducing purposes only, don't put it into the test suite, create a deterministic one!

      Note: Stored procedure is not important for the test case, it is just there to allow concurrent loops in MTR (in all versions).

      Note: Possibly related to MDEV-19614. Or not.

      INSTALL SONAME 'server_audit';
       
      --delimiter $
      CREATE PROCEDURE pr()
      BEGIN
        LOOP
          SET GLOBAL SERVER_AUDIT_EXCL_USERS = '';
        END LOOP;
      END $
      --delimiter ;
       
      --connect (pr1,localhost,root,,)
      --let $con1= `SELECT CONNECTION_ID()`
      --send CALL pr()
       
      --let $run= 1000
      while ($run)
      {
          --echo # Countdown: $run connections left
          --connect(con$run,localhost,root,,)
          --disconnect con$run
          --dec $run
      }
       
      # Cleanup
      --connection default
      --eval KILL $con1
      DROP PROCEDURE pr;
      UNINSTALL SONAME 'server_audit';
      

      It fails for me withing ~20 first loops, but it can vary a lot on different machines and builds.

      10.3 f98bb231

      Thread 9 (Thread 0x7fe3c4d5b700 (LWP 31624)):
      #0  __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
      #1  0x00007fe3cc9f0ce6 in __GI___pthread_mutex_lock (mutex=0x563dafc6a348 <LOCK_global_system_variables+40>) at ../nptl/pthread_mutex_lock.c:135
      #2  0x0000563daef0927b in safe_mutex_lock (mp=0x563dafc6a320 <LOCK_global_system_variables>, my_flags=0, file=0x563daf006d30 "/data/src/10.4/sql/sql_plugin.cc", line=3012) at /data/src/10.4/mysys/thr_mutex.c:293
      #3  0x0000563dae416d89 in inline_mysql_mutex_lock (that=0x563dafc6a320 <LOCK_global_system_variables>, src_file=0x563daf006d30 "/data/src/10.4/sql/sql_plugin.cc", src_line=3012) at /data/src/10.4/include/mysql/psi/mysql_thread.h:695
      #4  0x0000563dae41f51d in sync_dynamic_session_variables (thd=0x7fe3a0000b00, global_lock=true) at /data/src/10.4/sql/sql_plugin.cc:3012
      #5  0x0000563dae41f839 in intern_sys_var_ptr (thd=0x7fe3a0000b00, offset=104, global_lock=true) at /data/src/10.4/sql/sql_plugin.cc:3079
      #6  0x0000563dae41f9a4 in mysql_sys_var_str (thd=0x7fe3a0000b00, offset=104) at /data/src/10.4/sql/sql_plugin.cc:3126
      #7  0x00007fe3c4df60f0 in get_loc_info (thd=0x7fe3a0000b00) at /data/src/10.4/plugin/server_audit/server_audit.c:924
      #8  0x00007fe3c4df936f in auditing (thd=0x7fe3a0000b00, event_class=0, ev=0x7fe3c4d59920) at /data/src/10.4/plugin/server_audit/server_audit.c:2021
      #9  0x0000563dae56e76b in plugins_dispatch (thd=0x7fe3a0000b00, plugin=0x7fe3a0011970, arg=0x7fe3c4d598c0) at /data/src/10.4/sql/sql_audit.cc:385
      #10 0x0000563dae56e847 in mysql_audit_notify (thd=0x7fe3a0000b00, event_class=0, event=0x7fe3c4d59920) at /data/src/10.4/sql/sql_audit.cc:424
      #11 0x0000563dae84caef in mysql_audit_general_log (thd=0x7fe3a0000b00, time=1559322495, user=0x7fe3c4d59a00 "[root] @ localhost []", userlen=21, cmd=0x563daf002f5e "Connect", cmdlen=7, query=0x7fe3c4d59c70 "root@localhost as anonymous on test", querylen=35) at /data/src/10.4/sql/sql_audit.h:134
      #12 0x0000563dae84f882 in LOGGER::general_log_write (this=0x563dafc9eda0 <logger>, thd=0x7fe3a0000b00, command=COM_CONNECT, query=0x7fe3c4d59c70 "root@localhost as anonymous on test", query_length=35) at /data/src/10.4/sql/log.cc:1391
      #13 0x0000563dae84faa0 in LOGGER::general_log_print (this=0x563dafc9eda0 <logger>, thd=0x7fe3a0000b00, command=COM_CONNECT, format=0x563daefe6ba3 "%s@%s as %s on %s", args=0x7fe3c4d5a0b8) at /data/src/10.4/sql/log.cc:1423
      #14 0x0000563dae85ed55 in general_log_print (thd=0x7fe3a0000b00, command=COM_CONNECT, format=0x563daefe6ba3 "%s@%s as %s on %s") at /data/src/10.4/sql/log.cc:6655
      #15 0x0000563dae3550e7 in acl_authenticate (thd=0x7fe3a0000b00, com_change_user_pkt_len=0) at /data/src/10.4/sql/sql_acl.cc:13772
      #16 0x0000563dae571856 in check_connection (thd=0x7fe3a0000b00) at /data/src/10.4/sql/sql_connect.cc:1080
      #17 0x0000563dae5719e6 in login_connection (thd=0x7fe3a0000b00) at /data/src/10.4/sql/sql_connect.cc:1149
      #18 0x0000563dae571ffe in thd_prepare_connection (thd=0x7fe3a0000b00) at /data/src/10.4/sql/sql_connect.cc:1314
      #19 0x0000563dae572231 in do_handle_one_connection (connect=0x563db1d51010) at /data/src/10.4/sql/sql_connect.cc:1391
      #20 0x0000563dae571fd3 in handle_one_connection (arg=0x563db1d51010) at /data/src/10.4/sql/sql_connect.cc:1306
      #21 0x0000563daee9bfef in pfs_spawn_thread (arg=0x563db1e7c0a0) at /data/src/10.4/storage/perfschema/pfs.cc:1862
      #22 0x00007fe3cc9ee4a4 in start_thread (arg=0x7fe3c4d5b700) at pthread_create.c:456
      #23 0x00007fe3caf36d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
       
      Thread 7 (Thread 0x7fe3c4df1700 (LWP 31622)):
      #0  __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
      #1  0x00007fe3cc9f0ce6 in __GI___pthread_mutex_lock (mutex=0x7fe3c5000308 <lock_operations+40>) at ../nptl/pthread_mutex_lock.c:135
      #2  0x00007fe3c4dfa5c0 in update_excl_users (thd=0x7fe3a8000b00, var=0x7fe3c4ffe1e0 <mysql_sysvar_excl_users>, var_ptr=0x7fe3c4fff340 <excl_users>, save=0x7fe3a801be10) at /data/src/10.4/plugin/server_audit/server_audit.c:2722
      #3  0x0000563dae420eba in sys_var_pluginvar::global_update (this=0x7fe3b412c808, thd=0x7fe3a8000b00, var=0x7fe3a801bdf0) at /data/src/10.4/sql/sql_plugin.cc:3542
      #4  0x0000563dae2f2277 in sys_var::update (this=0x7fe3b412c808, thd=0x7fe3a8000b00, var=0x7fe3a801bdf0) at /data/src/10.4/sql/set_var.cc:208
      #5  0x0000563dae2f3faa in set_var::update (this=0x7fe3a801bdf0, thd=0x7fe3a8000b00) at /data/src/10.4/sql/set_var.cc:837
      #6  0x0000563dae2f3c38 in sql_set_variables (thd=0x7fe3a8000b00, var_list=0x7fe3a8020ba8, free=true) at /data/src/10.4/sql/set_var.cc:740
      #7  0x0000563dae4057c0 in mysql_execute_command (thd=0x7fe3a8000b00) at /data/src/10.4/sql/sql_parse.cc:5206
      #8  0x0000563dae31c989 in sp_instr_stmt::exec_core (this=0x7fe3a801be40, thd=0x7fe3a8000b00, nextp=0x7fe3c4dee684) at /data/src/10.4/sql/sp_head.cc:3607
      #9  0x0000563dae31bce6 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7fe3a801be88, thd=0x7fe3a8000b00, nextp=0x7fe3c4dee684, open_tables=false, instr=0x7fe3a801be40) at /data/src/10.4/sql/sp_head.cc:3335
      #10 0x0000563dae31c52e in sp_instr_stmt::execute (this=0x7fe3a801be40, thd=0x7fe3a8000b00, nextp=0x7fe3c4dee684) at /data/src/10.4/sql/sp_head.cc:3513
      #11 0x0000563dae31614e in sp_head::execute (this=0x7fe3a801ade8, thd=0x7fe3a8000b00, merge_da_on_success=true) at /data/src/10.4/sql/sp_head.cc:1346
      #12 0x0000563dae318ac5 in sp_head::execute_procedure (this=0x7fe3a801ade8, thd=0x7fe3a8000b00, args=0x7fe3a80058d8) at /data/src/10.4/sql/sp_head.cc:2288
      #13 0x0000563dae3fe4e8 in do_execute_sp (thd=0x7fe3a8000b00, sp=0x7fe3a801ade8) at /data/src/10.4/sql/sql_parse.cc:3005
      #14 0x0000563dae3ff0da in Sql_cmd_call::execute (this=0x7fe3a8012718, thd=0x7fe3a8000b00) at /data/src/10.4/sql/sql_parse.cc:3247
      #15 0x0000563dae40a757 in mysql_execute_command (thd=0x7fe3a8000b00) at /data/src/10.4/sql/sql_parse.cc:6354
      #16 0x0000563dae40fa07 in mysql_parse (thd=0x7fe3a8000b00, rawbuf=0x7fe3a8012668 "CALL pr()", length=9, parser_state=0x7fe3c4df0180, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:8164
      #17 0x0000563dae3fb0e3 in dispatch_command (command=COM_QUERY, thd=0x7fe3a8000b00, packet=0x7fe3a8008311 "CALL pr()", packet_length=9, is_com_multi=false, is_next_command=false) at /data/src/10.4/sql/sql_parse.cc:1829
      #18 0x0000563dae3f98a1 in do_command (thd=0x7fe3a8000b00) at /data/src/10.4/sql/sql_parse.cc:1362
      #19 0x0000563dae57226f in do_handle_one_connection (connect=0x563db1d51010) at /data/src/10.4/sql/sql_connect.cc:1403
      #20 0x0000563dae571fd3 in handle_one_connection (arg=0x563db1d51010) at /data/src/10.4/sql/sql_connect.cc:1306
      #21 0x0000563daee9bfef in pfs_spawn_thread (arg=0x563db1d86740) at /data/src/10.4/storage/perfschema/pfs.cc:1862
      #22 0x00007fe3cc9ee4a4 in start_thread (arg=0x7fe3c4df1700) at pthread_create.c:456
      #23 0x00007fe3caf36d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
      

        Attachments

          Activity

            People

            • Assignee:
              holyfoot Alexey Botchkov
              Reporter:
              elenst Elena Stepanova
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated: