Oracle 12c – RMAN and Unified Auditing – Does it really work?

By William Sescu

The new Oracle Unified Auditing feature, audits RMAN operation per default as soon as
you relink your Oracle binary and start your instance. A quite cool new feature, because it allows me
to audit RMAN operation out of the box. For example, someone could create a RMAN backup to ‘/tmp’ and then copy it to somewhere else. And I would like to know that. 😉

Oracle added 5 columns to the unified_audit_trail view only for RMAN, to find out what RMAN operation was done on the database. The new columns are the following.

• RMAN_SESSION_RECID
• RMAN_SESSION_STAMP
• RMAN_OPERATION
• RMAN_OBJECT_TYPE
• RMAN_DEVICE_TYPE

Due to the Oracle documentation, the column description is the following.

RMAN_SESSION_RECID

RMAN session identifier. Together with RMAN_SESSION_STAMP uniquely identifies an RMAN job
(note that this is not same as user session ID; the value is a recid in controlfile that identifies RMAN job)

RMAN_SESSION_STAMP

Timestamp for the session

RMAN_OPERATION

The RMAN operation executed by the job. One row will be added for each distinct operation within an RMAN session. For example, a backup job would contain BACKUP in the RMAN_OPERATION column.

RMAN_OBJECT_TYPE

Type of objects involved for backup or restore/recover or change/delete/crosscheck commands. It contains one of the following values. If RMAN command does not satisfy one of them,  then preference is given in order, from top to bottom of the list:

• DB FULL
• RECVR AREA
• DB INCR
• DATAFILE FULL
• DATAFILE INCR
• ARCHIVELOG
• CONTROLFILE
• SPFILE

RMAN_DEVICE_TYPE

Device involved in the RMAN job. It may be DISK or SBT_TAPE or *  (An * indicates that more than one location is involved). For a backup job, it will be the output device type. For other commands (such as restore or crosscheck),  it will be the input device type.

Ok. Let’s start with a first test. Just for the protocol, I am using here 12cR1 PSU Oct 2016.

First of all, I am activating the “immediate-write” feature, meaning that audit records are written immediately,  and not to the audit buffer first.

SQL> select parameter, value from v$option where parameter like '%Unified%';

PARAMETER              VALUE
---------------------- --------
Unified Auditing       TRUE

-- Modify OUA to use the immediate-write mode

SQL> BEGIN
  2  DBMS_AUDIT_MGMT.SET_AUDIT_TRAIL_PROPERTY(
  3  DBMS_AUDIT_MGMT.AUDIT_TRAIL_UNIFIED,
  4  DBMS_AUDIT_MGMT.AUDIT_TRAIL_WRITE_MODE,
  5  DBMS_AUDIT_MGMT.AUDIT_TRAIL_IMMEDIATE_WRITE);
  6  END;
  7  /

PL/SQL procedure successfully completed.

SQL> select * from DBA_AUDIT_MGMT_CONFIG_PARAMS where PARAMETER_NAME = 'AUDIT WRITE MODE';

PARAMETER_NAME                   PARAMETER_VALUE        AUDIT_TRAIL
-------------------------------- ---------------------- ----------------------------
AUDIT WRITE MODE                 IMMEDIATE WRITE MODE   UNIFIED AUDIT TRAIL

Ok. Cool. So far so good. Let’s start a RMAN backup job now.

oracle@dbidg01:/home/oracle/ [DBIT121] rman target /

Recovery Manager: Release 12.1.0.2.0 - Production on Fri Dec 9 15:59:44 2016

Copyright (c) 1982, 2014, Oracle and/or its affiliates.  All rights reserved.

connected to target database: DBIT121 (DBID=172831209)

RMAN> backup database plus archivelog delete input;
Starting backup at 09-DEC-2016 16:03:41
current log archived
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=12 device type=DISK
channel ORA_DISK_1: starting archived log backup set
channel ORA_DISK_1: specifying archived log(s) in backup set
input archived log thread=1 sequence=22 RECID=6 STAMP=930153822
channel ORA_DISK_1: starting piece 1 at 09-DEC-2016 16:03:43
channel ORA_DISK_1: finished piece 1 at 09-DEC-2016 16:03:44
piece handle=/u03/fast_recovery_area/DBIT121_SITE1/backupset/2016_12_09/o1_mf_annnn_TAG20161209T160342_d4okyh1t_.bkp tag=TAG20161209T160342 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
channel ORA_DISK_1: deleting archived log(s)
archived log file name=/u03/fast_recovery_area/DBIT121_SITE1/archivelog/2016_12_09/o1_mf_1_22_d4okyfo5_.arc RECID=6 STAMP=930153822
Finished backup at 09-DEC-2016 16:03:44

Starting backup at 09-DEC-2016 16:03:44
using channel ORA_DISK_1
channel ORA_DISK_1: starting full datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
input datafile file number=00005 name=/u02/oradata/DBIT121_SITE1/datafile/o1_mf_example_d4fjz1fz_.dbf
input datafile file number=00001 name=/u02/oradata/DBIT121_SITE1/datafile/o1_mf_system_d4fjt03j_.dbf
input datafile file number=00003 name=/u02/oradata/DBIT121_SITE1/datafile/o1_mf_sysaux_d4fjrlvs_.dbf
input datafile file number=00004 name=/u02/oradata/DBIT121_SITE1/datafile/o1_mf_undotbs1_d4fjvtd1_.dbf
input datafile file number=00006 name=/u02/oradata/DBIT121_SITE1/datafile/o1_mf_users_d4fjvqb1_.dbf
channel ORA_DISK_1: starting piece 1 at 09-DEC-2016 16:03:44
channel ORA_DISK_1: finished piece 1 at 09-DEC-2016 16:05:19
piece handle=/u03/fast_recovery_area/DBIT121_SITE1/backupset/2016_12_09/o1_mf_nnndf_TAG20161209T160344_d4okyjny_.bkp tag=TAG20161209T160344 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:01:35
channel ORA_DISK_1: starting full datafile backup set
channel ORA_DISK_1: specifying datafile(s) in backup set
including current control file in backup set
including current SPFILE in backup set
channel ORA_DISK_1: starting piece 1 at 09-DEC-2016 16:05:20
channel ORA_DISK_1: finished piece 1 at 09-DEC-2016 16:05:21
piece handle=/u03/fast_recovery_area/DBIT121_SITE1/backupset/2016_12_09/o1_mf_ncsnf_TAG20161209T160344_d4ol1jnj_.bkp tag=TAG20161209T160344 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 09-DEC-2016 16:05:21

Starting backup at 09-DEC-2016 16:05:21
current log archived
using channel ORA_DISK_1
channel ORA_DISK_1: starting archived log backup set
channel ORA_DISK_1: specifying archived log(s) in backup set
input archived log thread=1 sequence=23 RECID=7 STAMP=930153921
channel ORA_DISK_1: starting piece 1 at 09-DEC-2016 16:05:21
channel ORA_DISK_1: finished piece 1 at 09-DEC-2016 16:05:23
piece handle=/u03/fast_recovery_area/DBIT121_SITE1/backupset/2016_12_09/o1_mf_annnn_TAG20161209T160521_d4ol1ktz_.bkp tag=TAG20161209T160521 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:02
channel ORA_DISK_1: deleting archived log(s)
archived log file name=/u03/fast_recovery_area/DBIT121_SITE1/archivelog/2016_12_09/o1_mf_1_23_d4ol1kpj_.arc RECID=7 STAMP=930153921
Finished backup at 09-DEC-2016 16:05:23

RMAN>

After my RMAN Backup has finished, I open another session and checked the unified_audit_trail, but nothing is there.

SQL> select EVENT_TIMESTAMP, ACTION_NAME, RMAN_SESSION_RECID,
  2  RMAN_SESSION_STAMP, RMAN_OPERATION, RMAN_OBJECT_TYPE, RMAN_DEVICE_TYPE
  3  from unified_audit_trail where ACTION_NAME like '%RMAN%' order by 1;

no rows selected

Now I do a clean exit of my RMAN session, and here we go. Now I have an audit entry, saying that a RMAN backup to disk took place. Perfect, this is exactly what I wanted to see.

...
RMAN> exit

Recovery Manager complete.


SQL> select EVENT_TIMESTAMP, ACTION_NAME, RMAN_SESSION_RECID,
  2  RMAN_SESSION_STAMP, RMAN_OPERATION, RMAN_OBJECT_TYPE, RMAN_DEVICE_TYPE
  3  from unified_audit_trail where ACTION_NAME like '%RMAN%' order by 1;

EVENT_TIMESTAMP              ACTION_NAME    RMAN_SESSION_RECID RMAN_SESSION_STAMP RMAN_OPERATION       RMAN_OBJECT_TYPE     RMAN_
---------------------------- -------------- ------------------ ------------------ -------------------- -------------------- -----
09-DEC-16 04.08.10.532931 PM RMAN ACTION                    22          930153584 Backup               DB Full              Disk

This brings me to an idea. What happens if a Hacker logs into my system, starts a RMAN backup, and kills his own RMAN session, after the backup has finished? Sounds crazy, but Hackers are usually very creative.

Ok. The Hacker logs in now, and because the Hacker is smart, he gives his RMAN backup a TAG, so it is easier to delete it afterwards.

oracle@dbidg01:/home/oracle/ [DBIT121] rman target /

Recovery Manager: Release 12.1.0.2.0 - Production on Fri Dec 9 16:09:58 2016

Copyright (c) 1982, 2014, Oracle and/or its affiliates.  All rights reserved.

connected to target database: DBIT121 (DBID=172831209)

RMAN> alter system archive log current;

using target database control file instead of recovery catalog
Statement processed

RMAN> backup archivelog all format '/tmp/%U' TAG 'HACKER';

Starting backup at 09-DEC-2016 16:11:58
current log archived
allocated channel: ORA_DISK_1
channel ORA_DISK_1: SID=12 device type=DISK
channel ORA_DISK_1: starting archived log backup set
channel ORA_DISK_1: specifying archived log(s) in backup set
input archived log thread=1 sequence=24 RECID=8 STAMP=930154279
input archived log thread=1 sequence=25 RECID=9 STAMP=930154318
channel ORA_DISK_1: starting piece 1 at 09-DEC-2016 16:11:59
channel ORA_DISK_1: finished piece 1 at 09-DEC-2016 16:12:00
piece handle=/tmp/0ern21qf_1_1 tag=HACKER comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 09-DEC-2016 16:12:00

At this point, still no further entry in the unified_audit_trail.

SQL> r
  1  select EVENT_TIMESTAMP, ACTION_NAME, RMAN_SESSION_RECID,
  2  RMAN_SESSION_STAMP, RMAN_OPERATION, RMAN_OBJECT_TYPE, RMAN_DEVICE_TYPE
  3* from unified_audit_trail where ACTION_NAME like '%RMAN%' order by 1

EVENT_TIMESTAMP              ACTION_NAME    RMAN_SESSION_RECID RMAN_SESSION_STAMP RMAN_OPERATION       RMAN_OBJECT_TYPE     RMAN_
---------------------------- -------------- ------------------ ------------------ -------------------- -------------------- -----
09-DEC-16 04.08.10.532931 PM RMAN ACTION                    22          930153584 Backup               DB Full              Disk

Meanwhile, the Hacker copies the data away, and because the Hacker is a good boy, he cleans up everything afterwards. 🙂

RMAN> delete noprompt backuppiece tag=HACKER;

using channel ORA_DISK_1

List of Backup Pieces
BP Key  BS Key  Pc# Cp# Status      Device Type Piece Name
------- ------- --- --- ----------- ----------- ----------
14      14      1   1   AVAILABLE   DISK        /tmp/0ern21qf_1_1
deleted backup piece
backup piece handle=/tmp/0ern21qf_1_1 RECID=14 STAMP=930154319
Deleted 1 objects

At the moment, there is still nothing new in the unified_audit_trail. Now, to avoid entries into the unified_audit_trail view, the hacker kills his own session.

oracle@dbidg01:/tmp/ [DBIT121] ps -ef | grep rman | grep -v grep
oracle    8829  2839  0 16:09 pts/1    00:00:00 rman target /
oracle@dbidg01:/tmp/ [DBIT121] kill -9 8829


...
RMAN> Killed

And now the 1Million Dollar question … do we have a new entry or not?

SQL> r
  1  select EVENT_TIMESTAMP, ACTION_NAME, RMAN_SESSION_RECID,
  2  RMAN_SESSION_STAMP, RMAN_OPERATION, RMAN_OBJECT_TYPE, RMAN_DEVICE_TYPE
  3* from unified_audit_trail where ACTION_NAME like '%RMAN%' order by 1

EVENT_TIMESTAMP              ACTION_NAME    RMAN_SESSION_RECID RMAN_SESSION_STAMP RMAN_OPERATION       RMAN_OBJECT_TYPE     RMAN_
---------------------------- -------------- ------------------ ------------------ -------------------- -------------------- -----
09-DEC-16 04.08.10.532931 PM RMAN ACTION                    22          930153584 Backup               DB Full              Disk

No, no new entry. This entry is still the one from my regular RMAN backup with the clean exit.

Conclusion

Don’t rely too much on the unified_audit_trail records, in case you want to audit RMAN backups.

Cheers,
William