{"id":1726,"date":"2018-04-27T15:37:16","date_gmt":"2018-04-27T13:37:16","guid":{"rendered":"http:\/\/www.ludovicocaldara.net\/dba\/?p=1726"},"modified":"2020-08-18T16:10:35","modified_gmt":"2020-08-18T14:10:35","slug":"clean_audit_trail-not-working-12c","status":"publish","type":"post","link":"https:\/\/www.ludovicocaldara.net\/dba\/clean_audit_trail-not-working-12c\/","title":{"rendered":"DBMS_AUDIT_MGMT.CLEAN_AUDIT_TRAIL not working on 12c? Here’s why…"},"content":{"rendered":"

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

NOTE: The post is based on standard audit, not unified audit.<\/strong><\/p>\n

My customer developed a quite nice procedure for database housekeeping (including diag dest, OS audit trail, recyclebin, DB audit…)<\/p>\n

But after some performance problems, I have come across the infamous sql_id 4ztz048yfq32s:<\/p>\n

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\r\nFROM sys.dba_audit_session\r\nWHERE returncode != 0 AND timestamp >= current_timestamp - TO_DSINTERVAL('0 0:30:00')<\/pre>\n
This SQL comes from the “Failed Logon Attempts” metric in Enterprise Manager.<\/p>\n
I’ve checked the specific database, and the table SYS.AUD$ was containing way too many rows, dating before our purge time:<\/p>\n
SQL> select min(timestamp) from dba_audit_session;\r\n\r\nMIN(TIMESTAMP)\r\n-------------------\r\n04.02.2017 07:01:20\r\n\r\nSQL>  select dbid, count(*) from aud$ group by dbid;\r\n\r\n      DBID   COUNT(*)\r\n---------- ----------\r\n2416611527   35846477<\/pre>\n
The cleanup procedure does basically this:<\/p>\n
SQL> begin\r\n  2  dbms_audit_mgmt.set_last_archive_timestamp(audit_trail_type  => DBMS_AUDIT_MGMT.AUDIT_TRAIL_AUD_STD\r\n  3                          ,last_archive_time => SYSTIMESTAMP-31);\r\n  4  end;\r\n  5  \/\r\n\r\nPL\/SQL procedure successfully completed.\r\n\r\nSQL> set timing on\r\nSQL> begin\r\n  2  dbms_audit_mgmt.clean_audit_trail(\r\n  3    audit_trail_type => sys.dbms_audit_mgmt.AUDIT_TRAIL_AUD_STD,\r\n  4    use_last_arch_timestamp => TRUE);\r\n  5  end;\r\n  6  \/\r\n\r\nPL\/SQL procedure successfully completed.\r\n\r\nElapsed: 00:00:38.34<\/pre>\n
But despite a retention window of 31 days, the rows are still there:<\/p>\n
SQL> select min(timestamp) from dba_audit_session;\r\n\r\nMIN(TIMESTAMP)\r\n-------------------\r\n04.02.2017 07:01:20\r\n\r\nElapsed: 00:00:29.06<\/pre>\n
(today is 27.04.2018, so the oldest records are more than 1 year old)<\/p>\n
I’ve checked with ASH, the actual delete statement executed by the clean_audit_trail procedure is:<\/p>\n
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<\/pre>\n
So, the DBID clause is OK, but the NTIMESTAMP# clause is\u00a0 not!<\/p>\n
Why?<\/p>\n
Long story long (hint, it’s a bug: 19958239)
\n<\/span><\/strong>Update 30.05.2018 the solution is explained <\/span>in this Doc: 2068066<\/span>.1, thanks John)<\/span><\/span>
\n<\/strong><\/p>\n
The cleanup metadata is stored into the view DBA_AUDIT_MGMT_LAST_ARCH_TS. Its structure in 11g was:<\/p>\n
SQL> desc dba_audit_mgmt_last_arch_ts\r\n Name                                      Null?    Type\r\n ----------------------------------------- -------- ----------------------------\r\n AUDIT_TRAIL                                        VARCHAR2(20)\r\n RAC_INSTANCE                              NOT NULL NUMBER\r\n LAST_ARCHIVE_TS                                    TIMESTAMP(6) WITH TIME ZONE\r\n<\/pre>\n
But in 12c, there are 2 new columns:<\/p>\n
SQL> desc dba_audit_mgmt_last_arch_ts\r\n Name                                  Null?    Type\r\n ------------------------------------- -------- ----------------------------\r\n AUDIT_TRAIL                                    VARCHAR2(20)\r\n RAC_INSTANCE                          NOT NULL NUMBER\r\n LAST_ARCHIVE_TS                                TIMESTAMP(6) WITH TIME ZONE\r\n DATABASE_ID                           NOT NULL NUMBER\r\n CONTAINER_GUID                        NOT NULL VARCHAR2(33)\r\n<\/pre>\n
When the database is upgraded from 11g to 12c, the two new columns are set to “0” by default.<\/p>\n
SQL> select * from dba_audit_mgmt_last_arch_ts;\r\n\r\nAUDIT_TRAIL                 RAC_INSTANCE LAST_ARCHIVE_TS                      DATABASE_ID CONTAINER_GUID\r\n--------------------------- ------------ ------------------------------------ ----------- --------------------------------\r\nSTANDARD AUDIT TRAIL                   0 04-FEB-17 05.01.10.000000 AM +00:00            0 00000000000000000000000000000000\r\nOS AUDIT TRAIL                         1 04-FEB-17 05.01.15.000000 AM +02:00            0 00000000000000000000000000000000<\/pre>\n
But when the procedure DBMS_AUDIT_MGMT.SET_LAST_ARCHIVE_TIMESTAMP is executed, the actual dbid is used, and new lines appear:<\/p>\n
SQL> select * from dba_audit_mgmt_last_arch_ts;\r\n\r\nAUDIT_TRAIL                 RAC_INSTANCE LAST_ARCHIVE_TS                      DATABASE_ID CONTAINER_GUID\r\n--------------------------- ------------ ------------------------------------ ----------- --------------------------------\r\nSTANDARD AUDIT TRAIL                   0 04-FEB-17 05.01.10.000000 AM +00:00            0 00000000000000000000000000000000\r\nOS AUDIT TRAIL                         1 04-FEB-17 05.01.15.000000 AM +02:00            0 00000000000000000000000000000000\r\nSTANDARD AUDIT TRAIL                   0 27-MAR-18 12.29.55.000000 PM +00:00   2416611527 4A2962517EF2316FE0532296780AE383\r\nOS AUDIT TRAIL                         1 27-MAR-18 12.20.06.000000 PM +02:00   2416611527 4A2962517EF2316FE0532296780AE383<\/pre>\n
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.<\/p>\n
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)<\/p>\n
So, I have tried to modify the archive time for DBID 0:<\/p>\n
SQL> begin\r\n  2  dbms_audit_mgmt.set_last_archive_timestamp(audit_trail_type  => DBMS_AUDIT_MGMT.AUDIT_TRAIL_AUD_STD\r\n  3                          ,last_archive_time => SYSTIMESTAMP-31\r\n  4                          ,database_id => 0\r\n  5                          ,container_guid => '00000000000000000000000000000000');\r\n  6  end;\r\n  7\r\n  8  \/\r\n\r\nPL\/SQL procedure successfully completed.\r\n\r\nSQL> select database_id, audit_trail, last_archive_ts from dba_audit_mgmt_last_arch_ts;\r\n\r\nDATABASE_ID AUDIT_TRAIL\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 LAST_ARCHIVE_TS\r\n----------- ----------------------------- ----------------------------------------\r\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0 STANDARD AUDIT TRAIL\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 27-MAR-18 12.37.22.000000 PM +00:00\r\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0 OS AUDIT TRAIL\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 04-FEB-17 05.01.15.000000 AM +02:00\r\n\u00a02416611527 STANDARD AUDIT TRAIL\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 27-MAR-18 12.29.55.000000 PM +00:00\r\n\u00a02416611527 OS AUDIT TRAIL\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 27-MAR-18 12.20.06.000000 PM +02:00<\/pre>\n
Trying to execute the cleanup again, now leads to a better timestamp:<\/p>\n
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<\/pre>\n
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$).<\/p>\n
First, I’ve faked the DBID:<\/p>\n
SQL> update dba_audit_mgmt_last_arch_ts set database_id=2416611526 where database_id=0;\r\n\r\n2 rows updated.\r\n\r\nSQL> commit;\r\n\r\nCommit complete.\r\nSQL> select database_id, audit_trail, last_archive_ts from DBA_AUDIT_MGMT_LAST_ARCH_TS;\r\n\r\nDATABASE_ID AUDIT_TRAIL                                                  LAST_ARCHIVE_TS\r\n----------- ------------------------------------------------------------ ---------------------------------------------------------------------------\r\n 2416611526 STANDARD AUDIT TRAIL                                         27-MAR-18 12.37.22.000000 PM +00:00\r\n 2416611526 OS AUDIT TRAIL                                               04-FEB-17 05.01.15.000000 AM +02:00\r\n 2416611527 STANDARD AUDIT TRAIL                                         27-MAR-18 12.29.55.000000 PM +00:00\r\n 2416611527 OS AUDIT TRAIL                                               27-MAR-18 12.20.06.000000 PM +02:00\r\n<\/pre>\n
Then, I have tried to increase the retention timestamp (500 days):<\/p>\n
SQL> begin\r\n  2  dbms_audit_mgmt.set_last_archive_timestamp(audit_trail_type  => DBMS_AUDIT_MGMT.AUDIT_TRAIL_AUD_STD\r\n  3                          ,last_archive_time => SYSTIMESTAMP-500\r\n  4                          ,database_id => 2416611526\r\n  5                          ,container_guid => '00000000000000000000000000000000');\r\n  6  end;\r\n  7  \/\r\n\r\nPL\/SQL procedure successfully completed.\r\n\r\nSQL> select database_id, audit_trail, last_archive_ts from dba_audit_mgmt_last_arch_ts;\r\n\r\nDATABASE_ID AUDIT_TRAIL                                                  LAST_ARCHIVE_TS\r\n----------- ------------------------------------------------------------ ---------------------------------------------------------------------------\r\n 2416611526 STANDARD AUDIT TRAIL                                         13-DEC-16 12.48.23.000000 PM +00:00\r\n 2416611526 OS AUDIT TRAIL                                               04-FEB-17 05.01.15.000000 AM +02:00\r\n 2416611527 STANDARD AUDIT TRAIL                                         27-MAR-18 12.29.55.000000 PM +00:00\r\n 2416611527 OS AUDIT TRAIL                                               27-MAR-18 12.20.06.000000 PM +02:00\r\n<\/pre>\n
Finally, I have tried to purge the audit trail with both DBIDs:<\/p>\n
SQL> begin\r\n  2  dbms_audit_mgmt.clean_audit_trail(\r\n  3    audit_trail_type => sys.dbms_audit_mgmt.AUDIT_TRAIL_AUD_STD,\r\n  4    database_id =>   2416611526,\r\n  5    use_last_arch_timestamp => TRUE);\r\n  6  end;\r\n  7  \/\r\n\r\nPL\/SQL procedure successfully completed.\r\n\r\nElapsed: 00:00:45.89\r\n\r\nSQL> begin\r\n  2   dbms_audit_mgmt.clean_audit_trail(\r\n  3    audit_trail_type => sys.dbms_audit_mgmt.AUDIT_TRAIL_AUD_STD,\r\n  4    database_id =>   2416611527,\r\n  5     use_last_arch_timestamp => TRUE);\r\n  6  end\r\n  7  ;\r\n  8  \/\r\n\r\nPL\/SQL procedure successfully completed.\r\n\r\nElapsed: 00:00:34.72<\/pre>\n
As I expected, in both cases the the cleanup generated the delete with the timestamp of the fake DBID:<\/p>\n
-- clean audit trail for dbid 2416611526 \r\nDELETE 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\r\n\r\n-- clean audit trail for dbid 2416611527\r\nDELETE 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\r\n<\/pre>\n
Is it possible to delete the unwanted records from the view DBA_AUDIT_MGMT_LAST_ARCH_TS?<\/strong><\/p>\n
Not only is possible, but I recommend it:<\/p>\n
SQL> delete from dba_audit_mgmt_last_arch_ts where database_id=2416611526;\r\n\r\n2 rows deleted.\r\n\r\nSQL> commit;\r\n\r\nCommit complete.\r\n\r\nSQL><\/pre>\n
Afterwards, the timestamp in the where condition is correct and remains correct after subsequent executions of DBMS_AUDIT_MGMT.SET_LAST_ARCHIVE_TIMESTAMP.<\/p>\n
Conclusions, IMPORTANT FOR THE DATABASE OPERATIONS:<\/strong><\/p>\n
The upgrade causes the unwanted lines with DBID=0 in the DBA_AUDIT_MGMT_LAST_ARCH_TS view.<\/p>\n
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.<\/p>\n
This is what I plan to do now:<\/p>\n