[PS-4950] Invalid audit log file size when audit_log_rotations is changed during runtime - Percona JIRA

XML

Word

Printable

Details

Type: Bug
Status: Done
Priority: Medium
Resolution: Fixed
Affects Version/s: 5.6.x
Fix Version/s: 5.7.24-26, 8.0.13-3, 5.6.43-84.3
Component/s: None
Labels:
- audit-log-plugin

Description

Setup Percona Server 5.6 (tested on 5.6.41-84.1) with audit log plugin enabled:

audit_log_policy=ALL
audit_log_format=JSON
audit_log_rotate_on_size=32M
audit_log_rotations=25

Run an insert to a table and check that audit log files are created. Stop the insert at some point where there are less than the number of audit_log_rotations created

[root@auditnode1 ~]# ls -lh /var/lib/mysql/
total 493M
-rw-r--r-- 1 root root 650 Sep 28 03:14 RPM_UPGRADE_HISTORY
-rw-r--r-- 1 mysql mysql 650 Sep 28 03:14 RPM_UPGRADE_MARKER-LAST
-rw-rw---- 1 mysql mysql 163K Oct 19 04:53 audit.log
-rw-rw---- 1 mysql mysql 33M Oct 19 04:53 audit.log.01
-rw-rw---- 1 mysql mysql 33M Oct 19 04:50 audit.log.02
-rw-rw---- 1 mysql mysql 33M Oct 19 04:47 audit.log.03
-rw-rw---- 1 mysql mysql 33M Oct 19 04:44 audit.log.04
-rw-rw---- 1 mysql mysql 33M Oct 19 04:41 audit.log.05
-rw-rw---- 1 mysql mysql 33M Oct 19 04:37 audit.log.06
-rw-rw---- 1 mysql mysql 33M Oct 19 04:34 audit.log.07
-rw-rw---- 1 mysql mysql 33M Oct 19 04:31 audit.log.08
-rw-rw---- 1 mysql mysql 33M Oct 19 04:28 audit.log.09
-rw-rw---- 1 mysql mysql 5 Oct 19 04:24 auditnode1.pid
-rw-rw---- 1 mysql mysql 56 Aug 3 00:09 auto.cnf
-rw-rw---- 1 mysql mysql 48M Oct 19 04:53 ib_logfile0
-rw-rw---- 1 mysql mysql 48M Oct 19 04:53 ib_logfile1
-rw-rw---- 1 mysql mysql 76M Oct 19 04:53 ibdata1
drwx------ 2 mysql mysql 4.0K Aug 3 00:09 mysql
srwxrwxrwx 1 mysql mysql 0 Oct 19 04:24 mysql.sock
drwx------ 2 mysql mysql 4.0K Aug 3 00:09 performance_schema
drwx------ 2 mysql mysql 0 Oct 19 04:25 test
drwx------ 2 mysql mysql 58 Oct 18 05:03 test1

In my case, I stopped with audit.log.{01-09}.

Now run

audit_log_rotations=50;

mysql> show global variables like '%rotat%';
+--------------------------+----------+
| Variable_name | Value |
+--------------------------+----------+
| audit_log_rotate_on_size | 33554432 |
| audit_log_rotations | 25 |
+--------------------------+----------+
2 rows in set (0.00 sec)
mysql> set global audit_log_rotations=50;
Query OK, 0 rows affected (0.00 sec)
mysql> show global variables like '%rotat%';
+--------------------------+----------+
| Variable_name | Value |
+--------------------------+----------+
| audit_log_rotate_on_size | 33554432 |
| audit_log_rotations | 50 |
+--------------------------+----------+
2 rows in set (0.00 sec)

Continue inserting to the database and notice it creates the files audit.log.{10-25} instantly:

[root@auditnode1 ~]# ls -lh /var/lib/mysql
total 175M
-rw-r--r-- 1 root root 650 Sep 28 03:14 RPM_UPGRADE_HISTORY
-rw-r--r-- 1 mysql mysql 650 Sep 28 03:14 RPM_UPGRADE_MARKER-LAST
-rw-rw---- 1 mysql mysql 0 Oct 19 04:57 audit.log
-rw-rw---- 1 mysql mysql 2.4K Oct 19 04:57 audit.log.01
-rw-rw---- 1 mysql mysql 1.8K Oct 19 04:57 audit.log.02
-rw-rw---- 1 mysql mysql 1.9K Oct 19 04:57 audit.log.03
-rw-rw---- 1 mysql mysql 2.4K Oct 19 04:57 audit.log.04
-rw-rw---- 1 mysql mysql 2.0K Oct 19 04:57 audit.log.05
-rw-rw---- 1 mysql mysql 2.2K Oct 19 04:57 audit.log.06
-rw-rw---- 1 mysql mysql 1.9K Oct 19 04:57 audit.log.07
-rw-rw---- 1 mysql mysql 2.4K Oct 19 04:57 audit.log.08
-rw-rw---- 1 mysql mysql 1.8K Oct 19 04:57 audit.log.09
-rw-rw---- 1 mysql mysql 678 Oct 19 04:57 audit.log.10
-rw-rw---- 1 mysql mysql 175K Oct 19 04:57 audit.log.11
-rw-rw---- 1 mysql mysql 175K Oct 19 04:57 audit.log.12
-rw-rw---- 1 mysql mysql 186K Oct 19 04:57 audit.log.13
-rw-rw---- 1 mysql mysql 662 Oct 19 04:57 audit.log.14
-rw-rw---- 1 mysql mysql 173K Oct 19 04:57 audit.log.15
-rw-rw---- 1 mysql mysql 176K Oct 19 04:57 audit.log.16
-rw-rw---- 1 mysql mysql 180K Oct 19 04:57 audit.log.17
-rw-rw---- 1 mysql mysql 176K Oct 19 04:57 audit.log.18
-rw-rw---- 1 mysql mysql 175K Oct 19 04:57 audit.log.19
-rw-rw---- 1 mysql mysql 683 Oct 19 04:57 audit.log.20
-rw-rw---- 1 mysql mysql 184K Oct 19 04:57 audit.log.21
-rw-rw---- 1 mysql mysql 661 Oct 19 04:57 audit.log.22
-rw-rw---- 1 mysql mysql 173K Oct 19 04:57 audit.log.23
-rw-rw---- 1 mysql mysql 540 Oct 19 04:57 audit.log.24
-rw-rw---- 1 mysql mysql 176K Oct 19 04:57 audit.log.25
-rw-rw---- 1 mysql mysql 5 Oct 19 04:24 auditnode1.pid
-rw-rw---- 1 mysql mysql 56 Aug 3 00:09 auto.cnf
-rw-rw---- 1 mysql mysql 48M Oct 19 04:53 ib_logfile0
-rw-rw---- 1 mysql mysql 48M Oct 19 04:57 ib_logfile1
-rw-rw---- 1 mysql mysql 76M Oct 19 04:53 ibdata1
drwx------ 2 mysql mysql 4.0K Aug 3 00:09 mysql
srwxrwxrwx 1 mysql mysql 0 Oct 19 04:24 mysql.sock
drwx------ 2 mysql mysql 4.0K Aug 3 00:09 performance_schema
drwx------ 2 mysql mysql 0 Oct 19 04:25 test
drwx------ 2 mysql mysql 58 Oct 18 05:03 test1

And the file size keeps on changing:

[root@auditnode1 ~]# ls -lh /var/lib/mysql
total 175M
-rw-r--r-- 1 root root 650 Sep 28 03:14 RPM_UPGRADE_HISTORY
-rw-r--r-- 1 mysql mysql 650 Sep 28 03:14 RPM_UPGRADE_MARKER-LAST
-rw-rw---- 1 mysql mysql 0 Oct 19 04:58 audit.log
-rw-rw---- 1 mysql mysql 173K Oct 19 04:58 audit.log.01
-rw-rw---- 1 mysql mysql 283 Oct 19 04:58 audit.log.02
-rw-rw---- 1 mysql mysql 174K Oct 19 04:58 audit.log.03
-rw-rw---- 1 mysql mysql 679 Oct 19 04:58 audit.log.04
-rw-rw---- 1 mysql mysql 178K Oct 19 04:58 audit.log.05
-rw-rw---- 1 mysql mysql 283 Oct 19 04:58 audit.log.06
-rw-rw---- 1 mysql mysql 257 Oct 19 04:58 audit.log.07
-rw-rw---- 1 mysql mysql 677 Oct 19 04:58 audit.log.08
-rw-rw---- 1 mysql mysql 175K Oct 19 04:58 audit.log.09
-rw-rw---- 1 mysql mysql 540 Oct 19 04:58 audit.log.10
-rw-rw---- 1 mysql mysql 169K Oct 19 04:58 audit.log.11
-rw-rw---- 1 mysql mysql 540 Oct 19 04:58 audit.log.12
-rw-rw---- 1 mysql mysql 180K Oct 19 04:58 audit.log.13
-rw-rw---- 1 mysql mysql 177K Oct 19 04:58 audit.log.14
-rw-rw---- 1 mysql mysql 669 Oct 19 04:58 audit.log.15
-rw-rw---- 1 mysql mysql 168K Oct 19 04:58 audit.log.16
-rw-rw---- 1 mysql mysql 680 Oct 19 04:58 audit.log.17
-rw-rw---- 1 mysql mysql 181K Oct 19 04:58 audit.log.18
-rw-rw---- 1 mysql mysql 540 Oct 19 04:58 audit.log.19
-rw-rw---- 1 mysql mysql 173K Oct 19 04:58 audit.log.20
-rw-rw---- 1 mysql mysql 254 Oct 19 04:58 audit.log.21
-rw-rw---- 1 mysql mysql 398 Oct 19 04:58 audit.log.22
-rw-rw---- 1 mysql mysql 181K Oct 19 04:58 audit.log.23
-rw-rw---- 1 mysql mysql 673 Oct 19 04:58 audit.log.24
-rw-rw---- 1 mysql mysql 196K Oct 19 04:58 audit.log.25
-rw-rw---- 1 mysql mysql 5 Oct 19 04:24 auditnode1.pid
-rw-rw---- 1 mysql mysql 56 Aug 3 00:09 auto.cnf
-rw-rw---- 1 mysql mysql 48M Oct 19 04:53 ib_logfile0
-rw-rw---- 1 mysql mysql 48M Oct 19 04:58 ib_logfile1
-rw-rw---- 1 mysql mysql 76M Oct 19 04:53 ibdata1
drwx------ 2 mysql mysql 4.0K Aug 3 00:09 mysql
srwxrwxrwx 1 mysql mysql 0 Oct 19 04:24 mysql.sock
drwx------ 2 mysql mysql 4.0K Aug 3 00:09 performance_schema
drwx------ 2 mysql mysql 0 Oct 19 04:25 test
drwx------ 2 mysql mysql 58 Oct 18 05:03 test1

Moreover, the manual states that audit_log_rotations is non-dynamic but from the above output we can see it is dynamic.

https://www.percona.com/doc/percona-server/LATEST/management/audit_log_plugin.html#audit_log_rotations

Attachments

Issue Links

is duplicated by

PS-1027 LP #1637594: Audit Plugin allows static variable change at runtime

Done

PS-4963 audit_log_rotations is meant to not be dynamic, but can be changed with set global

Done

relates to

PS-5667 audit_log plugin not rotating logs

Done

PS-4963 audit_log_rotations is meant to not be dynamic, but can be changed with set global

Done

Activity

People

Assignee:: Sergei Glushchenko (Inactive)

Reporter:: Jericho Rivera (Inactive)

Votes:: 0 Vote for this issue

Watchers:: 1 Start watching this issue

Dates

Created:: 19/Oct/18 5:13 AM

Updated:: 31/May/19 10:18 AM

Resolved:: 27/Nov/18 10:47 AM

Time Tracking

Estimated:

Not Specified

Remaining:

Logged: