Auditing MySQL Access with the General Log (and Why to Avoid It in Production)

2020-04-10 · mysql, logging, security, auditing

Someone always asks "who ran that query?" or "what exactly is this application sending to the database?", and the quickest built-in answer is the general query log. It records every connection, statement and disconnect, in order, with the thread ID. It's great for a short investigation. It's also a very effective way to bring a busy production server to its knees, because it writes every statement synchronously to a single file or table. I learned that by leaving it on over a weekend.

Below: how I enable it for a bounded window, how to read the output, and what to use when you need continuous auditing. Examples are on MySQL 5.7 and 8.0. MariaDB has the same log with a couple of differences noted where they matter.

Enable it at runtime, not in the config

Never put general_log = 1 in my.cnf on a production server. It survives restarts and someone will forget it. Enable it dynamically, so a restart turns it off:

SET GLOBAL general_log_file = '/var/log/mysql/general-2020-04-10.log';
SET GLOBAL log_output = 'FILE';
SET GLOBAL general_log = 'ON';

Point the file at a filesystem with plenty of room and away from the data directory. The mysql OS user must be able to write there; on Ubuntu /var/log/mysql already exists with the right ownership, on CentOS create it:

sudo install -d -o mysql -g mysql -m 750 /var/log/mysql

Check the disk growth after a minute:

watch -n 5 ls -lh /var/log/mysql/general-2020-04-10.log

On a server doing a few thousand queries per second this file grows by hundreds of megabytes per minute. Set a mental limit before you start and stick to it.

Turn it off

SET GLOBAL general_log = 'OFF';

One line, but it gets its own heading because it's the one people forget. If I'm capturing during a call, I type the OFF statement into a terminal and leave it ready to press Enter before I turn the log on.

Reading the log

The file format is simple:

2020-04-10T09:14:02.118934Z   1187 Connect  appuser@10.0.0.5 on appdb using TCP/IP
2020-04-10T09:14:02.119411Z   1187 Query    SET NAMES utf8mb4
2020-04-10T09:14:02.120002Z   1187 Query    SELECT id, email FROM customers WHERE id = 4471
2020-04-10T09:14:02.125733Z   1187 Quit

The second column is the connection thread ID, which lets you reconstruct a session from connect to quit even when many sessions interleave. To follow one session:

awk -F'\t' '$2 ~ /^ *1187 /' /var/log/mysql/general-2020-04-10.log

To find every distinct user and host that connected:

grep -P '\tConnect\t' /var/log/mysql/general-2020-04-10.log | awk '{print $4}' | sort | uniq -c | sort -rn

To find who touched a specific table:

grep -i 'payroll' /var/log/mysql/general-2020-04-10.log | awk -F'\t' '{print $2}' | sort -u

Then map those thread IDs back to their Connect lines. Note that the timestamp is in UTC on 5.7+ unless log_timestamps = SYSTEM is set.

Logging to a table

Setting log_output = 'TABLE' writes to mysql.general_log instead, which you can query with SQL. It's handy for very short captures and terrible for long ones. The table uses the CSV engine, has no indexes, and grows without limit.

SET GLOBAL log_output = 'TABLE';
SET GLOBAL general_log = 'ON';
-- ... a few minutes ...
SET GLOBAL general_log = 'OFF';

SELECT event_time, user_host, thread_id, command_type, CONVERT(argument USING utf8mb4) AS stmt
FROM mysql.general_log
WHERE argument LIKE '%payroll%'
ORDER BY event_time;

Clear it afterwards; TRUNCATE is the only supported way:

TRUNCATE TABLE mysql.general_log;

What to use for continuous auditing

The general log is the wrong tool for compliance or continuous monitoring, for three reasons: the write cost on every statement, the fact that it logs passwords in CREATE USER and SET PASSWORD statements in some versions, and the lack of filtering. Alternatives:

MariaDB Audit Plugin (server_audit) ships with MariaDB 10.x and works on MySQL 5.7. It can log only connects and DDL, filter by user, and rotate its own files:

[mysqld]
plugin_load_add           = server_audit
server_audit_logging      = ON
server_audit_events       = CONNECT,QUERY_DDL,QUERY_DCL
server_audit_excl_users   = monitoring
server_audit_file_rotate_size = 100000000
server_audit_file_rotations   = 10

Percona Audit Log Plugin (audit_log) does the same for Percona Server and MySQL, with JSON output.
MySQL Enterprise Audit for Oracle's commercial edition.
Performance Schema events_statements_history_long for a rolling buffer of recent statements per thread without touching disk:

UPDATE performance_schema.setup_consumers SET ENABLED = 'YES'
WHERE NAME = 'events_statements_history_long';
SELECT thread_id, sql_text FROM performance_schema.events_statements_history_long
WHERE sql_text LIKE '%payroll%';

After the capture

Confirm the server has stopped writing:

SHOW GLOBAL VARIABLES LIKE 'general_log%';

ls -lh /var/log/mysql/general-2020-04-10.log; sleep 10; ls -lh /var/log/mysql/general-2020-04-10.log

Same size twice means it is off. Compress and move the file somewhere with restricted permissions immediately; it contains every query parameter, including personal data and potentially credentials.

sudo gzip /var/log/mysql/general-2020-04-10.log
sudo chmod 600 /var/log/mysql/general-2020-04-10.log.gz

Gotchas

ERROR 1231 (42000): Variable 'general_log_file' can't be set to the value of '/var/log/mysql/general.log' or an error log entry Could not use /var/log/mysql/general.log for logging (error 13 - Permission denied). The mysql user cannot write to the directory, or AppArmor on Ubuntu denies it. Check /etc/apparmor.d/usr.sbin.mysqld includes /var/log/mysql/** rw.

Disk full during capture. The server does not stop or crash; it logs Failed to write to mysql.general_log and continues, but everything else on that filesystem suffers. Turn the log off, delete or compress the file, and next time pick a shorter window.

Statements from prepared-statement APIs show Prepare and Execute lines with ? placeholders rather than values on the Prepare line. The Execute line has the bound values, so read that one.

log_output = 'FILE,TABLE' writes to both destinations and doubles the overhead. Pick one.

For anything longer than a diagnosis I install an audit plugin and keep the general log for the day I genuinely need to see everything.