Trying to log both user logins and quits but only logs quits

[clownred]

Hi,

Great plugin and appreciate having it available for MySQL.

I am having an issue with the plugin not logging user connections - when a user logs into mysql with "mysql -umyuser -p" etc, I want to log both user logins and quits/logouts. With the following in my cnf file it logs quits successfully but not user logins :-

audit_record_cmds="Quit, connect"

I have tried using "Connect" instead of "connect", with quotes and without quotes, without success. Note that if I comment out "audit_record_cmds" from the cnf file and restart, then the plugin will successfully log both user logins and quits/logouts. The problem with that is that I want to control and limit what it logs rather than logging everything.

Am I doing something wrong, is this possible.

Note that I did not do the offsets steps when I installed the plugin since my MySQL version is standard. I am assuming that since the plugin is active, the default offsets worked ok.

CNF file entries

plugin-load=AUDIT=libaudit_plugin.so
audit_json_file=1
audit_record_cmds="Quit, connect"

OUTPUT FROM ERROR LOG WHEN START MYSQL

131206 22:12:44 [Note] Plugin 'FEDERATED' is disabled.
131206 22:12:44 [Note] Audit Plugin: Set interface version to: 12839424 (50154)
131206 22:12:44 InnoDB: Initializing buffer pool, size = 200.0M
131206 22:12:44 InnoDB: Completed initialization of buffer pool
131206 22:12:44 InnoDB: Started; log sequence number 0 409383309
131206 22:12:44 [Note] Audit Plugin: starting up. Version: 1.0.3 , Revision: 371 (64bit). AUDIT plugin interface version: 50154. MySQL Server version: 5.1.54-1ubuntu4-log.
131206 22:12:44 [Note] Audit Plugin: setup_offsets audit_offsets: (null) validate_checksum: 1 offsets_by_version: 1
131206 22:12:45 [Note] Audit Plugin: mysqld: /usr/sbin/mysqld (ab2cb4399ee0306c0822a9a682f03bf4)
131206 22:12:45 [ERROR] Audit Plugin: Offsets: 5.1.54-community (c23b86ac2f64e9de6731fef97e79c98e) match thread validation check fails with value: 0. Skipping offest.
131206 22:12:45 [ERROR] Audit Plugin: Offsets: 5.1.54-community (c23b86ac2f64e9de6731fef97e79c98e) match thread validation check fails with value: 0. Skipping offest.
131206 22:12:45 [Note] Audit Plugin: extended offsets validate res: MySQL thread id 123456, query id 789 aud_tusr
131206 22:12:45 [Note] Audit Plugin: Using offsets from offset version: 5.1.54 (9fca5d956c33e646920e68c541aabcae)
131206 22:12:45 [Note] Audit Plugin: Set num_record_cmds: 2
131206 22:12:45 [Note] Audit Plugin: mem func addr: 0x7fc427031b00 mem start addr: 0x7fc427032000 page size: 4096
131206 22:12:45 [Note] Audit Plugin: hot patching function: 0x7fc427522730, trampolineFunction: 0x7fc427032000 trampolinePage: 0x7fc427032000
131206 22:12:45 [Note] Audit Plugin: hot patch for: log_slow_statement (0x7fc427522730) complete. Audit func: 0x7fc427031650, Trampoline address: 0x7fc427032000 size: 14.
131206 22:12:45 [Note] Audit Plugin: hot patching function: 0x7fc427528120, trampolineFunction: 0x7fc427032020 trampolinePage: 0x7fc427032000
131206 22:12:45 [Note] Audit Plugin: hot patch for: mysql_execute_command (0x7fc427528120) complete. Audit func: 0x7fc427031470, Trampoline address: 0x7fc427032020 size: 18.
131206 22:12:45 [Note] Audit Plugin: hot patching function: 0x7fc427520860, trampolineFunction: 0x7fc427032040 trampolinePage: 0x7fc427032000
131206 22:12:45 [Note] Audit Plugin: hot patch for: check_user (0x7fc427520860) complete. Audit func: 0x7fc4270316c0, Trampoline address: 0x7fc427032040 size: 17.
131206 22:12:45 [Note] Audit Plugin: hot patching function: 0x7fc427655080, trampolineFunction: 0x7fc427032060 trampolinePage: 0x7fc427032000
131206 22:12:45 [Note] Audit Plugin: hot patch for: send_result_to_client (0x7fc427655080) complete. Audit func: 0x7fc427031150, Trampoline address: 0x7fc427032060 size: 18.
131206 22:12:45 [Note] Audit Plugin: hot patching function: 0x7fc427523aa0, trampolineFunction: 0x7fc427032080 trampolinePage: 0x7fc427032000
131206 22:12:45 [Note] Audit Plugin: hot patch for: check_table_access (0x7fc427523aa0) complete. Audit func: 0x7fc427030f90, Trampoline address: 0x7fc427032080 size: 14.
131206 22:12:45 [Note] Audit Plugin: hot patching function: 0x7fc42756ba40, trampolineFunction: 0x7fc4270320a0 trampolinePage: 0x7fc427032000
131206 22:12:45 [Note] Audit Plugin: hot patch for: open_tables (0x7fc42756ba40) complete. Audit func: 0x7fc427031220, Trampoline address: 0x7fc4270320a0 size: 15.
131206 22:12:45 [Note] Audit Plugin: Init completed successfully.
131206 22:12:45 [Note] Event Scheduler: Loaded 0 events
131206 22:12:45 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.54-1ubuntu4-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Ubuntu)
131206 22:12:45 [Note] Audit Plugin: thd_query_string_func: 0x7fc4275064f0

VERSION INFO

mysql> status

mysql Ver 14.14 Distrib 5.1.63, for debian-linux-gnu (x86_64) using readline 6.2

Connection id: 34
Current database:
Current user: debian-sys-maint@localhost
SSL: Not in use
Current pager: stdout
Using outfile: ''
Using delimiter: ;
Server version: 5.1.54-1ubuntu4-log (Ubuntu)
Protocol version: 10
Connection: Localhost via UNIX socket
Server characterset: latin1
Db characterset: latin1
Client characterset: latin1
Conn. characterset: latin1
UNIX socket: /var/run/mysqld/mysqld.sock
Uptime: 5 min 17 sec

Threads: 1 Questions: 101 Slow queries: 1 Opens: 315 Flush tables: 1 Open tables: 77 Queries per second avg: 0.318

mysql> select version();
+---------------------+
| version() |
+---------------------+
| 5.1.54-1ubuntu4-log |
+---------------------+
1 row in set (0.00 sec)

mysql> show global status like 'AUDIT_version';
+---------------+-----------+
| Variable_name | Value |
+---------------+-----------+
| AUDIT_version | 1.0.3-371 |
+---------------+-----------+

PLUGIN STATUS

mysql> show plugins;
+------------+----------+----------------+--------------------+---------+
| Name | Status | Type | Library | License |
+------------+----------+----------------+--------------------+---------+
| binlog | ACTIVE | STORAGE ENGINE | NULL | GPL |
| partition | ACTIVE | STORAGE ENGINE | NULL | GPL |
| ARCHIVE | ACTIVE | STORAGE ENGINE | NULL | GPL |
| BLACKHOLE | ACTIVE | STORAGE ENGINE | NULL | GPL |
| CSV | ACTIVE | STORAGE ENGINE | NULL | GPL |
| FEDERATED | DISABLED | STORAGE ENGINE | NULL | GPL |
| MEMORY | ACTIVE | STORAGE ENGINE | NULL | GPL |
| InnoDB | ACTIVE | STORAGE ENGINE | NULL | GPL |
| MyISAM | ACTIVE | STORAGE ENGINE | NULL | GPL |
| MRG_MYISAM | ACTIVE | STORAGE ENGINE | NULL | GPL |
| AUDIT | ACTIVE | DAEMON | libaudit_plugin.so | GPL |
+------------+----------+----------------+--------------------+---------+

Thanks!

[glicht]

It should work with the configuration you are stating, especially if you are seeing the entries without the audit_record_cmds configuration. I did a test on my env (although not the exact same mysql version/distribution and it works fine).

Can you try using the latest dev-snapshot of the audit plugin. You can download the dev-snapshot builds from here:

https://bintray.com/mcafee/mysql-audit-plugin/dev-snapshot

Latest build currently is: 1.0.4-453. It is stable and production ready.

[clownred]

Thanks for responding Guylichtman.

I removed the previous plugin install and bounced mysql a few times. Then I installed a new plugin version :-
http://dl.bintray.com/mcafee/mysql-audit-plugin/audit-plugin-mysql-5.1-1.0.4-453-linux-x86_64.zip

mysql> show global status like 'AUDIT_version';
+---------------+-----------+
| Variable_name | Value |
+---------------+-----------+
| Audit_version | 1.0.4-453 |
+---------------+-----------+

Then restarted mysql and unfortunately it is still not logging user logins. Since I am using mysql 5.1.54 I am going try the plugin on a more up to date mysql version 5.5.32, and see if that makes a difference.

Currently I am running on Ubuntu Natty, on a VM :-
root@ubuntu:/usr/lib/mysql/plugin# uname -a
Linux ubuntu 2.6.38-8-generic #42-Ubuntu SMP Mon Apr 11 03:31:24 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux

MYSQL ERROR LOG DURING START

131209 15:20:46 [Note] Plugin 'FEDERATED' is disabled.
131209 15:20:46 [Note] Audit Plugin: Set interface version to: 12839424 (50154)
131209 15:20:46 InnoDB: Initializing buffer pool, size = 200.0M
131209 15:20:46 InnoDB: Completed initialization of buffer pool
131209 15:20:46 InnoDB: Started; log sequence number 0 409383309
131209 15:20:46 [Note] Audit Plugin: starting up. Version: 1.0.4 , Revision: 453 (64bit). AUDIT plugin interface version: 50154. MySQL Server version: 5.1.54-1ubuntu4-log.
131209 15:20:46 [Note] Audit Plugin: setup_offsets audit_offsets: (null) validate_checksum: 1 offsets_by_version: 1
131209 15:20:46 [Note] Audit Plugin: mysqld: /usr/sbin/mysqld (ab2cb4399ee0306c0822a9a682f03bf4)
131209 15:20:46 [ERROR] Audit Plugin: Offsets: 5.1.54-community (c23b86ac2f64e9de6731fef97e79c98e) match thread validation check fails with value: 0. Skipping offest.
131209 15:20:46 [ERROR] Audit Plugin: Offsets: 5.1.54-community (c23b86ac2f64e9de6731fef97e79c98e) match thread validation check fails with value: 0. Skipping offest.
131209 15:20:46 [Note] Audit Plugin: extended offsets validate res: MySQL thread id 123456, query id 789 aud_tusr
131209 15:20:46 [Note] Audit Plugin: Using offsets from offset version: 5.1.54 (9fca5d956c33e646920e68c541aabcae)
131209 15:20:46 [Note] Audit Plugin: Set num_record_cmds: 2
131209 15:20:46 [Note] Audit Plugin: mem func addr: % mem start addr: % page size: 140091204909040
131209 15:20:46 [Note] Audit Plugin: hot patching function: %, trampolineFunction: % trampolinePage: %
131209 15:20:46 [Note] Audit Plugin: hot patch for: log_slow_statement (%) complete. Audit func: %, Trampoline address: % size: 2261813040.
131209 15:20:46 [Note] Audit Plugin: hot patching function: %, trampolineFunction: % trampolinePage: %
131209 15:20:46 [Note] Audit Plugin: hot patch for: mysql_execute_command (%) complete. Audit func: %, Trampoline address: % size: 2261836064.
131209 15:20:46 [Note] Audit Plugin: hot patching function: %, trampolineFunction: % trampolinePage: %
131209 15:20:46 [Note] Audit Plugin: hot patch for: check_user (%) complete. Audit func: %, Trampoline address: % size: 2261805152.
131209 15:20:46 [Note] Audit Plugin: hot patching function: %, trampolineFunction: % trampolinePage: %
131209 15:20:46 [Note] Audit Plugin: hot patch for: send_result_to_client (%) complete. Audit func: %, Trampoline address: % size: 2263068800.
131209 15:20:46 [Note] Audit Plugin: hot patching function: %, trampolineFunction: % trampolinePage: %
131209 15:20:46 [Note] Audit Plugin: hot patch for: check_table_access (%) complete. Audit func: %, Trampoline address: % size: 2261818016.
131209 15:20:46 [Note] Audit Plugin: hot patching function: %, trampolineFunction: % trampolinePage: %
131209 15:20:46 [Note] Audit Plugin: hot patch for: open_tables (%) complete. Audit func: %, Trampoline address: % size: 2262112832.
131209 15:20:46 [Note] Audit Plugin: Done initializing sql command names. status_vars_index: [142], com_status_vars: [%].
131209 15:20:46 [Note] Audit Plugin: Init completed successfully.
131209 15:20:46 [Note] Audit Plugin: thd_query_string_func: 0x7f6986cec4f0
131209 15:20:46 [Note] Event Scheduler: Loaded 0 events
131209 15:20:46 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.54-1ubuntu4-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Ubuntu)

thanks

[glicht]

Hi,

Are you sure the "logins" are being logged when audit_record_cmds is not set. What log entry are you seeing in the json file?

I think that with this ubuntu 5.1 distribution we don't catch the "Connect" command at all. Reason is that we use binary interception on the function "check_user" and I think this function is inlined in 5.1.54-1ubuntu4.

Best,

Guy

[clownred]

Hi Guy,

With the audit_record_cmds not set, if I login as a regular user, then quit, then login as a privileged user and also quit, I get the following audit log entries :-

root@ubuntu:/var/lib/mysql# tail -4 mysql-audit.json
{"msg-type":"activity","date":"1386643887458","thread-id":"34","query-id":"98","user":"mike","priv_user":"mike","host":"localhost","cmd":"select","query":"select @@version_comment limit 1"}
{"msg-type":"activity","date":"1386643893493","thread-id":"34","query-id":"99","user":"mike","priv_user":"mike","host":"localhost","cmd":"Quit","query":"Quit"}
{"msg-type":"activity","date":"1386643936476","thread-id":"35","query-id":"100","user":"debian-sys-maint","priv_user":"debian-sys-maint","host":"localhost","cmd":"select","query":"select @@version_comment limit 1"}
{"msg-type":"activity","date":"1386643962674","thread-id":"35","query-id":"101","user":"debian-sys-maint","priv_user":"debian-sys-maint","host":"localhost","cmd":"Quit","query":"Quit"}

plugin-load=AUDIT=libaudit_plugin.so
audit_json_file=1
#audit_record_cmds=connect,Quit

I did test on a second VM host running Natty and Percona Mysql Server 5.5 and the plugin successfully recorded logins and quits, with the audit_record_cmds set. Since that was Percona I had to do the offsets settings for this one and it all worked just fine. Here are settings for that :-

AUDIT_version | 1.0.3-371

Server version: 5.5.23-55 Percona Server (GPL), Release 25.3

plugin-load=AUDIT=libaudit_plugin.so
audit_offsets=6456, 6504, 4064, 4504, 104, 2584
audit_json_file=1
audit_record_cmds=connect,Quit,select

thanks
mike

[glicht]

The 5.1.54-1ubuntu4 distribution doesn't log the Connect cmd. The entry you are seeing:

{"msg-type":"activity","date":"1386643887458","thread-id":"34","query-id":"98","user":"mike","priv_user":"mike","host":"localhost","cmd":"select","query":"select @@version_comment limit 1"}

is a select statement which is executed after the actual connect.

Good to hear that it is working with your other versions.

[clownred]

Thank you Guy.