Trying to set audit_log_exclude_accounts crashes server.

[selivan]

Query:

set global audit_log_exclude_accounts='info@localhost';

Installed packages:

ii percona-toolkit 2.2.19-1 all Advanced MySQL and system command-line tools
ii percona-xtrabackup-24 2.4.4-1.trusty amd64 Open source backup tool for InnoDB and XtraDB
ii percona-xtradb-cluster-client-5.7 5.7.14-26.17-1.trusty amd64 Percona XtraDB Cluster database client binaries
ii percona-xtradb-cluster-common-5.7 5.7.14-26.17-1.trusty amd64 Percona XtraDB Cluster database common files (e.g. /etc/mysql/my.cnf)
ii percona-xtradb-cluster-galera-3.x 3.17-1.trusty amd64 Galera components of Percona XtraDB Cluster
ii percona-xtradb-cluster-server-5.7 5.7.14-26.17-1.trusty amd64 Percona XtraDB Cluster database server binaries

Error log:

10:42:53 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.
Please help us make Percona XtraDB Cluster better by reporting any
bugs at https://bugs.launchpad.net/percona-xtradb-cluster

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

Thread pointer: 0x7fb0b4000e60
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 = 7fb124e3ea30 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0xef9fbc]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x7a9601]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7fb2bf653330]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7fb2bea94c37]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7fb2bea98028]
/lib/x86_64-linux-gnu/libc.so.6(+0x732a4)[0x7fb2bead12a4]
/lib/x86_64-linux-gnu/libc.so.6(+0x7f55e)[0x7fb2beadd55e]
/usr/lib/mysql/plugin/audit_log.so(+0x482e)[0x7fb11880682e]
/usr/sbin/mysqld(_ZN17sys_var_pluginvar13global_updateEP3THDP7set_var+0x59)[0xcf8eb9]
/usr/sbin/mysqld(_ZN7sys_var6updateEP3THDP7set_var+0x1ed)[0xc4187d]
/usr/sbin/mysqld(_ZN7set_var6updateEP3THD+0x17)[0xc41ef7]
/usr/sbin/mysqld(_Z17sql_set_variablesP3THDP4ListI12set_var_baseE+0x71)[0xc42ac1]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THDb+0x5613)[0xcd2583]
/usr/sbin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x645)[0xcd46e5]
/usr/sbin/mysqld[0xcd4813]
/usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xd50)[0xcd5f10]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x192)[0xcd7bd2]
/usr/sbin/mysqld(handle_connection+0x368)[0xd9c748]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0x12719d4]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8184)[0x7fb2bf64b184]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fb2beb5837d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7fb0b4005d50): is an invalid pointer
Connection ID (thread ID): 21
Status: NOT_KILLED

You may download the Percona XtraDB Cluster operations manual by visiting
http://www.percona.com/software/percona-xtradb-cluster/. You may find information
in the manual which will help you identify the cause of the crash.
2016-11-15T10:42:53.314517Z mysqld_safe Number of processes running now: 0
2016-11-15T10:42:53.315375Z mysqld_safe WSREP: not restarting wsrep node automatically
2016-11-15T10:42:53.316816Z mysqld_safe mysqld from pid file /var/lib/mysql/data/db4-ire1.pid ended

[selivan (selivan5)]

Additional info: OS is Ubuntu 14.04 Trusty, PXC packages installed from Percona apt repository.

[Krunal Bauskar (krunal-bauskar)]

I tried this with Ubuntu 15.04 shouldn't be different but couldn't reproduce it.

Can you arrange to send the log files + my.cnf configuration setting.

Also, is this always reproducible. Do you have short-test-case ?

[selivan (selivan5)]

Reproduced it again several times. Always reproducable for me.

my.cnf: https://gist.github.com/selivan/696c20d32a4339b463347bffb19ec93d
error.log: https://gist.github.com/selivan/1b9d352f757518f96ff778292950c795

How I did it:

(selivanov@localhost) [(none)]> show variables like 'audit_log%';
+-----------------------------+---------------------------------+
| Variable_name | Value |
+-----------------------------+---------------------------------+
| audit_log_buffer_size | 1048576 |
| audit_log_exclude_accounts | info'@'127.0.0.1 |
| audit_log_exclude_commands | |
| audit_log_exclude_databases | |
| audit_log_file | /var/log/mysql/mysql-audit.json |
| audit_log_flush | OFF |
| audit_log_format | JSON |
| audit_log_handler | FILE |
| audit_log_include_accounts | |
| audit_log_include_commands | |
| audit_log_include_databases | |
| audit_log_policy | ALL |
| audit_log_rotate_on_size | 0 |
| audit_log_rotations | 0 |
| audit_log_strategy | PERFORMANCE |
| audit_log_syslog_facility | LOG_USER |
| audit_log_syslog_ident | percona-audit |
| audit_log_syslog_priority | LOG_INFO |
+-----------------------------+---------------------------------+
18 rows in set (0.00 sec)

(selivanov@localhost) [(none)]> set global audit_log_exclude_accounts='info@localhost';
ERROR 2013 (HY000): Lost connection to MySQL server during query

[selivan (selivan5)]

I suppose, to reproduce it you should have exactly the same audit plugin settings and probably try it on Ubuntu 14.04 Trusty.

[Krunal Bauskar (krunal-bauskar)]

I was able to reproduce this with PS-5.7.14 upstream

WAY-1
====

Tried following 2 commands:

./bin/mysqld --initialize-insecure --datadir=./data-dir --basedir=./

./bin/mysqld --datadir=./data-dir --basedir=. --port=29993 --socket=/tmp/mysql.sock --skip-grant-tables --plugin-load=audit_log=audit_log.so --audit_log_file=./data-dir/mysql-audit.json --audit_log_strategy=PERFORMANCE --audit_log_format=JSON --audit_log_exclude_accounts='info'@'127.0.0.1'

2016-11-17T09:38:52.280274Z 0 [Note] InnoDB: Buffer pool(s) load completed at 161117 15:08:52
2016-11-17T09:38:53.273925Z 0 [ERROR] Plugin audit_log reported: 'Cannot open file ./data-dir/mysql-audit.json.'
2016-11-17T09:38:53.274028Z 0 [ERROR] Plugin audit_log reported: 'Error: No such file or directory'
2016-11-17T09:38:53.274068Z 0 [ERROR] Plugin 'audit_log' init function returned error.
2016-11-17T09:38:53.274103Z 0 [ERROR] Plugin 'audit_log' registration as a AUDIT failed.
mysqld: /opt/projects/codebase/non-forked-percona/ps57/mysys/my_malloc.c:128: my_free: Assertion `mh->m_magic == 1234' failed.
09:38:53 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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

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

Thread pointer: 0x0
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 = 0 thread_stack 0x40000
./bin/mysqld(my_print_stacktrace+0x47)[0x199601f]
./bin/mysqld(handle_fatal_signal+0x440)[0xf2c22b]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10d10)[0x7f61c6774d10]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f61c5b2e1c7]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f61c5b2fe2a]
/lib/x86_64-linux-gnu/libc.so.6(+0x2e0bd)[0x7f61c5b270bd]
/lib/x86_64-linux-gnu/libc.so.6(+0x2e172)[0x7f61c5b27172]
./bin/mysqld(my_free+0x4c)[0x198fe57]
/opt/projects/codebase/non-forked-percona/installed/ps/5.7/lib/mysql/plugin/audit_log.so(+0x621e)[0x7f61ad3cf21e]
./bin/mysqld(_Z21finalize_audit_pluginP13st_plugin_int+0x3f)[0xf2e387]
./bin/mysqld[0x166c27c]
./bin/mysqld[0x166d12a]
./bin/mysqld(_Z11plugin_initPiPPci+0x8f5)[0x166dac4]
./bin/mysqld[0xf1a39f]
./bin/mysqld(_Z11mysqld_mainiPPc+0x82e)[0xf1ba57]
./bin/mysqld(main+0x20)[0xf12946]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7f61c5b19ac0]
./bin/mysqld(_start+0x29)[0xf12859]
You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server...

[Sergei Glushchenko (sergei.glushchenko)]

Looks like when setting the value via command line UPDATE and CHECK functions are not invoked.

[Sergei Glushchenko (sergei.glushchenko)]

Test case

audit_log_acc.test:

set global audit_log_exclude_accounts='info@localhost';

audit_log_acc-master.opt:
$AUDIT_LOG_OPT
$AUDIT_LOG_LOAD
--audit_log_exclude_accounts='info'@'127.0.0.1'

[Sergei Glushchenko (sergei.glushchenko)]

Fix will be to manually invoke audit_log_*_accounts_validate and audit_log_*_accounts_update in plugin init.

[Sergei Glushchenko (sergei.glushchenko)]

https://github.com/percona/percona-server/pull/1175
https://github.com/percona/percona-server/pull/1176

[Krunal Bauskar (krunal-bauskar)]

Looks like this has been fixed in upstream.

[Krunal Bauskar (krunal-bauskar)]

Let me take it back. Seems like PS-5.7.17 is still hitting this issue.

I could reproduce it with PS-5.7.17.

<snippet from comment#5 to reproduce>

./bin/mysqld --no-defaults --initialize-insecure --datadir=./data-dir --basedir=./

./bin/mysqld --datadir=./data-dir --basedir=. --port=29993 --socket=/tmp/mysql.sock --skip-grant-tables --plugin-load=audit_log=audit_log.so --audit_log_file=./data-dir/mysql-audit.json --audit_log_strategy=PERFORMANCE --audit_log_format=JSON --audit_log_exclude_accounts='info'@'127.0.0.1'

</snippet from comment#5 to reproduce>

[Laurynas Biveinis (laurynas-biveinis)]

Bug 1666496

[Krunal Bauskar (krunal-bauskar)]

This is an upstream issue and relevant issue has been logged in upstream. Will close this in from PXC kitty.

[Shahriyar Rzayev (rzayev-sehriyar)]

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

[Shahriyar Rzayev (rzayev-sehriyar)]

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

[Shahriyar Rzayev (rzayev-sehriyar)]

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