mysqld crash not long after installing audit plugin

[svenXY]

We installed the plugin yesterday around noon and the next line in the error log (22:48:37) was that mysqld terminated. We never had this problem before, so we think it may be caused or at least be related to the plugin.

my.cnf:

AUDIT

plugin-load=AUDIT=libaudit_plugin.so audit_json_file=1 audit_json_socket_name=/tmp/audit.sock audit_json_socket=OFF audit_json_file=ON audit_whitelist_users=xxx,yyy,zzz,{},; audit_json_log_file=/var/log/mysql/audit.log audit_record_cmds=connect,Quit,show,select,insert,update,delete audit_validate_checksum=OFF

audit_uninstall_plugin=ON

mysqld

Server version: 5.6.35-log MySQL Community Server (GPL) Protocol version: 10

error log

Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Warning] option 'audit-json-file-bufsize': signed value 0 adjusted to 1
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Warning] option 'plugin-audit-json-file-bufsize': signed value 0 adjusted to 1
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: starting up. Version: 1.1.1 , Revision: 660 (64bit). AUDIT plugin interface version: 769 (0x301). MySQL Server version: 5.6.35-log.
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: setup_offsets audit_offsets: (null) validate_checksum: 0 offsets_by_version: 1
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: mysqld: /usr/sbin/mysqld (8984b85a57509c7b9788e66b8b00ef35)
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: extended offsets validate res: MySQL thread id 123456, OS thread handle 0x0, query id 789 aud_tusr
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: Using offsets from offset version: 5.6.35 (99380b27b010574648b20257896ca1d3)
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: Set whitelist_cmds num: 2, value: BEGIN,COMMIT
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: Set record_cmds num: 7, value: connect,Quit,show,select,insert,update,delete
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: Set whitelist_users num: 13, value: xxx,yyyy,zzzz,{},;
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: Set password_masking_cmds num: 7, value: CREATE_USER,GRANT,SET_OPTION,SLAVE_START,CREATE_SERVER,ALTER_SERVER,CHANGE_MASTER
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: Compile password_masking_regex  res: [1]
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: Set password_masking_regex  value: [identified(?:/\*.*?\*/|\s)*?by(?:/\*.*?\*/|\s)*?(?:password)?(?:/\*.*?\*/|\s)*?['|"](?<psw>.*?)(?<!\\)['|"]|password(?:/\*.*?\*/|\s)*?\((?:/\*.*?\*/|\s)*?['|"](?<psw>.*?)(?<!\\)['|"](?:/\*.*?\*/|\s)*?\)|password(?:/\*.*?\*/|\s)*?(?:for(?:/\*.*?\*/|\s)*?\S+?)?(?:/\*.*?\*/|\s)*?=(?:/\*.*?\*/|\s)*?['|"](?<psw>.*?)(?<!\\)['|"]|password(?:/\*.*?\*/|\s)*?['|"](?<psw>.*?)(?<!\\)['|"]]
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: Set json_socket_name str: [/tmp/audit.sock] value: [/tmp/audit.sock]
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: bufsize for file [/var/log/mysql/audit.log]: 1. Value of json_file_bufsize: 1.
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: success opening file: /var/log/mysql/audit.log.
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: mem via 32bit mmap: 0x4001d000 page size: 4096
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: hot patching function: 0x6e40c0, trampolineFunction: 0x4001d000 trampolinePage: 0x4001d000
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: hot patch for: mysql_execute_command (0x6e40c0) complete. Audit func: 0x7fde988101a0, Trampoline address: 0x4001d000, size: 6, used: 34.
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: hot patching function: 0x6a5c90, trampolineFunction: 0x4001d030 trampolinePage: 0x4001d000
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: hot patch for: send_result_to_client (0x6a5c90) complete. Audit func: 0x7fde9880fb20, Trampoline address: 0x4001d030, size: 8, used: 36.
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: hot patching function: 0x6dea30, trampolineFunction: 0x4001d060 trampolinePage: 0x4001d000
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: hot patch for: check_table_access (0x6dea30) complete. Audit func: 0x7fde988103b0, Trampoline address: 0x4001d060, size: 6, used: 34.
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: hot patching function: 0x6a1340, trampolineFunction: 0x4001d090 trampolinePage: 0x4001d000
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: hot patch for: open_tables (0x6a1340) complete. Audit func: 0x7fde9880f820, Trampoline address: 0x4001d090, size: 6, used: 34.
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: Done initializing sql command names. status_vars_index: [141], com_status_vars: [0x1234780].
Mar 23 13:10:53 db01.my.dom mysqld: 2017-03-23 13:10:53 8308 [Note] Audit Plugin: Init completed successfully.
Mar 23 22:48:37 db01.my.dom mysqld: terminate called after throwing an instance of 'std::out_of_range'
Mar 23 22:48:37 db01.my.dom mysqld:   what():  vector::_M_range_check
Mar 23 22:48:37 db01.my.dom mysqld: 22:48:37 UTC - mysqld got signal 6 ;
Mar 23 22:48:37 db01.my.dom mysqld: This could be because you hit a bug. It is also possible that this binary
Mar 23 22:48:37 db01.my.dom mysqld: or one of the libraries it was linked against is corrupt, improperly built,
Mar 23 22:48:37 db01.my.dom mysqld: or misconfigured. This error can also be caused by malfunctioning hardware.
Mar 23 22:48:37 db01.my.dom mysqld: We will try our best to scrape up some info that will hopefully help
Mar 23 22:48:37 db01.my.dom mysqld: diagnose the problem, but since we have already crashed,
Mar 23 22:48:37 db01.my.dom mysqld: something is definitely wrong and this may fail.
Mar 23 22:48:37 db01.my.dom mysqld:
Mar 23 22:48:37 db01.my.dom mysqld: key_buffer_size=8388608
Mar 23 22:48:37 db01.my.dom mysqld: read_buffer_size=262144
Mar 23 22:48:37 db01.my.dom mysqld: max_used_connections=48
Mar 23 22:48:37 db01.my.dom mysqld: max_threads=150
Mar 23 22:48:37 db01.my.dom mysqld: thread_count=5
Mar 23 22:48:37 db01.my.dom mysqld: connection_count=3
Mar 23 22:48:37 db01.my.dom mysqld: It is possible that mysqld could use up to
Mar 23 22:48:37 db01.my.dom mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2506111 K  bytes of memory
Mar 23 22:48:37 db01.my.dom mysqld: Hope that's ok; if not, decrease some variables in the equation.
Mar 23 22:48:37 db01.my.dom mysqld:
Mar 23 22:48:37 db01.my.dom mysqld: Thread pointer: 0x0
Mar 23 22:48:37 db01.my.dom mysqld: Attempting backtrace. You can use the following information to find out
Mar 23 22:48:37 db01.my.dom mysqld: where mysqld died. If you see no messages after this, something went
Mar 23 22:48:37 db01.my.dom mysqld: terribly wrong...
Mar 23 22:48:37 db01.my.dom mysqld: stack_bottom = 0 thread_stack 0x40000
Mar 23 22:48:37 db01.my.dom mysqld: /usr/sbin/mysqld(my_print_stacktrace+0x35)[0x8e3535]
Mar 23 22:48:37 db01.my.dom mysqld: /usr/sbin/mysqld(handle_fatal_signal+0x494)[0x6676f4]
Mar 23 22:48:37 db01.my.dom mysqld: /lib64/libpthread.so.0[0x3772c0f7e0]
Mar 23 22:48:37 db01.my.dom mysqld: /lib64/libc.so.6(gsignal+0x35)[0x37728325e5]
Mar 23 22:48:37 db01.my.dom mysqld: /lib64/libc.so.6(abort+0x175)[0x3772833dc5]
Mar 23 22:48:37 db01.my.dom mysqld: /usr/lib64/libstdc++.so.6(_ZN9__gnu_cxx27__verbose_terminate_handlerEv+0x12d)[0x37750bea7d]
Mar 23 22:48:37 db01.my.dom mysqld: /usr/lib64/libstdc++.so.6[0x37750bcbd6]
Mar 23 22:48:37 db01.my.dom mysqld: /usr/lib64/libstdc++.so.6[0x37750bcc03]
Mar 23 22:48:37 db01.my.dom mysqld: /usr/lib64/libstdc++.so.6[0x37750bcd22]
Mar 23 22:48:37 db01.my.dom mysqld: /usr/lib64/libstdc++.so.6(_ZSt20__throw_out_of_rangePKc+0x67)[0x3775061db7]
Mar 23 22:48:37 db01.my.dom mysqld: /usr/sbin/mysqld[0xacac8d]
Mar 23 22:48:37 db01.my.dom mysqld: /usr/sbin/mysqld[0xacda0a]
Mar 23 22:48:37 db01.my.dom mysqld: /usr/sbin/mysqld[0xaceb42]
Mar 23 22:48:37 db01.my.dom mysqld: /lib64/libpthread.so.0[0x3772c07aa1]
Mar 23 22:48:37 db01.my.dom mysqld: /lib64/libc.so.6(clone+0x6d)[0x37728e8aad]
Mar 23 22:48:37 db01.my.dom mysqld: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
Mar 23 22:48:37 db01.my.dom mysqld: information that should help you find out what is causing the crash.
Mar 23 22:48:38 db01.my.dom mysqld: 2017-03-23 22:48:38 0 [Note] /usr/sbin/mysqld (mysqld 5.6.35-log) starting as process 24620 ...
Mar 23 22:48:38 db01.my.dom mysqld: 2017-03-23 22:48:38 24620 [Note] Plugin 'FEDERATED' is disabled.
Mar 23 22:48:38 db01.my.dom mysqld: 2017-03-23 22:48:38 24620 [Warning] option 'audit-json-file-bufsize': signed value 0 adjusted to 1
Mar 23 22:48:38 db01.my.dom mysqld: 2017-03-23 22:48:38 24620 [Warning] option 'plugin-audit-json-file-bufsize': signed value 0 adjusted to 1
Mar 23 22:48:38 db01.my.dom mysqld: 2017-03-23 22:48:38 24620 [ERROR] Function 'AUDIT' already exists
Mar 23 22:48:38 db01.my.dom mysqld: 2017-03-23 22:48:38 24620 [Warning] Couldn't load plugin named 'AUDIT' with soname 'libaudit_plugin.so'.

[svenXY]

Not sure if this is of any additional help, but after the restart, we saw many of

Mar 23 22:48:42 db02.my.dom mysqld: 2017-03-23 22:48:42 7f1c79f9b720  InnoDB: Error: table `tmp`.`#sql2074_6_1e36` does not exist in the InnoDB internal
Mar 23 22:48:42 db01.my.dom mysqld: InnoDB: data dictionary though MySQL is trying to drop it.
Mar 23 22:48:42 db01.my.dom mysqld: InnoDB: Have you copied the .frm file of the table to the
Mar 23 22:48:42 db01.my.dom mysqld: InnoDB: MySQL database directory from another database?
Mar 23 22:48:42 db01.my.dom mysqld: InnoDB: You can look for further help from
Mar 23 22:48:42 db01.my.dom mysqld: InnoDB: http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html

[aharonrobbins]

Hi. Can you please try using the latest dev-snapshot version? Thanksl.

[svenXY]

hi & thanks for the quick answer. Does that mean that you assume it was your plugin that crashed the mysqld?

[aharonrobbins]

Hi. For some reason I didn't see your question in email, but just now by looking at Github.

To answer your question, I am not assuming the plugin crashed the server. In particular, the plugin does not use std::vector. But to be safe, I'd like you to try our latest, which has several bug fixes.

The last few lines in your log are also troublesome. It says that it can't load the plugin; that looks like it's happening when the DB restarts. Can you double check from the mysql client that the plugin is loaded correctly and functioning? Also please double check that you don't have a different plugin named 'audit', just to be safe.

Much thanks,

Aharon

[aharonrobbins]

Hi. Any update on this?

[aharonrobbins]

Closing this issue.