Installation of audit_log plugin crashes mysql server if audit_log_file points to a inaccessible path

[monty solomon]

2015-03-23T22:42:55 audit_log: Cannot open file /opt/m. Error: : Permission denied
2015-03-23 22:42:55 5792 [ERROR] Plugin 'audit_log' init function returned error.
2015-03-23 22:42:55 5792 [ERROR] Plugin 'audit_log' registration as a AUDIT failed.
2015-03-23 22:42:55 5792 [Note] Shutting down plugin 'audit_log'
22:42:55 UTC - mysqld got signal 11 ;
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.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

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

Thread pointer: 0x29175c90
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 = 7f9d5fdb5d40 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8c13ac]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x651e41]
/lib64/libpthread.so.0(+0xf710)[0x7fa3bd49b710]
/usr/lib64/mysql/plugin/audit_log.so(+0x4a28)[0x7f9d5e20da28]
/usr/sbin/mysqld(_Z21finalize_audit_pluginP13st_plugin_int+0x1f)[0x6812bf]
/usr/sbin/mysqld[0x6e0097]
/usr/sbin/mysqld(_Z20mysql_install_pluginP3THDPK19st_mysql_lex_stringS3_+0x5ae)[0x6e12ce]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x3d9d)[0x6d41ad]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x5c8)[0x6d7478]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xfb7)[0x6d8b97]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x162)[0x6a67a2]
/usr/sbin/mysqld(handle_one_connection+0x40)[0x6a6890]
/usr/sbin/mysqld(pfs_spawn_thread+0x143)[0xacd003]
/lib64/libpthread.so.0(+0x79d1)[0x7fa3bd4939d1]
/lib64/libc.so.6(clone+0x6d)[0x7fa3bbbb2b6d]

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

[monty solomon (monty+launchpad)]

The file name entry from the error log contains non-ascii characters

0000000 2 0 1 5 - 0 3 - 2 3 T 2 2 : 4 2
        062 060 061 065 055 060 063 055 062 063 124 062 062 072 064 062
0000020 : 5 5 a u d i t _ l o g : C
        072 065 065 040 141 165 144 151 164 137 154 157 147 072 040 103
0000040 a n n o t o p e n f i l e
        141 156 156 157 164 040 157 160 145 156 040 146 151 154 145 040
0000060 / o p t / m y \b 005 . E r r o r
        057 157 160 164 057 155 171 010 005 056 040 105 162 162 157 162
0000100 : : P e r m i s s i o n d
        072 040 072 040 120 145 162 155 151 163 163 151 157 156 040 144
0000120 e n i e d \n 2 0 1 5 - 0 3 - 2 3

[monty solomon (monty+launchpad)]

mysql Ver 14.14 Distrib 5.6.22-71.0, for Linux (x86_64) using EditLine wrapper
Server version: 5.6.22-71.0-log Percona Server (GPL), Release 71.0, Revision 726
Linux willowtub 2.6.32-431.el6.x86_64 #1 SMP Fri Nov 22 03:15:09 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux
CentOS release 6.5 (Final)

[monty solomon (monty+launchpad)]

The problem occurred on a few different servers.

[monty solomon (monty+launchpad)]

Another example

2015-03-23 22:37:17 5857 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
2015-03-23 22:37:17 5857 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'bin.001636' at position 387019559
2015-03-23 22:37:17 5857 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2015-03-23 22:37:17 5857 [ERROR] Slave I/O: error reconnecting to master 'SUSR_Repl@bullis:3306' - retry-time: 15 retries: 1, Error_code: 2003
2015-03-23 22:37:32 5857 [Note] Slave: connected to master 'SUSR_Repl@bullis:3306',replication resumed in log 'bin.001636' at position 387019559
2015-03-23T22:43:55 audit_log: Cannot open file /opt/m. Error: : Permission denied
2015-03-23 22:43:55 5857 [ERROR] Plugin 'audit_log' init function returned error.
2015-03-23 22:43:55 5857 [ERROR] Plugin 'audit_log' registration as a AUDIT failed.
2015-03-23 22:43:55 5857 [Note] Shutting down plugin 'audit_log'
22:43:55 UTC - mysqld got signal 11 ;
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.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

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

Thread pointer: 0x2a0bdd60
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 = 7fa73908ad40 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8c13ac]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x651e41]
/lib64/libpthread.so.0(+0xf710)[0x7fad8f194710]
/usr/lib64/mysql/plugin/audit_log.so(+0x4a28)[0x7fa72f59aa28]
/usr/sbin/mysqld(_Z21finalize_audit_pluginP13st_plugin_int+0x1f)[0x6812bf]
/usr/sbin/mysqld[0x6e0097]
/usr/sbin/mysqld(_Z20mysql_install_pluginP3THDPK19st_mysql_lex_stringS3_+0x5ae)[0x6e12ce]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x3d9d)[0x6d41ad]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x5c8)[0x6d7478]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xfb7)[0x6d8b97]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x162)[0x6a67a2]
/usr/sbin/mysqld(handle_one_connection+0x40)[0x6a6890]
/usr/sbin/mysqld(pfs_spawn_thread+0x143)[0xacd003]
/lib64/libpthread.so.0(+0x79d1)[0x7fad8f18c9d1]
/lib64/libc.so.6(clone+0x6d)[0x7fad8d8...

[monty solomon (monty+launchpad)]

Installation procedure for the running servers via puppet

Add entries to my.cnf

audit-log = FORCE_PLUS_PERMANENT
audit_log_file = /opt/mysql/dblogs1/test-p0/audit/audit.log
audit_log_format = JSON
audit_log_strategy = SEMISYNCHRONOUS
plugin-load = audit_log.so

execute
INSTALL PLUGIN audit_log SONAME 'audit_log.so'

Mar 23 22:43:56 puppet-agent[16927]: (/Stage[main]/Mysql::Audit_log/Exec[load_audit_log.so]/returns) ERROR 2013 (HY000) at line 1: Lost connection to MySQL server during query
Mar 23 22:43:56 puppet-agent[16927]: mysql -uroot -e "INSTALL PLUGIN audit_log SONAME 'audit_log.so'" returned 1 instead of one of [0]
Mar 23 22:43:56 puppet-agent[16927]: (/Stage[main]/Mysql::Audit_log/Exec[load_audit_log.so]/returns) change from notrun to 0 failed: mysql -uroot -e "INSTALL PLUGIN audit_log SONAME 'audit_log.so'" returned 1 instead of one of [0]
Mar 23 22:43:56 puppet-agent[16927]: (/Stage[main]/Mysql::Audit_log/Exec[load_audit_log.so]/returns) ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/opt/mysql/dbprod/test-p0.sock' (2)
Mar 23 22:43:56 puppet-agent[16927]: (/Stage[main]/Mysql::Audit_log/Exec[load_audit_log.so]) Failed to call refresh: mysql -uroot -e "INSTALL PLUGIN audit_log SONAME 'audit_log.so'" returned 1 instead of one of [0]
Mar 23 22:43:56 puppet-agent[16927]: (/Stage[main]/Mysql::Audit_log/Exec[load_audit_log.so]) mysql -uroot -e "INSTALL PLUGIN audit_log SONAME 'audit_log.so'" returned 1 instead of one of [0]

[monty solomon (monty+launchpad)]

2015-03-23 22:34:09 5850 [Note] Start binlog_dump to master_thread_id(48126913) slave_server(2922609890), pos(bin.001636, 271174138)
2015-03-23T22:37:17 audit_log: Cannot open file /opt/m. Error: : Permission denied
2015-03-23 22:37:17 5850 [ERROR] Plugin 'audit_log' init function returned error.
2015-03-23 22:37:17 5850 [ERROR] Plugin 'audit_log' registration as a AUDIT failed.
2015-03-23 22:37:17 5850 [Note] Shutting down plugin 'audit_log'
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8c13ac]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x651e41]
/lib64/libpthread.so.0(+0xf710)[0x7ff6021e0710]
/usr/lib64/mysql/plugin/audit_log.so(+0x4a28)[0x7fef98f84a28]
/usr/sbin/mysqld(_Z21finalize_audit_pluginP13st_plugin_int+0x1f)[0x6812bf]
/usr/sbin/mysqld[0x6e0097]
/usr/sbin/mysqld(_Z20mysql_install_pluginP3THDPK19st_mysql_lex_stringS3_+0x5ae)[0x6e12ce]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x3d9d)[0x6d41ad]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x5c8)[0x6d7478]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xfb7)[0x6d8b97]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x162)[0x6a67a2]
/usr/sbin/mysqld(handle_one_connection+0x40)[0x6a6890]
/usr/sbin/mysqld(pfs_spawn_thread+0x143)[0xacd003]
/lib64/libpthread.so.0(+0x79d1)[0x7ff6021d89d1]
/lib64/libc.so.6(clone+0x6d)[0x7ff6008f7b6d]
150323 22:37:17 mysqld_safe Number of processes running now: 0
150323 22:37:17 mysqld_safe mysqld restarted

0000000 062 060 061 065 055 060 063 055 062 063 124 062 062 072 063 067
          2 0 1 5 - 0 3 - 2 3 T 2 2 : 3 7
0000020 072 061 067 040 141 165 144 151 164 137 154 157 147 072 040 103
          : 1 7 a u d i t _ l o g : C
0000040 141 156 156 157 164 040 157 160 145 156 040 146 151 154 145 040
          a n n o t o p e n f i l e
0000060 057 157 160 164 057 155 171 010 005 056 040 105 162 162 157 162
          / o p t / m y \b 005 . E r r o r
0000100 072 040 072 040 120 145 162 155 151 163 163 151 157 156 040 144
          : : P e r m i s s i o n d
0000120 145 156 151 145 144 012 062 060 061 065 055 060 063 055 062 063
          e n i e d \n 2 0 1 5 - 0 3 - 2 3

mysql Ver 14.14 Distrib 5.6.22-71.0, for Linux (x86_64) using EditLine wrapper
Server version: 5.6.22-71.0-log Percona Server (GPL), Release 71.0, Revision 726
Linux bullis 2.6.32-431.el6.x86_64 #1 SMP Fri Nov 22 03:15:09 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux
CentOS release 6.5 (Final)

[Valerii Kravchuk (valerii-kravchuk)]

This is easy to confirm:

[root@centos openxs]# mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.6.23-72.1-log Percona Server (GPL), Release 72.1, Revision 0503478

Copyright (c) 2009-2015 Percona LLC and/or its affiliates
Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> INSTALL PLUGIN audit_log SONAME 'audit_log.so'
    -> ;
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql> exit
Bye

In the error log we see:

...
2015-03-24 10:01:49 3126 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.23-72.1-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 Percona Server (GPL), Release 72.1, Revision 0503478
2015-03-24T08:03:01 audit_log: Cannot open file /var/log/mysql-audit.log. Error: : Permission denied
2015-03-24 10:03:01 3126 [ERROR] Plugin 'audit_log' init function returned error.
2015-03-24 10:03:01 3126 [ERROR] Plugin 'audit_log' registration as a AUDIT failed.
2015-03-24 10:03:01 3126 [Note] Shutting down plugin 'audit_log'
08:03:01 UTC - mysqld got signal 11 ;
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.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may 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=1
max_threads=153
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 = 69184 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f02ec7f9000
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 = 7f031d3a1d00 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8cc59c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x654f11]
/lib64/libpthread.so.0(+0xf710)[0x7f031cdb6710]
/usr/lib64/mysql/plugin/audit_log.so(+0x34b7)[0x7f02f491d4b7]
/usr/sbin/mysqld(_Z21finalize_audit_pluginP13st_plugin_int+0x1f)[0x684d6f]
/usr/sbin/mysqld[0x6e45c7]
/usr/sbin/mysqld(_Z20mysql_install_pluginP3THDPK19st_mysql_lex_stringS3_+0x5de)[0x6e587e]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x101c)[0x6d587c]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x5c8)[0x6db7e8]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xff9)[0x6dcf59]
/usr/sbin/mysqld(_Z24do_handle_one_con...

[Sergei Glushchenko (sergei.glushchenko)]

https://github.com/percona/percona-server/pull/47, https://github.com/percona/percona-server/pull/48

[monty solomon (monty+launchpad)]

The audit_log_file was created and existed with appropriate permissions before the plugin was installed.

# ls -al audit.log
-rw-rw---- 1 mysql mysql 0 Mar 31 05:00 audit.log

The problem occurs when audit-log = FORCE_PLUS_PERMANENT

[monty solomon (monty+launchpad)]

When audit-log = ON it writes to the log file but does not set the audit_log_file variable.

I started the server with the plugin uninstalled and these options in my.cnf

loose-audit-log = ON
loose-audit_log_file = /opt/mysql/dblogs1/test-p0/audit/audit.log
loose-audit_log_format = JSON
loose-audit_log_strategy = SEMISYNCHRONOUS

mysql> show variables like 'audit%';
Empty set (0.00 sec)

# ls -lt
-rw-rw---- 1 mysql mysql 0 Mar 31 05:19 audit.log

Then I executed the following

mysql -uroot -e "INSTALL PLUGIN audit_log SONAME 'audit_log.so'"

mysql> show variables like 'audit%';
+---------------------------+-----------------+
| Variable_name | Value |
+---------------------------+-----------------+
| audit_log_buffer_size | 1048576 |
| audit_log_file | |
| audit_log_flush | OFF |
| audit_log_format | JSON |
| audit_log_handler | FILE |
| audit_log_policy | ALL |
| audit_log_rotate_on_size | 0 |
| audit_log_rotations | 0 |
| audit_log_strategy | SEMISYNCHRONOUS |
| audit_log_syslog_facility | LOG_USER |
| audit_log_syslog_ident | percona-audit |
| audit_log_syslog_priority | LOG_INFO |
+---------------------------+-----------------+
12 rows in set (0.00 sec)

# ls -lt
-rw-rw---- 1 mysql mysql 3952 Mar 31 05:20 audit.log

# ls -lt
-rw-rw---- 1 mysql mysql 4974 Mar 31 05:20 audit.log

[Sergei Glushchenko (sergei.glushchenko)]

The problem with wrong value of audit_log_file after "INSTALL PLUGIN... " will be fixed as part of fix for bug 1437505.

[monty solomon (monty+launchpad)]

The summary of this bug was changed to include "if audit_log_file points to a inaccessible path"

Does that refer to the value of audit_log_file in the my.cnf file?

[Laurynas Biveinis (laurynas-biveinis)]

I have edited the title so that it were specific. My new title is too narrow. Monty, Sergei, can you improve it?

[Laurynas Biveinis (laurynas-biveinis)]

For the release note entry, note the duplicate bug: UNINSTALL PLUGIN used to crash too.

[Shahriyar Rzayev (rzayev-sehriyar)]

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