Valgrind: Invalid read of size 8 at get_record_buffer by audit_log_notify

[Tomislav Plavcic]

==1842== Thread 33:
==1842== Invalid read of size 8
==1842== at 0x36448AE7: get_record_buffer (audit_log.c:1785)
==1842== by 0x36447E63: audit_log_notify (audit_log.c:1133)
==1842== by 0xE7F3D2: plugins_dispatch(THD*, st_plugin_int**, void*) (sql_audit.cc:1231)
==1842== by 0xE7F51A: event_class_dispatch(THD*, mysql_event_class_t, void const*) (sql_audit.cc:1294)
==1842== by 0xE7DD8A: mysql_audit_notify(THD*, mysql_event_general_subclass_t, int, char const*, unsigned long) (sql_audit.cc:327)
==1842== by 0x151C9B3: mysql_audit_general(THD*, mysql_event_general_subclass_t, int, char const*) (sql_audit.h:93)
==1842== by 0x1521C8A: dispatch_command(THD*, COM_DATA const*, enum_server_command) (sql_parse.cc:1869)
==1842== by 0x151F7AC: do_command(THD*) (sql_parse.cc:1010)
==1842== by 0x1661847: handle_connection (connection_handler_per_thread.cc:312)
==1842== by 0x1D0C13B: pfs_spawn_thread (pfs.cc:2188)
==1842== by 0x5075DC4: start_thread (pthread_create.c:308)
==1842== by 0x6E5CCEC: clone (clone.S:113)
==1842== Address 0x3788a438 is 24 bytes inside a block of size 448 free'd
==1842== at 0x18670EB: my_free (my_malloc.c:132)
==1842== by 0x155786F: plugin_var_memalloc_free(system_variables*) (sql_plugin.cc:3354)
==1842== by 0x155A397: free_system_variables(system_variables*, bool) (sql_plugin.cc:4319)
==1842== by 0x152A174: mysql_execute_command(THD*, bool) (sql_parse.cc:5203)
==1842== by 0x152BC42: mysql_parse(THD*, Parser_state*) (sql_parse.cc:5838)
==1842== by 0x1520892: dispatch_command(THD*, COM_DATA const*, enum_server_command) (sql_parse.cc:1447)
==1842== by 0x151F7AC: do_command(THD*) (sql_parse.cc:1010)
==1842== by 0x1661847: handle_connection (connection_handler_per_thread.cc:312)
==1842== by 0x1D0C13B: pfs_spawn_thread (pfs.cc:2188)
==1842== by 0x5075DC4: start_thread (pthread_create.c:308)
==1842== by 0x6E5CCEC: clone (clone.S:113)
==1842==
==1842== Invalid read of size 1
==1842== at 0x36447ED6: audit_log_notify (audit_log.c:1143)
==1842== by 0xE7F3D2: plugins_dispatch(THD*, st_plugin_int**, void*) (sql_audit.cc:1231)
==1842== by 0xE7F51A: event_class_dispatch(THD*, mysql_event_class_t, void const*) (sql_audit.cc:1294)
==1842== by 0xE7DD8A: mysql_audit_notify(THD*, mysql_event_general_subclass_t, int, char const*, unsigned long) (sql_audit.cc:327)
==1842== by 0x151C9B3: mysql_audit_general(THD*, mysql_event_general_subclass_t, int, char const*) (sql_audit.h:93)
==1842== by 0x1521C8A: dispatch_command(THD*, COM_DATA const*, enum_server_command) (sql_parse.cc:1869)
==1842== by 0x151F7AC: do_command(THD*) (sql_parse.cc:1010)
==1842== by 0x1661847: handle_connection (connection_handler_per_thread.cc:312)
==1842== by 0x1D0C13B: pfs_spawn_thread (pfs.cc:2188)
==1842== by 0x5075DC4: start_thread (pthread_create.c:308)
==1842== by 0x6E5CCEC: clone (clone.S:113)
==1842== Address 0x3788a440 is 32 bytes inside a block of size 448 free'd
==1842== at 0x18670EB: my_free (my_malloc.c:132)
==1842== by 0x155786F: plugin_var_memalloc_free(system_variables*) (sql_plugin.cc:3354)
==1842== by 0x155A397: free_system_variables(system_variables*, bool) (sql_plugin.cc:4319)
==1842== by 0x152A174: mysql_execute_command(THD*, bool) (sql_parse.cc:5203)
==1842== by 0x152BC42: mysql_parse(THD*, Parser_state*) (sql_parse.cc:5838)
==1842== by 0x1520892: dispatch_command(THD*, COM_DATA const*, enum_server_command) (sql_parse.cc:1447)
==1842== by 0x151F7AC: do_command(THD*) (sql_parse.cc:1010)
==1842== by 0x1661847: handle_connection (connection_handler_per_thread.cc:312)
==1842== by 0x1D0C13B: pfs_spawn_thread (pfs.cc:2188)
==1842== by 0x5075DC4: start_thread (pthread_create.c:308)
==1842== by 0x6E5CCEC: clone (clone.S:113)

The full error log is attached.
Here's the reduced test case:
DROP DATABASE test;
SET STATEMENT max_join_size=0 FOR SELECT 0 t0;

[Tomislav Plavcic (tplavcic)]

Similar test case:
DROP DATABASE test;
SET STATEMENT sql_mode='' FOR SELECT *;

Also you need to use audit_log plugin, I used --init-file=plugins_57.sql from here (without tokudb): https://github.com/Percona-QA/percona-qa/blob/master/plugins_57.sql

[Sergei Glushchenko (sergei.glushchenko)]

Looks like audit plugin notified about event after THDVAR's released by MySQL

[Sergei Glushchenko (sergei.glushchenko)]

With slightly modified server:

diff --git i/sql/sql_plugin.cc w/sql/sql_plugin.cc
index 0aea4da..37da9c7 100644
--- i/sql/sql_plugin.cc
+++ w/sql/sql_plugin.cc
@@ -3351,6 +3351,9 @@ static void plugin_var_memalloc_free(struct system_variables *vars)
   for (root= vars->dynamic_variables_allocs; root; root= next)
   {
     next= root->next;
+ char *var= (char *) (root + 1);
+ for (int i=0; var[i]; i++)
+ var[i]= 0;
     my_free(root);
   }
   vars->dynamic_variables_allocs= NULL;

it is possible to crash it sometimes with stack trace

(lldb) bt
* thread #25: tid = 0x0018, 0x00007fff900e6f06 libsystem_kernel.dylib`__pthread_kill + 10, stop reason = signal SIGSTOP
    frame #0: 0x00007fff900e6f06 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff890cb4ec libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x0000000103d58a1b mysqld`my_write_core(sig=11) + 43 at stacktrace.c:247
    frame #3: 0x0000000103c10178 mysqld`::handle_fatal_signal(sig=11) + 1640 at signal_handler.cc:223
    frame #4: 0x00007fff8e04552a libsystem_platform.dylib`_sigtramp + 26
  * frame #5: 0x000000010d3032d3 audit_log.so`audit_log_update_thd_local(thd=0x00007fc6a410ae00, local=0x00007fc6a350c6d8, event_class=0, event=0x0000700000bc6460) + 883 at audit_log.c:1013
    frame #6: 0x000000010d302915 audit_log.so`audit_log_notify(thd=0x00007fc6a410ae00, event_class=MYSQL_AUDIT_GENERAL_CLASS, event=0x0000700000bc6460) + 133 at audit_log.c:1137
    frame #7: 0x0000000103c13700 mysqld`plugins_dispatch(thd=0x00007fc6a410ae00, plugin=0x00007fc6a3508ec0, arg=0x0000700000bc63d8) + 144 at sql_audit.cc:1230
    frame #8: 0x0000000103c10d0b mysqld`event_class_dispatch(thd=0x00007fc6a410ae00, event_class=MYSQL_AUDIT_GENERAL_CLASS, event=0x0000700000bc6460) + 331 at sql_audit.cc:1294
    frame #9: 0x0000000103c10652 mysqld`mysql_audit_notify(thd=0x00007fc6a410ae00, subclass=MYSQL_AUDIT_GENERAL_STATUS, error_code=1096, msg="Query", msg_len=5) + 866 at sql_audit.cc:327
    frame #10: 0x0000000103a2f636 mysqld`mysql_audit_general(thd=0x00007fc6a410ae00, event_subtype=MYSQL_AUDIT_GENERAL_STATUS, error_code=1096, msg="Query") + 118 at sql_audit.h:92
    frame #11: 0x0000000103a2d93a mysqld`dispatch_command(thd=0x00007fc6a410ae00, com_data=0x0000700000bc7db8, command=COM_QUERY) + 10266 at sql_parse.cc:1871
    frame #12: 0x0000000103a2e26e mysqld`do_command(thd=0x00007fc6a410ae00) + 1390 at sql_parse.cc:1010
    frame #13: 0x0000000103bd1196 mysqld`::handle_connection(arg=0x00007fc6a482f6e0) + 662 at connection_handler_per_thread.cc:312
    frame #14: 0x000000010434b40c mysqld`::pfs_spawn_thread(arg=0x00007fc6a4847a70) + 396 at pfs.cc:2188
    frame #15: 0x00007fff890c899d libsystem_pthread.dylib`_pthread_body + 131
    frame #16: 0x00007fff890c891a libsystem_pthread.dylib`_pthread_start + 168
    frame #17: 0x00007fff890c6351 libsystem_pthread.dylib`thread_start + 13

p event_general->general_query
(MYSQL_LEX_CSTRING) $2 = (str = "SET STATEMENT sql_mode='' FOR SELECT *", length = 38)

It means that plugin variables are freed first and then audit event passed to plugin which is a core server bug IMHO.

[Sergei Glushchenko (sergei.glushchenko)]

Appears to be "SET STATEMENT ... FOR ..." bug

[Sergei Glushchenko (sergei.glushchenko)]

Finally, tracked it down to the combination of two issues:

1. SET STATEMENT ... FOR ... did not copy MEMALLOC'ed variables correctly
2. When MEMALLOC'ed variables are copied by SET STATEMENT ... FOR ... , audit log still needs to access original session values

[Sergei Glushchenko (sergei.glushchenko)]

https://github.com/percona/percona-server/pull/1097
https://github.com/percona/percona-server/pull/1098

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1013