audit_trail=os set with audit_syslog_level is losing the audit trail

I have recently discovered that the Oracle audit trail is not guaranteed if it is sent to syslog.

The Oracle® Database Security Guide 11g Release 2 (11.2) E36292-02 says:

• If the Operating System Audit Trail Becomes Full

• Be aware that an operating system audit trail or file system, including the Windows Event Log, can become full, and therefore, unable to accept new records, including audit records from Oracle Database. In this case, Oracle Database cancels and rolls back the operation being performed, including operations that normally are always audited. (See "Activities That Are Always Audited for All Platforms".) If the operating system audit trail becomes full, then set the AUDIT_TRAIL parameter to use database audit trail (such as DB or DB, EXTENDED). This prevents the audited actions from completing if their audit records cannot be stored. You should periodically archive and purge the operating system audit file to prevent these types of failures.
• If you plan to use operating system auditing, then ensure that the operating system audit trail or the file system does not fill completely. Most operating systems provide administrators with sufficient information and warning to ensure this does not occur. If you configure auditing to use the database audit trail, you can prevent this potential loss of audit information. Oracle Database prevents audited events from occurring if the audit trail is unable to accept the database audit record for the statement.

Be careful how you read this  "Oracle Database prevents audited events from occurring if the audit trail is unable to accept the database audit record for the statement."

No it doesn't.

If the trail is sent to syslog and the filesystem becomes full, Oracle continues to work but does not write the audit trail.

A little auditing to OS background (if you want more detail on how to set it up, the manual is very easy to follow)

If you set audit_sys_operations=true a log of anything done by sysdba and sysoper is written.

This trail is written the form of .aud files to the audit_file_dest (adump). I have written previously about how to manage these in Oracle 11.2.

You can send all your oracle audit (including those generated as a result of audit statements) to these OS files instead of sys.aud$ by setting audit_trail=OS (instead of DB)

You can take this one step further though and have these logs sent to syslog instead. you might think of syslog as /var/log/messages but in fact it can be any file you like.  It is written to by the syslog service.

To send the trail to syslog you define it in oracle using the parameter audit_syslog_level.

What you put in audit_syslog_level must be defined in
/etc/syslog.conf (Linux 5) or /etc/rsyslog.conf (Linux 6)
e.g. if audit_syslog_level='local6.info'
then
 /etc/syslog.conf
*.info;local6.none /var/log/messages
local6.* /var/log/oracle/oracleaudit.log

or for AIX
local6.info /var/log/oracle/oracleaudit.log

the syslog services needs restarting after this file is changed


For Oracle you would set
alter system set audit_sys_operations=true scope=spfile;
alter system set audit_trail=os scope=spfile;
alter system set audit_syslog_level='local6.info' scope=spfile;
Shutdown immediate;
Startup;


Let me show you first how Oracle behaves when you are writing to .aud files and the file system fills up


SQL> show parameter audit
audit_file_dest string /var/log/oracle
audit_sys_operations  TRUE
audit_syslog_level ''
audit_trail string OS
SQL> shutdown immediate;

I filled the filesystem /var/log/oracle

SQL> startup
ORA-09817: Write to audit file failed. Linux-x86_64 Error: 28: No space left on device Additional information: 12 ORA-09945: Unable to initialize the audit trail file Linux-x86_64 Error: 28: No space left on device

It's clearly trying to write a file as it creates a zero byte file but can't put anything in it, so the startup fails
-rw-r----- 1 oracle dba   0 Dec 2 12:51 MYSID_ora_18762_20131202125132.aud

> sqlplus / as sysdba
SQL*Plus: Release 11.2.0.4.0
ERROR: ORA-09817: Write to audit file failed. Linux-x86_64 Error: 28: No space left on device

So I emptied the filesystem again

> sqlplus / as sysdba
SQL*Plus: Release 11.2.0.4.0
SQL>

and it's fine and the connection audit file wrote

-rw-r----- 1 oracle dba 1131 Dec 2 12:54 MYSID_ora_24020_20131202125416.aud

This is completely expected behaviour, you can't start up the database if it can't write the mandatory audit file.

But now look, let's do some audited stuff with syslog configured instead of .aud files:

sylog.conf
# Oracle audit logs local6.* /var/log/oracle/oracleaudit.log

> ls -l /var/log/oracle/oracleaudit.log
-rw------- 1 root root 7950336 Nov 25 14:49 /var/log/oracle/oracleaudit.log

SQL> show parameter audit;
audit_file_dest string /mydiagpath/admin/mysid/adump
audit_sys_operations TRUE
audit_syslog_level string LOCAL6.INFO
audit_trail string OS

I fill the file system and connect to the database

>sqlplus / as sysdba

it let me in, it should have refused

SQL> select to_char(sysdate,'MM/DD/YY HH24:MI:SS') from dual;
11/25/13 14:50:18
>exit

The oracleaudit.log timestamp changed,

-rw------- 1 root root 7950336 Nov 25 14:50 /var/log/oracle/oracleaudit.log

but it didn't write a record into it.  The size remained the same and the last entry was still from 14:11

tail -2 oracleaudit.log Nov 25 14:11:42 myservername Oracle Audit[25001]: LENGTH: "249" SESSIONID:[7] "7 165147" ENTRYID:[1] "1" STATEMENT:[1] "1" USERID:[6] "MYUSER" USERHOST:[12] "myserver" ACTION:[3] "100" RETURNCODE:[1] "0" COMMENT$TEXT:[20] "Authenticated by: OS" OS$USERID:[6] "myuser" DBID:[10] "nnnnnnnnnnnn" PRIV$USED:[1] "5"

something like create user should fail right?


> sqlplus / as sysdba
SQL*Plus: Release 11.2.0.4.0
SQL> audit create user by system;
Audit succeeded.
SQL> audit drop user by system;
Audit succeeded.
SQL> alter user system identified by systempassword;
User altered.
SQL>

nothing written to log for the sysdba connection or work done

tail -2 oracleaudit.log
Nov 25 14:11:42 myservername Oracle Audit[25001]: LENGTH: "249" SESSIONID:[7] "7 165147" ENTRYID:[1] "1" STATEMENT:[1] "1" USERID:[6] "MYUSER" USERHOST:[12] "myserver" ACTION:[3] "100" RETURNCODE:[1] "0" COMMENT$TEXT:[20] "Authenticated by: OS" OS$USERID:[6] "myuser" DBID:[10] "nnnnnnnnnnnn" PRIV$USED:[1] "5"

-rw------- 1 root root 7950336 Nov 25 14:57 oracleaudit.log


> sqlplus system/systempassword
SQL*Plus: Release 11.2.0.4.0
SQL> CREATE USER "NEWUSER" PROFILE "DEFAULT" IDENTIFIED BY "newuser" DEFAULT TABLESPACE "USERS" TEMPORARY TABLESPACE "TEMP";
User created.
SQL> drop user "NEWUSER";
User dropped.
SQL> exit

the audit file still hasn't altered, nothing is being written,

-rw------- 1 root root 7950336 Nov 25 14:51 /var/log/oracle/oracleaudit.log

it's not overwriting itself at either end:

tail -2 oracleaudit.log
Nov 25 14:11:42 myservername Oracle Audit[25001]: LENGTH: "249" SESSIONID:[7] "7 165147" ENTRYID:[1] "1" STATEMENT:[1] "1" USERID:[6] "MYUSER" USERHOST:[12] "myserver" ACTION:[3] "100" RETURNCODE:[1] "0" COMMENT$TEXT:[20] "Authenticated by: OS" OS$USERID:[6] "myuser" DBID:[10] "nnnnnnnnnnnn" PRIV$USED:[1] "5"

Just to show it's not wrapping:

head -1 oracleaudit.log
Nov 24 04:03:16 myservername Oracle Audit[13482]: LENGTH: "249" SESSIONID:[7] "7 152208" ENTRYID:[1] "1" STATEMENT:[1] "1" USERID:[6] "MYUSER" USERHOST:[12] "myhost" ACTION:[3] "100" RETURNCODE:[1] "0" COMMENT$TEXT:[20] "Authenticated by: OS" OS$USERID:[6] "myuser" DBID:[10] "nnnnnnnnn" PRIV$USED:[1] "5"


show it's not going to old adump

ls -ltr /mydiagpath/admin/mysid/adump
-rw-r----- 1 oracle dba 727 Nov 5 12:12 mysid_ora_3870_2.aud
-rw-r----- 1 oracle dba 732 Nov 5 12:12 mysid_ora_5002_1.aud
-rw-r----- 1 oracle dba 1413 Nov 5 12:12 mysid_ora_4904_1.aud

No only old files in there.

show it's not going to /var/log/messages

tail -2 /var/log/messages
Nov 25 11:41:14 myhost ntpd[5325]: synchronized to nn.nn.n.n, stratum 3
Nov 25 12:26:05 myhost ntpd[5325]: synchronized to nnn.nnn.nnn.n stratum 3

nothing is being written to any logs but oracle is allowing audited transactions to happen

Nothing is being written to the audit log for ddl but let's go for dml, it can't let dml through surely:


> date Mon Nov 25 14:59:51 GMT 2013
> sqlplus / as sysdba
SQL*Plus: Release 11.2.0.4.0 Production on Mon Nov 25 15:00:20 2013
SQL> audit create table by system;
Audit succeeded.
SQL> audit insert table by system;
Audit succeeded.
SQL> exit

> sqlplus system/systempassword
SQL*Plus: Release 11.2.0.4.0 Production on Mon Nov 25 15:01:01 2013
SQL> create table test_table (cola number) tablespace tools;
Table created.
SQL> Insert into test_table values(1);
1 row created.
SQL> commit;
Commit complete.
SQL> select * from test_table;
COLA ---------- 1
SQL> exit

and the audit log, still absolutely nothing:

-rw------- 1 root root 7950336 Nov 25 15:02 /var/log/oracle/oracleaudit.log

tail -2 oracleaudit.log
Nov 25 14:11:42 myservername Oracle Audit[25001]: LENGTH: "249" SESSIONID:[7] "7 165147" ENTRYID:[1] "1" STATEMENT:[1] "1" USERID:[6] "MYUSER" USERHOST:[12] "myserver" ACTION:[3] "100" RETURNCODE:[1] "0" COMMENT$TEXT:[20] "Authenticated by: OS" OS$USERID:[6] "myuser" DBID:[10] "nnnnnnnnnnnn" PRIV$USED:[1] "5"

maybe it's cached somewhere? So let's clear some space in the file system and see if Oracle write the logs that are missing.

I removed my files padding the filesystem out and waited a while then connected again.

Nov 25 14:11:42 myservername Oracle Audit[25001]: LENGTH: "249" SESSIONID:[7] "7 165147" ENTRYID:[1] "1" STATEMENT:[1] "1" USERID:[6] "MYUSER" USERHOST:[12] "myserver" ACTION:[3] "100" RETURNCODE:[1] "0" COMMENT$TEXT:[20] "Authenticated by: OS" OS$USERID:[6] "myuser" DBID:[10] "nnnnnnnnnnnn" PRIV$USED:[1] "5"
Nov 25 15:03:39 myservername Oracle Audit[22921]: LENGTH: "249" SESSIONI D:[7] "7165484" ENTRYID:[1] "1" STATEMENT:[1] "1" USERID:[6] "MYUSER" USERHOST:[ 12] "myserver" ACTION:[3] "100" RETURNCODE:[1] "0" COMMENT$TEXT:[20] "Authenticated by: OS" OS$USERID:[6] "myuser" DBID:[10] "nnnnnnnn" PRIV$USED:[1] "5"

Oracle started to write the new audit records, but all the events that should have been audited that happened in between didn't show.

I have reported this to Oracle but I am wondering if it is expected behaviour, once Oracle hands off to syslog it has no control about whether unix actually writes the record. 

I think it's something to understand.

Make sure your filesystem monitoring of where syslog is writing the file is good,  you can do it through OEM, you don't have to rely on your unix admins.

******
Oracle have stated:

Syslog is a logger facility which runs as a daemon process started by the Linux kernel. Different OS programs can send messages to this logger so that they are recorded as per the configuration mentioned in /etc/syslog.conf.

When Oracle Database runs as a program, it sends its audit records to be written to the same logging facility (SYSLOGD). The Oracle Database program is a client to the Syslogd daemon process.
The APIs used to send messages to Syslogd are:
1. openlog - to open the connection to the system logger
2. syslog - generates a log message, which will be distributed by syslogd
3. closelog - to closes the descriptor being used to write to the system logger.

None of these routines returns a status back to the caller. Typically, these messages are buffered in a ring buffer which gets flushed to the destination as mentioned in syslog.conf, by the SYSLOGD daemon. In other words, these are asynchronous calls to the syslogd. Therefore, the failure to write to the real destination mentioned in syslog.conf cannot be collected by the callers. In this case, its the Oracle Database program and this cannotdetermine the failure.

Perhaps there should be a message on the console or some other location indicating failure to write to Syslog. But callers don't seem to get that notification. Therefore, this bug cannot be fixed by Oracle.

Workaround would be to use OS audit files without syslog as it has been tested and found to be working as expected, they do abort the action.

In Oracle 12c Unified Auditing does not offer syslog configuration.

*******