Uploaded image for project: 'Percona Server'
  1. Percona Server
  2. PS-4950

Invalid audit log file size when audit_log_rotations is changed during runtime

    XMLWordPrintable

    Details

      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

          Activity

            People

            • Assignee:
              sergei.glushchenko Sergei Glushchenko
              Reporter:
              jericho.rivera Jericho Rivera
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Time Tracking

                Estimated:
                Original Estimate - Not Specified
                Not Specified
                Remaining:
                Remaining Estimate - 0 minutes
                0m
                Logged:
                Time Spent - 4 hours
                4h