Wednesday, December 4, 2013

Excessive Audit File (*.aud) Generation

Excessive amount of audit file generation was observed in a 11gR2 RAC environment. The audit trail parameter was set to OS and adump directory was getting populated with *.aud files at a rate of 60 per second. Audit files were cleaned out using cron (1298957.1) and schedule frequency wasn't enough to reduce the amount of *.aud file to an acceptable level. With 11gR2 (also available in 10.2.0.5 and 11.1.0.7) it is possible to use DBMS_AUDIT_MGMT to purge audit records including OS audit files (731908.1).
Starting with 11gR1 audit file generation has changed to create a new audit file for new session instead of appending to an existing audit file (1474823.1). This would generate lot of small (in size) audit files and could see burst of audit file generation for 3 tier application when connection pools are initiated. Also by default audit is enable of several actions. These could be found with the scripts on 1019552.6 or 287436.1. Below is the output from running script (1019552.6) on a new 11.2.0.4 RAC DB (only audit trail is changed to OS).
SQL> @tstaudit
Press return to see the audit related parameters...

NAME                 DISPLAY_VALUE
-------------------- --------------------
audit_file_dest      /opt/app/oracle/admin/std11g2/adump

audit_sys_operations FALSE
audit_syslog_level
audit_trail          OS

System auditing options across the system and by user

User name    Proxy name   Audit Option                   SUCCESS    FAILURE
------------ ------------ ------------------------------ ---------- ----------
                          ALTER ANY PROCEDURE            BY ACCESS  BY ACCESS
                          ALTER ANY TABLE                BY ACCESS  BY ACCESS
                          ALTER DATABASE                 BY ACCESS  BY ACCESS
                          ALTER PROFILE                  BY ACCESS  BY ACCESS
                          ALTER SYSTEM                   BY ACCESS  BY ACCESS
                          ALTER USER                     BY ACCESS  BY ACCESS
                          CREATE ANY JOB                 BY ACCESS  BY ACCESS
                          CREATE ANY LIBRARY             BY ACCESS  BY ACCESS
                          CREATE ANY PROCEDURE           BY ACCESS  BY ACCESS
                          CREATE ANY TABLE               BY ACCESS  BY ACCESS
                          CREATE EXTERNAL JOB            BY ACCESS  BY ACCESS
                          CREATE PUBLIC DATABASE LINK    BY ACCESS  BY ACCESS
                          CREATE SESSION                 BY ACCESS  BY ACCESS
                          CREATE USER                    BY ACCESS  BY ACCESS
                          DATABASE LINK                  BY ACCESS  BY ACCESS
                          DIRECTORY                      BY ACCESS  BY ACCESS
                          DROP ANY PROCEDURE             BY ACCESS  BY ACCESS
                          DROP ANY TABLE                 BY ACCESS  BY ACCESS
                          DROP PROFILE                   BY ACCESS  BY ACCESS
                          DROP USER                      BY ACCESS  BY ACCESS
                          EXEMPT ACCESS POLICY           BY ACCESS  BY ACCESS
                          GRANT ANY OBJECT PRIVILEGE     BY ACCESS  BY ACCESS
                          GRANT ANY PRIVILEGE            BY ACCESS  BY ACCESS
                          GRANT ANY ROLE                 BY ACCESS  BY ACCESS
                          PROFILE                        BY ACCESS  BY ACCESS
                          PUBLIC SYNONYM                 BY ACCESS  BY ACCESS
                          ROLE                           BY ACCESS  BY ACCESS
                          SYSTEM AUDIT                   BY ACCESS  BY ACCESS
                          SYSTEM GRANT                   BY ACCESS  BY ACCESS

29 rows selected.

Press return to see auditing options on all objects...

no rows selected
Press return to see audit trail... Note that the query returns the audit data for the last day only

no rows selected
Press return to see system privileges audited across the system and by user...
As seen from above output one of the audit option is "CREATE SESSION". As changing audit trail requires a restart of the database (RAC allows rolling restarts) it was decided to remove the audit on create session. This reduced the amount of audit file generated but still could see burst of audit files being generated every 5 second. Having examined the audit file it was now clear no audit files were generated for non sys users after removing audit on create session. Only audit files now generated are for sys users and only had following content on them
Thu Nov 28 14:32:12 2013 +01:00
LENGTH : '155'
ACTION :[7] 'CONNECT'
DATABASE USER:[1] '/'
PRIVILEGE :[6] 'SYSDBA'
CLIENT USER:[6] 'oracle'
CLIENT TERMINAL:[0] ''
STATUS:[1] '0'
DBID:[10] '2765679112'



Audit for various sys user operations are created by default irrespective of the configuration setting (308066.1). Audit files could also be generated by grid control agent (1196323.1) which wasn't applicable in this case as there was no grid control or agent running. Another possible cause is due to the resource health check by the grid infrastructure (1378881.1). Resource check interval was set to 1 second and if this had been the cause the audit file generation frequency would have been every 1 second instead of every 5 second. So this wasn't the cause either. Metalink note 1171314.1 list possible causes for excessive audit file generation and classify them as expected behavior, due to audit setting or due to bug but it still didn't provide any help in diagnosing the cause of this audit file generation.
There was no application or cron jobs that were executed on the OS as sys user. So it was decided to check where the sys connections originating from.
SQL>  select inst_id,sid,serial#,program,machine,USERNAME ,sql_id from gv$session where username='SYS' order by 1;

   INST_ID        SID    SERIAL# PROGRAM                               MACHINE      USERN   SQL_ID
---------- ---------- ---------- -----------------------------------   ---------    ------- -------------
         1        569          5 oraagent.bin@dm-db1.hps (TNS V1-V3)   dm-db1.hps   SYS
         1       2566       6317 oracle@dm-db1.hps (O001)              dm-db1.hps   SYS
         1       3683        561 oraagent.bin@dm-db1.hps (TNS V1-V3)   dm-db1.hps   SYS    4qm8a3w6a1rfd
         1       3967          1 oraagent.bin@dm-db1.hps (TNS V1-V3)   dm-db1.hps   SYS
         2        569          3 oraagent.bin@dm-db2.hps (TNS V1-V3)   dm-db2.hps   SYS
         2       3682          1 oraagent.bin@dm-db2.hps (TNS V1-V3)   dm-db2.hps   SYS

6 rows selected.
Sys sessions with program oraagent.bin@hostname are expected in RAC environment (except for bug in 11.2.0.2, refer 1307139.1) and does not cause excessive audit file generation. Only thing out of place was O001 process. Looking at the logon time for this session it showed been logon while back and similar systems (11.2.0.3 RAC) didn't have this process logon for long periods as in this case. From the Oracle reference document states "Onnn slave processes are spawned on demand. These processes communicate with the ASM instance. Maintains a connection to the ASM instance for metadata operations". According to 1556564.1 Onnn processes are spawned and terminated automatically and could be killed of if required and system will re-spawn it when needed and killing it will not effect database operations.
However it was decided to do a cluster stack restart on the node 1 during system maintenance. After the restart the Onnn process was not there and audit file generation went back to normal, burst of audit file generation every 5 second wasn't there anymore.

Useful metalink note
How to Setup Auditing [ID 1020945.6]
11g: Possible reasons for many OS audit trail (.aud) files, <1KB in size [ID 1474823.1]
Large Number of Audit Files Generated by Oracle Restart or Grid Infrastructure [ID 1378881.1]
Large Number Of Audit Files Generated During Rman Backups [ID 1211396.1]
AUDIT_SYS_OPERATIONS Set To FALSE Yet Audit Files Are Generated [ID 308066.1]
Huge/Large/Excessive Number Of Audit Records Are Being Generated In The Database [ID 1171314.1]
SCRIPT: Generate AUDIT and NOAUDIT Statements for Current Audit Settings [ID 287436.1]
How does the NOAUDIT option work (Disabling AUDIT commands)[ID 1068714.6]
A Lot of Audit Files in ASM Home [ID 813416.1]
Many OS Audit Files Produced By The Grid Control Agent Connections [ID 1196323.1]
New Feature DBMS_AUDIT_MGMT To Manage And Purge Audit Information [ID 731908.1]
Manage Audit File Directory Growth with cron [ID 1298957.1]
Script to Show Audit Options/Audit Trail [ID 1019552.6]
AUDIT_TRAIL Set to DB yet Some Audited Entries for non-Sysdba Users Are Created in the OS Trail. [ID 1279934.1]
The Column DBA_PRIV_AUDIT_OPTS Has Rows With USER_NAME 'ANY CLIENT' and PROXY_NAME NULL [ID 455565.1]
High Load On Server from Process Ora_onnn [ID 1556564.1]