Bug #54989 With null_audit installed, server hangs on an attempt to install a plugin twice
Submitted: 4 Jul 2010 18:38 Modified: 2 Sep 2010 16:11
Reporter: Elena Stepanova Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:5.5.5-m3 OS:Any
Assigned to: Sergey Vojtovich CPU Architecture:Any
Tags: audit, plugin
Triage: Triaged: D1 (Critical)

[4 Jul 2010 18:38] Elena Stepanova
Description:
If null_audit plugin is installed and general log is disabled, server hangs on attempt to install an already installed plugin (normally it just throws error 1125 ER_UDF_EXISTS).

The plugin which is installed twice can be null_audit itself or some other plugin.

In stack trace, the only thread that seems to be doing something is this (trace from debug version, the problem exists in both debug and non-debug):

Thread 2 (Thread 1191770432 (LWP 12064)):
#0  0x00002b3f63e9d548 in __lll_mutex_lock_wait () from /lib64/libpthread.so.0
#1  0x00002b3f63e99907 in _L_mutex_lock_1029 () from /lib64/libpthread.so.0
#2  0x00002b3f63e99887 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x00000000005d0ea8 in inline_mysql_mutex_lock (that=0x108ca60,
    src_file=0xaadd48 "mysql-5.5.5-m3/sql/sql_plugin.cc", src_line=1912)
    at mysql-5.5.5-m3/include/mysql/psi/mysql_thread.h:638
#4  0x00000000005d207a in plugin_foreach_with_mask (thd=0x1835100, func=0x69a293 <acquire_plugins>, type=5, state_mask=4294967287, arg=0x4708c3a4)
    at mysql-5.5.5-m3/sql/sql_plugin.cc:1912
#5  0x000000000069a21b in mysql_audit_notify (thd=0x1835100, event_class=0, event_subtype=1)
    at mysql-5.5.5-m3/sql/sql_audit.cc:165
#6  0x000000000053170d in mysql_audit_general (thd=0x1835100, event_subtype=1, error_code=1125, msg=0x4708c7e0 "Function 'rpl_semi_sync_master' already exists")
    at mysql-5.5.5-m3/sql/sql_audit.h:126
#7  0x00000000005317ef in my_message_sql (error=1125, str=0x4708c7e0 "Function 'rpl_semi_sync_master' already exists", MyFlags=0)
    at mysql-5.5.5-m3/sql/mysqld.cc:3105
#8  0x0000000000a03035 in my_printv_error (error=1125, format=0x10cd6fa "Function '%-.192s' already exists", MyFlags=0, ap=0x4708ca30)
    at mysql-5.5.5-m3/mysys/my_error.c:147
#9  0x00000000005d660d in report_error (where_to=2, error=1125) at mysql-5.5.5-m3/sql/sql_plugin.cc:270
#10 0x00000000005d6f6a in plugin_add (tmp_root=0x1837a98, name=0x1837348, dl=0x1837358, argc=0x4708d27c, argv=0x186d9c0, report=2)
    at mysql-5.5.5-m3/sql/sql_plugin.cc:766
#11 0x00000000005d74bf in mysql_install_plugin (thd=0x1835100, name=0x1837348, dl=0x1837358)
    at mysql-5.5.5-m3/sql/sql_plugin.cc:1770
#12 0x00000000005cb5f1 in mysql_execute_command (thd=0x1835100) at mysql-5.5.5-m3/sql/sql_parse.cc:4691
#13 0x00000000005cbd8b in mysql_parse (thd=0x1835100, inBuf=0x18b3ad0 "install plugin rpl_semi_sync_master soname 'semisync_master.so'", length=63,
    parser_state=0x4708ea50) at mysql-5.5.5-m3/sql/sql_parse.cc:5911
#14 0x00000000005cc9f1 in dispatch_command (command=COM_QUERY, thd=0x1835100, packet=0x18abaa1 "install plugin rpl_semi_sync_master soname 'semisync_master.so'",
    packet_length=63) at mysql-5.5.5-m3/sql/sql_parse.cc:1135
#15 0x00000000005cdf17 in do_command (thd=0x1835100) at mysql-5.5.5-m3/sql/sql_parse.cc:807
#16 0x000000000069d121 in do_handle_one_connection (thd_arg=0x1835100) at mysql-5.5.5-m3/sql/sql_connect.cc:1196
#17 0x000000000069d1ea in handle_one_connection (arg=0x1835100) at mysql-5.5.5-m3/sql/sql_connect.cc:1135
#18 0x00002b3f63e97143 in start_thread () from /lib64/libpthread.so.0
#19 0x00002b3f645068cd in clone () from /lib64/libc.so.6
#20 0x0000000000000000 in ?? ()

How to repeat:
SET GLOBAL general_log=0;
INSTALL PLUGIN null_audit SONAME 'adt_null.so';
INSTALL PLUGIN rpl_semi_sync_master SONAME 'semisync_master.so';
INSTALL PLUGIN rpl_semi_sync_master SONAME 'semisync_master.so';
[20 Aug 2010 9:53] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/116354

3186 Sergey Vojtovich	2010-08-20
      BUG#54989 - With null_audit installed, server hangs on an
                  attempt to install a plugin twice
      
      Server crashes when [UN]INSTALL PLUGIN fails (returns an
      error) and general log is disabled and there are audit
      plugins interested in MYSQL_AUDIT_GENERAL_CLASS. 
      
      When audit event is triggered, audit subsystem acquires interested
      plugins by walking through plugin list. Evidently plugin list
      iterator protects plugin list by acquiring LOCK_plugin, see
      plugin_foreach_with_mask().
      
      On the other hand [UN]INSTALL PLUGIN is acquiring LOCK_plugin
      rather for a long time.
      
      When audit event is triggered during [UN]INSTALL PLUGIN, plugin
      list iterator acquires the same lock (within the same thread)
      second time.
      
      Repeatable only with general_log disabled, because general_log
      triggers MYSQL_AUDIT_GENERAL_LOG event, which acquires audit
      plugins before [UN]INSTALL PLUGIN acquired LOCK_plugin.
      
      With this fix we pre-acquire audit plugins for events that
      may potentially occur during [UN]INSTALL PLUGIN.
      
      This hack should be removed when LOCK_plugin is fixed so it
      protects only what it supposed to protect.
      
      No test case for this fix - we do not have facility to test
      audit plugins yet.
     @ sql/sql_audit.cc
        Move "acquire audit plugin" logics to a separate
        function.
     @ sql/sql_audit.h
        Move "acquire audit plugin" logics to a separate
        function.
     @ sql/sql_plugin.cc
        Pre-acquire audit plugins for events that may potentially occur
        during [UN]INSTALL PLUGIN.
[23 Aug 2010 9:32] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/116476

3191 Sergey Vojtovich	2010-08-23 [merge]
      Merge fix for BUG#54989 to mysql-5.5-bugfixing.
[25 Aug 2010 9:21] Bugs System
Pushed into mysql-5.5 5.5.6-m3 (revid:alik@ibmvm-20100825092002-2yvkb3iwu43ycpnm) (version source revid:alik@ibmvm-20100825092002-2yvkb3iwu43ycpnm) (merge vers: 5.5.6-m3) (pib:20)
[27 Aug 2010 20:09] Paul Dubois
Noted in 5.5.6 changelog.

If audit plugins were installed that were interested in
MYSQL_AUDIT_GENERAL_CLASS events and the general query log was
disabled, failed INSTALL PLUGIN or UNINSTALL PLUGIN statements caused
a server crash.  

Setting report to Need Merge pending push to 5.6.x.
[30 Aug 2010 8:29] Bugs System
Pushed into mysql-trunk 5.6.1-m4 (revid:alik@sun.com-20100830082732-n2eyijnv86exc5ci) (version source revid:alik@sun.com-20100830082732-n2eyijnv86exc5ci) (merge vers: 5.6.1-m4) (pib:21)
[30 Aug 2010 8:33] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100830082745-n6sh01wlwh3itasv) (version source revid:alik@sun.com-20100830082745-n6sh01wlwh3itasv) (pib:21)
[30 Aug 2010 18:25] Paul Dubois
Noted in 5.6.1 changelog.