This post was originally published on this site
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
