DBMS_AUDIT_MGMT.CLEAN_AUDIT_TRAIL not working on 12c? Here’s why…

It is bad to realize, after a few years, that my customer’s Audit Cleanup procedures are not working properly for every database…

NOTE: The post is based on standard audit, not unified audit.

My customer developed a quite nice procedure for database housekeeping (including diag dest, OS audit trail, recyclebin, DB audit…)

But after some performance problems, I have come across the infamous sql_id 4ztz048yfq32s:

SELECT TO_CHAR(current_timestamp AT TIME ZONE 'GMT', 'YYYY-MM-DD HH24:MI:SS TZD') AS curr_timestamp, COUNT(username) AS failed_count, TO_CHAR(MIN(timestamp), 'yyyy-mm-dd hh24:mi:ss') AS first_occur_time, TO_CHAR(MAX(timestamp), 'yyyy-mm-dd hh24:mi:ss') AS last_occur_time
FROM sys.dba_audit_session
WHERE returncode != 0 AND timestamp >= current_timestamp - TO_DSINTERVAL('0 0:30:00')

This SQL comes from the “Failed Logon Attempts” metric in Enterprise Manager.

I’ve checked the specific database, and the table SYS.AUD$ was containing way too many rows, dating before our purge time:

SQL> select min(timestamp) from dba_audit_session;

MIN(TIMESTAMP)
-------------------
04.02.2017 07:01:20

SQL>  select dbid, count(*) from aud$ group by dbid;

      DBID   COUNT(*)
---------- ----------
2416611527   35846477

The cleanup procedure does basically this:

SQL> begin
  2  dbms_audit_mgmt.set_last_archive_timestamp(audit_trail_type  => DBMS_AUDIT_MGMT.AUDIT_TRAIL_AUD_STD
  3                          ,last_archive_time => SYSTIMESTAMP-31);
  4  end;
  5  /

PL/SQL procedure successfully completed.

SQL> set timing on
SQL> begin
  2  dbms_audit_mgmt.clean_audit_trail(
  3    audit_trail_type => sys.dbms_audit_mgmt.AUDIT_TRAIL_AUD_STD,
  4    use_last_arch_timestamp => TRUE);
  5  end;
  6  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:38.34

But despite a retention window of 31 days, the rows are still there:

SQL> select min(timestamp) from dba_audit_session;

MIN(TIMESTAMP)
-------------------
04.02.2017 07:01:20

Elapsed: 00:00:29.06

(today is 27.04.2018, so the oldest records are more than 1 year old)

I’ve checked with ASH, the actual delete statement executed by the clean_audit_trail procedure is:

DELETE FROM SYS.AUD$ WHERE DBID = 2416611527 AND NTIMESTAMP# < to_timestamp('2017-02-04 05:01:10', 'YYYY-MM-DD HH24:MI:SS.FF') AND ROWNUM <= 140724603463440

So, the DBID clause is OK, but the NTIMESTAMP# clause is  not!

Why?

Long story long (hint, it’s a bug: 19958239)
Update 30.05.2018 the solution is explained in this Doc: 2068066.1, thanks John)

The cleanup metadata is stored into the view DBA_AUDIT_MGMT_LAST_ARCH_TS. Its structure in 11g was:

SQL> desc dba_audit_mgmt_last_arch_ts
 Name                                      Null?    Type
 ----------------------------------------- -------- ----------------------------
 AUDIT_TRAIL                                        VARCHAR2(20)
 RAC_INSTANCE                              NOT NULL NUMBER
 LAST_ARCHIVE_TS                                    TIMESTAMP(6) WITH TIME ZONE

But in 12c, there are 2 new columns:

SQL> desc dba_audit_mgmt_last_arch_ts
 Name                                  Null?    Type
 ------------------------------------- -------- ----------------------------
 AUDIT_TRAIL                                    VARCHAR2(20)
 RAC_INSTANCE                          NOT NULL NUMBER
 LAST_ARCHIVE_TS                                TIMESTAMP(6) WITH TIME ZONE
 DATABASE_ID                           NOT NULL NUMBER
 CONTAINER_GUID                        NOT NULL VARCHAR2(33)

When the database is upgraded from 11g to 12c, the two new columns are set to “0” by default.

SQL> select * from dba_audit_mgmt_last_arch_ts;

AUDIT_TRAIL                 RAC_INSTANCE LAST_ARCHIVE_TS                      DATABASE_ID CONTAINER_GUID
--------------------------- ------------ ------------------------------------ ----------- --------------------------------
STANDARD AUDIT TRAIL                   0 04-FEB-17 05.01.10.000000 AM +00:00            0 00000000000000000000000000000000
OS AUDIT TRAIL                         1 04-FEB-17 05.01.15.000000 AM +02:00            0 00000000000000000000000000000000

But when the procedure DBMS_AUDIT_MGMT.SET_LAST_ARCHIVE_TIMESTAMP is executed, the actual dbid is used, and new lines appear:

SQL> select * from dba_audit_mgmt_last_arch_ts;

AUDIT_TRAIL                 RAC_INSTANCE LAST_ARCHIVE_TS                      DATABASE_ID CONTAINER_GUID
--------------------------- ------------ ------------------------------------ ----------- --------------------------------
STANDARD AUDIT TRAIL                   0 04-FEB-17 05.01.10.000000 AM +00:00            0 00000000000000000000000000000000
OS AUDIT TRAIL                         1 04-FEB-17 05.01.15.000000 AM +02:00            0 00000000000000000000000000000000
STANDARD AUDIT TRAIL                   0 27-MAR-18 12.29.55.000000 PM +00:00   2416611527 4A2962517EF2316FE0532296780AE383
OS AUDIT TRAIL                         1 27-MAR-18 12.20.06.000000 PM +02:00   2416611527 4A2962517EF2316FE0532296780AE383

It is clear now that the DELETE statement is not constructed properly. It should get the LAST_ARCHIVE_TS of the actual DBID being purged… but it takes the other one.

According to my tests, it does not use neither the correct timestamp for the dbid, nor get the oldest timestamp: it uses instead the timestamp of the first record found by the clause “WHERE AUDIT_TRAIL=’STANDARD AUDIT TRAIL'”. It depends on the physical location of the row in the table! Clearly a big mess… (PS, not sure 100%, but this is what I suppose)

So, I have tried to modify the archive time for DBID 0:

SQL> begin
  2  dbms_audit_mgmt.set_last_archive_timestamp(audit_trail_type  => DBMS_AUDIT_MGMT.AUDIT_TRAIL_AUD_STD
  3                          ,last_archive_time => SYSTIMESTAMP-31
  4                          ,database_id => 0
  5                          ,container_guid => '00000000000000000000000000000000');
  6  end;
  7
  8  /

PL/SQL procedure successfully completed.

SQL> select database_id, audit_trail, last_archive_ts from dba_audit_mgmt_last_arch_ts;

DATABASE_ID AUDIT_TRAIL                   LAST_ARCHIVE_TS
----------- ----------------------------- ----------------------------------------
          0 STANDARD AUDIT TRAIL          27-MAR-18 12.37.22.000000 PM +00:00
          0 OS AUDIT TRAIL                04-FEB-17 05.01.15.000000 AM +02:00
 2416611527 STANDARD AUDIT TRAIL          27-MAR-18 12.29.55.000000 PM +00:00
 2416611527 OS AUDIT TRAIL                27-MAR-18 12.20.06.000000 PM +02:00

Trying to execute the cleanup again, now leads to a better timestamp:

DELETE FROM SYS.AUD$ WHERE DBID = 2416611527 AND NTIMESTAMP# < to_timestamp('2018-03-27 12:37:22', 'YYYY-MM-DD HH24:MI:SS.FF') AND ROWNUM <= 140724603463440

I have then tried to play a little bit with the DBA_AUDIT_MGMT_LAST_ARCH_TS view (and the underlying table DAM_LAST_ARCH_TS$).

First, I’ve faked the DBID:

SQL> update dba_audit_mgmt_last_arch_ts set database_id=2416611526 where database_id=0;

2 rows updated.

SQL> commit;

Commit complete.
SQL> select database_id, audit_trail, last_archive_ts from DBA_AUDIT_MGMT_LAST_ARCH_TS;

DATABASE_ID AUDIT_TRAIL                                                  LAST_ARCHIVE_TS
----------- ------------------------------------------------------------ ---------------------------------------------------------------------------
 2416611526 STANDARD AUDIT TRAIL                                         27-MAR-18 12.37.22.000000 PM +00:00
 2416611526 OS AUDIT TRAIL                                               04-FEB-17 05.01.15.000000 AM +02:00
 2416611527 STANDARD AUDIT TRAIL                                         27-MAR-18 12.29.55.000000 PM +00:00
 2416611527 OS AUDIT TRAIL                                               27-MAR-18 12.20.06.000000 PM +02:00

Then, I have tried to increase the retention timestamp (500 days):

SQL> begin
  2  dbms_audit_mgmt.set_last_archive_timestamp(audit_trail_type  => DBMS_AUDIT_MGMT.AUDIT_TRAIL_AUD_STD
  3                          ,last_archive_time => SYSTIMESTAMP-500
  4                          ,database_id => 2416611526
  5                          ,container_guid => '00000000000000000000000000000000');
  6  end;
  7  /

PL/SQL procedure successfully completed.

SQL> select database_id, audit_trail, last_archive_ts from dba_audit_mgmt_last_arch_ts;

DATABASE_ID AUDIT_TRAIL                                                  LAST_ARCHIVE_TS
----------- ------------------------------------------------------------ ---------------------------------------------------------------------------
 2416611526 STANDARD AUDIT TRAIL                                         13-DEC-16 12.48.23.000000 PM +00:00
 2416611526 OS AUDIT TRAIL                                               04-FEB-17 05.01.15.000000 AM +02:00
 2416611527 STANDARD AUDIT TRAIL                                         27-MAR-18 12.29.55.000000 PM +00:00
 2416611527 OS AUDIT TRAIL                                               27-MAR-18 12.20.06.000000 PM +02:00

Finally, I have tried to purge the audit trail with both DBIDs:

SQL> begin
  2  dbms_audit_mgmt.clean_audit_trail(
  3    audit_trail_type => sys.dbms_audit_mgmt.AUDIT_TRAIL_AUD_STD,
  4    database_id =>   2416611526,
  5    use_last_arch_timestamp => TRUE);
  6  end;
  7  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:45.89

SQL> begin
  2   dbms_audit_mgmt.clean_audit_trail(
  3    audit_trail_type => sys.dbms_audit_mgmt.AUDIT_TRAIL_AUD_STD,
  4    database_id =>   2416611527,
  5     use_last_arch_timestamp => TRUE);
  6  end
  7  ;
  8  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:34.72

As I expected, in both cases the the cleanup generated the delete with the timestamp of the fake DBID:

-- clean audit trail for dbid 2416611526 
DELETE FROM SYS.AUD$ WHERE DBID = 2416611526 AND NTIMESTAMP# < to_timestamp('2016-12-13 12:48:23', 'YYYY-MM-DD HH24:MI:SS.FF') AND ROWNUM <= 140724603463440

-- clean audit trail for dbid 2416611527
DELETE FROM SYS.AUD$ WHERE DBID = 2416611527 AND NTIMESTAMP# < to_timestamp('2016-12-13 12:48:23', 'YYYY-MM-DD HH24:MI:SS.FF') AND ROWNUM <= 140724603463440

Is it possible to delete the unwanted records from the view DBA_AUDIT_MGMT_LAST_ARCH_TS?

Not only is possible, but I recommend it:

SQL> delete from dba_audit_mgmt_last_arch_ts where database_id=2416611526;

2 rows deleted.

SQL> commit;

Commit complete.

SQL>

Afterwards, the timestamp in the where condition is correct and remains correct after subsequent executions of DBMS_AUDIT_MGMT.SET_LAST_ARCHIVE_TIMESTAMP.

Conclusions, IMPORTANT FOR THE DATABASE OPERATIONS:

The upgrade causes the unwanted lines with DBID=0 in the DBA_AUDIT_MGMT_LAST_ARCH_TS view.

Moreover, any duplicate changes the DBID: any subsequent execution of DBMS_AUDIT_MGMT.SET_LAST_ARCHIVE_TIMESTAMP in the duplicated database will lead to additional lines in the view.

This is what I plan to do now:

  • Whenever I upgrade from 11g to 12c, cleanup the data from DBA_AUDIT_MGMT_LAST_ARCH_TS and schedule the cleanup for DBID 0 as well
  • Whenever I duplicate a database, I execute a DELETE (without clauses) from DBA_AUDIT_MGMT_LAST_ARCH_T and a truncate of the table SYS.AUD$ (it is a duplicate, after all!)

HTH

关注dbDao.com的新浪微博

扫码加入微信Oracle小密圈,了解Oracle最新技术下载分享资源

TEL/電話+86 13764045638
Email service@parnassusdata.com
QQ 47079569