MySQL 5.6 general query log behavior change

The MySQL general query log can be a useful debugging tool, showing commands received from clients.  In versions through MySQL 5.5, you could count on the GQL to log every command it received – the logging happened before parsing.  That can be helpful – for example, the GQL entries might have records of somebody unsuccessfully attempting to exploit SQL injection vulnerabilities that result in syntax exceptions.

Here’s a sample, which I’ll run in both 5.5 and 5.6 and show the resulting GQL:

mysql> SELECT 1;
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.00 sec)

mysql> SELECT NOTHING();
ERROR 1305 (42000): FUNCTION NOTHING does not exist
mysql> SELECT 2;
+---+
| 2 |
+---+
| 2 |
+---+
1 row in set (0.00 sec)

In 5.5, this produces the following in the general query log:

130513 18:26:34        1 Query    SELECT 1
130513 18:26:40        1 Query    SELECT NOTHING()
130513 18:26:44        1 Query    SELECT 2

In 5.6, the same produces the following:

130425 21:53:25        1 Query    SELECT 1
130425 21:53:35        1 Query    SELECT 2

The behavior hasn’t changed between 5.5 and 5.6 with respect to successfully-parsed, but unauthorized statements.  With the limited-privilege anonymous user account, I issued the following against both 5.5 and 5.6 servers:

mysql> SHOW GRANTS;
+--------------------------------------+
| Grants for @localhost                |
+--------------------------------------+
| GRANT USAGE ON *.* TO ''@'localhost' |
+--------------------------------------+
1 row in set (0.00 sec)

mysql> SELECT * FROM mysql.user;
ERROR 1142 (42000): SELECT command denied to user ''@'localhost' for table 'user'

The general query log for both 5.5 and 5.6 recorded the attempt to SELECT from mysql.user system table:

130513 18:31:10        3 Query    SHOW GRANTS
130513 18:31:11        3 Query    SELECT * FROM mysql.user

The documentation doesn’t explicitly note this behavior change (I filed Bug#68937 to include this in the manual) – it talks about the password-masking feature which triggered this behavioral change, though (and this page also documents which statements are rewritten).  In order to mask passwords in log files, the log entries have to be written after they are parsed.  When I issue the following statement in 5.6, the password is masked in the general query log:

mysql> SET PASSWORD = PASSWORD('test');
Query OK, 0 rows affected (0.00 sec)

Here’s the corresponding general query log entry:

130513 18:45:59        2 Query    SET PASSWORD FOR `root`=<secret>

That’s much appreciated behavior – there’s typically no reason to expose passwords in logs.  For those who do need this temporarily for diagnostic purposes, there’s a –log-raw option which logs before parsing, just like in 5.5.  This means that plain-text passwords as well as statements with syntax errors get logged.  Here’s the result in 5.6 with –log-raw enabled:

130513 18:43:10        1 Query    SELECT NOTHING()

Unfortunately, there’s no status variable to tell a DBA whether or not they are protected by the new 5.6 behavior, or whether the running server has been started with –log-raw to override it and is still logging plain-text passwords.  I filed Bug#68936 to address that.  I would also love to allow users (with appropriate permissions) the ability to change this configuration option without restart of MySQL Server, but it’s probably not something that will need – or want – to be changed in a production environment where downtime is critical.

I’m happy to see plain-text passwords removed from logs in 5.6, and hope that this post helps clarify associated behavioral changes related to the general query log in 5.6.