Audit log issues when audit_log_handler=SYSLOG on Ubuntu

[Przemek]

When audit log is set to log to syslog, by default, for some reason it starts to log user actions to /var/log/auth.log instead on /var/log/syslog. Only initial startup entry ends up in /var/log/syslog. Moreover, audit_log_syslog_ident seems to be completely ignored, except for the initial event. Enabling log_syslog=1 tells the audit plugin to log everything to /var/log/syslog but still ident is ignored.
Tested on Ubuntu 14.04 and 16.04, with Percona Server 5.7.18 installed from Apt repo.

Examples:

mysql> show variables like '%audit%';
+-----------------------------+---------------+
| Variable_name | Value |
+-----------------------------+---------------+
| audit_log_buffer_size | 1048576 |
| audit_log_exclude_accounts | |
| audit_log_exclude_commands | |
| audit_log_exclude_databases | |
| audit_log_file | audit.log |
| audit_log_flush | OFF |
| audit_log_format | OLD |
| audit_log_handler | SYSLOG |
| 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 | ASYNCHRONOUS |
| 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)

root@vagrant:~# tail /var/log/syslog
Aug 4 10:31:30 vagrant systemd[1]: Starting Percona Server...
Aug 4 10:31:30 vagrant percona-audit: {"audit_record":{"name":"Audit","record":"1_1970-01-01T00:00:00","timestamp":"2017-08-04T10:31:30 UTC","mysql_version":"5.7.18-16","startup_optionsi":"--daemonize --pid-file=/var/run/mysqld/mysqld.pid","os_version":"x86_64-debian-linux-gnu"}}

root@vagrant:~# tail -1 /var/log/auth.log
Aug 4 10:41:18 vagrant mysqld[16176]: {"audit_record":{"name":"Query","record":"14_1970-01-01T00:00:00","timestamp":"2017-08-04T10:41:18 UTC","command_class":"create_db","connection_id":"5","status":0,"sqltext":"create database test","user":"root[root] @ localhost []","host":"localhost","os_user":"root","ip":"","db":""}}

mysql> set global log_syslog=1;
Query OK, 0 rows affected (0.00 sec)

root@vagrant:~# tail -1 /var/log/syslog
Aug 4 11:43:18 vagrant mysqld[16931]: <AUDIT_RECORD#012 NAME="Query"#012 RECORD="6_1970-01-01T00:00:00"#012 TIMESTAMP="2017-08-04T11:43:18 UTC"#012 COMMAND_CLASS="set_option"#012 CONNECTION_ID="3"#012 STATUS="0"#012 SQLTEXT="set global log_syslog=1"#012 USER="root[root] @ localhost []"#012 HOST="localhost"#012 OS_USER="root"#012 IP=""#012 DB=""#012/>

In the same configuration, logging works as expected on Centos:

mysql> show variables like '%syslog%';
+---------------------------+---------------+
| Variable_name | Value |
+---------------------------+---------------+
| audit_log_syslog_facility | LOG_USER |
| audit_log_syslog_ident | percona-audit |
| audit_log_syslog_priority | LOG_INFO |
| log_syslog | OFF |
| log_syslog_facility | daemon |
| log_syslog_include_pid | ON |
| log_syslog_tag | |
+---------------------------+---------------+
7 rows in set (0.01 sec)

mysql> \! tail -2 /var/log/messages
Aug 4 11:23:06 vagrant-centos65 percona-audit: <AUDIT_RECORD#012 NAME="Query"#012 RECORD="756_1970-01-01T00:00:00"#012 TIMESTAMP="2017-08-04T11:23:06 UTC"#012 COMMAND_CLASS="insert"#012 CONNECTION_ID="197"#012 STATUS="0"#012 SQLTEXT="INSERT INTO t1 VALUES (755026)"#012 USER="root[root] @ localhost []"#012 HOST="localhost"#012 OS_USER=""#012 IP=""#012 DB="test"#012/>
Aug 4 11:23:06 vagrant-centos65 percona-audit: <AUDIT_RECORD#012 NAME="Quit"#012 RECORD="757_1970-01-01T00:00:00"#012 TIMESTAMP="2017-08-04T11:23:06 UTC"#012 CONNECTION_ID="197"#012 STATUS="0"#012 USER="root"#012 PRIV_USER="root"#012 OS_LOGIN=""#012 PROXY_USER=""#012 HOST="localhost"#012 IP=""#012 DB="test"#012/>
mysql> \! cat /etc/issue
CentOS release 6.5 (Final)
Kernel \r on an \m

[Sveta Smirnova (svetasmirnova)]

Bug is not repeatable with tar.gz package and with self-compiled Percona Server, started with help of MTR:

./mtr --start --mysqld=--plugin-load=audit_log.so --mysqld=--audit_log_handler=SYSLOG --mysqld=--audit_log_syslog_ident=mysql-audit --mysqld=--audit_log_format=JSON innodb &

Only packaged version is affected.

[Shahriyar Rzayev (rzayev-sehriyar)]

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