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)

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:

| 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.


4 thoughts on “MySQL 5.6 general query log behavior change

  1. The sad thing for me is that after all these years, it’s still possible to add a server commandline option without an associated variable in SHOW VARIABLES.

    1. Hi Baron – I completely agree that there should be a general rule that all new configuration options should have a corresponding global variable. Ideally, that variable will allow runtime manipulation by a user with appropriate privileges (to avoid requiring server restart for reconfiguration). This actually mirrors a proposal I recently made, after running into the two options in 5.6 where this wasn’t done (–log-raw and –default-authentication-plugin). There are a couple of other options introduced in 5.6 which are exceptions:

      1. –validate-password state is best obtained from INFORMATION_SCHEMA.PLUGINS table
      2. –plugin-load-add is the same way (and mirrors –plugin-load behavior)
      3. –performance-schema-instrument controls which PERFORMANCE_SCHEMA instruments are enabled at startup. Because of how this configuration works (allowing multiple –performance-schema-instrument options and pattern matching), getting the current state from the related PERFORMANCE_SCHEMA tables is better than exposing this information in global variables (IMHO).

      I’ve already started looking at 5.7 options and am pushing the same general policy you mentioned: No new options without associated global variables, at least without explicit design justification.

  2. Hi Todd,

    Those changes do make sense if you don’t want to see unsuccessful
    commands in the general log.However, the main purpose of general
    log is to help in debugging process. Therefore the ability to see
    the failed commands is quite useful for debugging.

    I would add an option to be able to see the commands that had been
    issued, but executed unsuccessfully. I would also add the server
    error message that had been issued together.

    Best regards,

    Jacob Nikom

    1. Hi Jacob,

      The –log-raw option will revert to the behavior of MySQL 5.5 and log all commands, not just those which succeed. It’s also worth noting that I’ve only observed 5.6 general query log filtering statements with syntax errors (those which cannot be parsed) – those with execution errors, such as duplicate key exceptions, etc. still are written to the log.

      Hope that helps!


Leave a Reply

Your email address will not be published. Required fields are marked *

Time limit is exhausted. Please reload CAPTCHA.