audit_log_flush makes an incorrect log to be used

[Agustín]

Description:

When using audit_log_flush to manually rotate the logs, if issued more than once, it will make the incorrect log to be used. After the logs are rotated automatically (because of audit_log_rotate_on_size), the correct logs are used again, until audit_log_flush is used more than once again.

This is happening on 5.7 and 5.6. Outputs for 5.7 only are included, for brevity.

How to repeat:

+-------------------------+----------------------------------------------------+
| Variable_name | Value |
+-------------------------+----------------------------------------------------+
...
| version | 5.7.18-14 |
| version_comment | Percona Server (GPL), Release 14, Revision 2c06f4d |

mysql [localhost] {msandbox} ((none)) > 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 | FILE |
| audit_log_include_accounts | |
| audit_log_include_commands | |
| audit_log_include_databases | |
| audit_log_policy | ALL |
| audit_log_rotate_on_size | 5242880 |
| audit_log_rotations | 1 |
| audit_log_strategy | ASYNCHRONOUS |
| audit_log_syslog_facility | LOG_USER |
| audit_log_syslog_ident | percona-audit |
| audit_log_syslog_priority | LOG_INFO |
+-----------------------------+---------------+

Note: audit_log_rotations doesn't need to be 1, it can be anything greater than 0, and the behaviour is the same (audit_log.1 will be used).

I'm adding the inode number to the ls output for clarity on which file is being written to.

Step #1:

After having set the audit log, generate load until we have at least two audit logs. I used the following:

shell> while true; do ./use -e "select 'some text'" > /dev/null; done

Step #2:

shell> ls -lhi audit.log*
17119250 -rw-r----- 1 agustin.gallego percona 1.6M Jun 2 15:53 audit.log
17119248 -rw-r----- 1 agustin.gallego percona 5.1M Jun 2 15:53 audit.log.1

mysql [localhost] {msandbox} ((none)) > SET GLOBAL audit_log_flush=1;
Query OK, 0 rows affected (0.01 sec)

shell> ls -lhi audit.log*
17119248 -rw-r----- 1 agustin.gallego percona 90K Jun 2 15:53 audit.log
17119250 -rw-r----- 1 agustin.gallego percona 1.6M Jun 2 15:53 audit.log.1

# The logs were correctly rotated, and audit.log is being used (increasing in size)

shell> ls -lhi audit.log*
17119248 -rw-r----- 1 agustin.gallego percona 625K Jun 2 15:53 audit.log
17119250 -rw-r----- 1 agustin.gallego percona 1.6M Jun 2 15:53 audit.log.1

Step #3:

Before the audit.log reaches audit_log_rotate_on_size, manually flush the audit log again, and audit.log.1 will be used, instead:

mysql [localhost] {msandbox} ((none)) > SET GLOBAL audit_log_flush=1;
Query OK, 0 rows affected (0.01 sec)

shell> ls -lhi audit.log*
17119248 -rw-r----- 1 agustin.gallego percona 703K Jun 2 15:53 audit.log
17119250 -rw-r----- 1 agustin.gallego percona 2.0M Jun 2 15:53 audit.log.1

shell> ls -lhi audit.log*
17119248 -rw-r----- 1 agustin.gallego percona 703K Jun 2 15:53 audit.log
17119250 -rw-r----- 1 agustin.gallego percona 2.4M Jun 2 15:53 audit.log.1

# The logs are incorrectly rotated, and audit.log.1 is being used (incrementing in size)

As a final note, additional manual flushing commands will not work until audit.log.1 reaches audit_log_rotate_on_size and is automatically rotated (and correctly using audit.log again).

How to fix:

Make the functionality consistent, so that only audit.log is written to, and the files are correctly rotated. This bug leaves the audit logs inconsistent since audit.log.1 will have statements for before and after statements found in audit.log.

[Shahriyar Rzayev (rzayev-sehriyar)]

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