MySQL Bugs: #79090: my_message in MYSQL_AUDIT_GENERAL

Bug #79090	my_message in MYSQL_AUDIT_GENERAL_CLASS handler crashes debug build
Submitted:	3 Nov 2015 9:02	Modified:	31 Mar 2016 5:20
Reporter:	Laurynas Biveinis (OCA)	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: Security: Audit	Severity:	S2 (Serious)
Version:	5.7.9	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	plugin api

Description:
If one does my_message in an audit plugin MYSQL_AUDIT_GENERAL_CLASS handler, for an event subclass != MYSQL_AUDIT_GENERAL_ERROR (which will result in bug 79079), it will crash the debug build:
...
Assertion failed: (m_status == DA_EMPTY), function disable_status, file /Users/laurynas/percona/mysql-5.7.9/sql/sql_error.h, line 354.
08:55:35 UTC - mysqld got signal 6 ;
...
(lldb) bt
* thread #24: tid = 0x0017, 0x00007fff9209b0ae libsystem_kernel.dylib`__pthread_kill + 10, stop reason = signal SIGSTOP
  * frame #0: 0x00007fff9209b0ae libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff9968a500 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x000000010726833b mysqld-debug`my_write_core(sig=6) + 43 at stacktrace.c:247
    frame #3: 0x0000000107115023 mysqld-debug`::handle_fatal_signal(sig=6) + 1683 at signal_handler.cc:220
    frame #4: 0x00007fff96e0152a libsystem_platform.dylib`_sigtramp + 26
    frame #5: 0x00007fff9209b0af libsystem_kernel.dylib`__pthread_kill + 11
    frame #6: 0x00007fff9968a500 libsystem_pthread.dylib`pthread_kill + 90
    frame #7: 0x00007fff999ea37b libsystem_c.dylib`abort + 129
    frame #8: 0x00007fff999b19c4 libsystem_c.dylib`__assert_rtn + 321
    frame #9: 0x0000000106f4c4ff mysqld-debug`Diagnostics_area::disable_status(this=0x00007ff139b0be80) + 79 at sql_error.h:354
    frame #10: 0x0000000106f380b8 mysqld-debug`dispatch_command(thd=0x00007ff139b09000, com_data=0x0000700000b44db8, command=COM_QUIT) + 8184 at sql_parse.cc:1487
    frame #11: 0x0000000106f394ff mysqld-debug`do_command(thd=0x00007ff139b09000) + 1311 at sql_parse.cc:852
    frame #12: 0x00000001070d240f mysqld-debug`::handle_connection(arg=0x00007ff1385f2450) + 495 at connection_handler_per_thread.cc:295
    frame #13: 0x0000000107869e7b mysqld-debug`::pfs_spawn_thread(arg=0x00007ff1385f2360) + 411 at pfs.cc:2192
    frame #14: 0x00007fff996879b1 libsystem_pthread.dylib`_pthread_body + 131
    frame #15: 0x00007fff9968792e libsystem_pthread.dylib`_pthread_start + 168
    frame #16: 0x00007fff99685385 libsystem_pthread.dylib`thread_start + 13
...
(lldb) up
frame #10: 0x0000000106f380b8 mysqld-debug`dispatch_command(thd=0x00007ff139b09000, com_data=0x0000700000b44db8, command=COM_QUIT) + 8184 at sql_parse.cc:1487
   1484	    // TODO: access of protocol_classic should be removed
   1485	    if (thd->is_classic_protocol())
   1486	      thd->get_protocol_classic()->get_net()->error= 0;
-> 1487	    thd->get_stmt_da()->disable_status();       // Don't send anything back
   1488	    error=TRUE;					// End server
   1489	    break;
   1490	#ifndef EMBEDDED_LIBRARY

How to repeat:
Apply this

--- mysql-server/plugin/audit_null/audit_null.c	2015-11-03 10:46:59.000000000 +0200
+++ mysql-5.7.9/plugin/audit_null/audit_null.c	2015-11-03 10:55:05.000000000 +0200
@@ -388,6 +388,7 @@ static int audit_null_notify(MYSQL_THD t
     switch (event_general->event_subclass)
     {
     case MYSQL_AUDIT_GENERAL_LOG:
+      my_message(ER_AUDIT_API_ABORT, "Aborting an unabortable event", MYF(0));
       number_of_calls_general_log++;
       break;
     case MYSQL_AUDIT_GENERAL_ERROR:

Run audit_plugin_2 testcase.

Suggested fix:
Document and enforce that MYSQL_AUDIT_GENERAL_CLASS is non-terminatable event?

The above was for MYSQL_AUDIT_GENERAL_LOG subclass.

MYSQL_AUDIT_GENERAL_RESULT subclass results in

Assertion failed: (! is_set() || m_can_overwrite_status), function set_error_status, file /Users/laurynas/percona/mysql-5.7.9/sql/sql_error.cc, line 444.
09:04:07 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=1
max_threads=151
thread_count=1
connection_count=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61129 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7fb89c104200
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 700000b44de8 thread_stack 0x40000
0   mysqld-debug                        0x0000000105a0b268 my_print_stacktrace + 72
1   mysqld-debug                        0x00000001058b7d32 handle_fatal_signal + 930
2   libsystem_platform.dylib            0x00007fff96e0152a _sigtramp + 26
3   ???                                 0x0000000000000000 0x0 + 0
4   libsystem_c.dylib                   0x00007fff999ea37b abort + 129
5   libsystem_c.dylib                   0x00007fff999b19c4 basename + 0
6   mysqld-debug                        0x000000010565eee3 _ZN16Diagnostics_area16set_error_statusEjPKcS1_ + 163
7   mysqld-debug                        0x0000000105632bb3 _ZN3THD15raise_conditionEjPKcN13Sql_condition19enum_severity_levelES1_ + 515
8   mysqld-debug                        0x000000010589b7da my_message_sql + 394
9   mysqld-debug                        0x00000001059fd188 my_message + 40
10  adt_null.so                         0x000000010e27c5b2 audit_null_notify + 466
11  mysqld-debug                        0x00000001058ba623 _ZL16plugins_dispatchP3THDPP13st_plugin_intPv + 147
12  mysqld-debug                        0x00000001058b8a35 _ZL20event_class_dispatchP3THD19mysql_event_class_tPKv + 213
13  mysqld-debug                        0x00000001058b84cb _Z18mysql_audit_notifyP3THD30mysql_event_general_subclass_tiPKcm + 827
14  mysqld-debug                        0x00000001056dd419 _ZL19mysql_audit_generalP3THD30mysql_event_general_subclass_tiPKc + 121
15  mysqld-debug                        0x00000001056dbb8d _Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command + 10957
16  mysqld-debug                        0x00000001056dc4ff _Z10do_commandP3THD + 1311
17  mysqld-debug                        0x000000010587540f handle_connection + 495
18  mysqld-debug                        0x000000010600ce7b pfs_spawn_thread + 411
19  libsystem_pthread.dylib             0x00007fff996879b1 _pthread_body + 131
20  libsystem_pthread.dylib             0x00007fff9968792e _pthread_body + 0
21  libsystem_pthread.dylib             0x00007fff99685385 thread_start + 13

MYSQL_AUDIT_GENERAL_STATUS results in the same stacktrace as MYSQL_AUDIT_GENERAL_RESULT

Hello Laurynas,
 
Thank you for the report.
Observed that debug build crashes.

Thanks,
Umesh

//

mysqld-debug: /export/umesh/server/source/bugs/mysql-5.7.9/sql/sql_error.h:354: void Diagnostics_area::disable_status(): Assertion `m_status == DA_EMPTY' failed.
09:20:32 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=1
max_threads=151
thread_count=1
connection_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61086 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f7d0011de10
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7f7d44c31e50 thread_stack 0x40000
/export/umesh/server/source/bugs/mysql-5.7.9/sql/mysqld-debug(my_print_stacktrace+0x35)[0x1796a4d]
/export/umesh/server/source/bugs/mysql-5.7.9/sql/mysqld-debug(handle_fatal_signal+0x3f6)[0xe1dbe9]
/lib64/libpthread.so.0(+0xf130)[0x7f7d5ea87130]
/lib64/libc.so.6(gsignal+0x37)[0x7f7d5d47e5d7]
/lib64/libc.so.6(abort+0x148)[0x7f7d5d47fcc8]
/lib64/libc.so.6(+0x2e546)[0x7f7d5d477546]
/lib64/libc.so.6(+0x2e5f2)[0x7f7d5d4775f2]
/export/umesh/server/source/bugs/mysql-5.7.9/sql/mysqld-debug(Diagnostics_area::disable_status()+0x39)[0xe2efad]
/export/umesh/server/source/bugs/mysql-5.7.9/sql/mysqld-debug(dispatch_command(THD*, COM_DATA const*, enum_server_command)+0x16d1)[0x148a8a5]
/export/umesh/server/source/bugs/mysql-5.7.9/sql/mysqld-debug(do_command(THD*)+0x4b2)[0x1488ce6]
/export/umesh/server/source/bugs/mysql-5.7.9/sql/mysqld-debug(handle_connection+0x1d0)[0x15b2e4b]
/export/umesh/server/source/bugs/mysql-5.7.9/sql/mysqld-debug(pfs_spawn_thread+0x170)[0x1be0ac8]
/lib64/libpthread.so.0(+0x7df5)[0x7f7d5ea7fdf5]
/lib64/libc.so.6(clone+0x6d)[0x7f7d5d53f60d]

Fixed as a duplicate of

Bug#79079 Infinite recursion by calling my_message from MYSQL_AUDIT_GENERAL_CLASS handler