Oracle LogMiner Helps Investigate Security Issues

This will help when you need to investigate some past changes to your database when auditing was not enabled. This doesn’t imply that you don’t need auditing. On the contrary, I see no reason not to use it in any and every database. However, often we get systems “as is” and we need a working method now and not the next time it happens.

Here is the story. One night my team got paged about a materialized view (MV) refresh that failed with “ORA-01017: invalid username/password; logon denied”. This was an MV on the table from a remote database using a database link.

Obviously, someone changed the password (ruling out modification of the database link and materialized view). After some questioning, we couldn’t figure out who the culprit was. The client became very worried that someone unauthorized changed the password, and so it became our top priority to figure out who/when/why.

The first thing to look at is whether auditing is enabled in a given instance. As usual, it’s never there when you need it — AUDIT_TRAIL=NONE. My first estimation of the time frame when the password was changed was the 24 hours between last MV refresh and the first failure. But that’s not good enough.

DBA_USERS doesn’t contain a column with the time of the password change, but it’s based on the SYS.USER$ table, and there is a PTIME column there. Fair enough — the timestamp there was within the 24 hours range I mentioned above: the time was 12:40:30. That’s better already.

DBAs often use the SYSDBA account for a simple login. In case you don’t know, all SYSDBA connections are logged, regardless of audit_trial parameter. So let’s have a look at those audit files. First, we need to check the audit_file_dest parameter. If it’s empty, audit files are created in $ORACLE_HOME/rdbms/audit (that can be platform-specific). Here I found a few suspicious files created at 12:40 and 12:37. I don’t believe in coincidence, so this is probably the incident.

Anyway, let’s try LogMiner. First, I restored the archived logs for the time frame I needed using RMAN.
Start LogMiner:

BEGIN 
   DBMS_LOGMNR.START_LOGMNR( 
   STARTTIME => '2006-10-10 02:00:00', 
   ENDTIME => '2006-10-10 13:00:00', 
   OPTIONS => DBMS_LOGMNR.DICT_FROM_ONLINE_CATALOG + DBMS_LOGMNR.CONTINUOUS_MINE); 
END; 
/

I included a longer period to make sure I catch other possible manipulations. Then I captured all the modifications to USER$ table using the statement:

create table user_mod
  as
select *
  from V$LOGMNR_CONTENTS
  where seg_owner='SYS'
    and seg_name='USER$';

There were several entries — the majority of them with the USERNAME column NULL and a few with SYS. That’s what I needed – two updates with timestamps 12:39 and 12:40 from the SYS user. (Internal updates, if you’re interested, are updates of the LCOUNT column in USER$ table when the user tries to login with wrong password.) Unfortunately, I couldn’t see any details, as it was all marked unsupported (because of SYS objects, I believe). Actually, I’m going to mention later that I should have just extracted DDL statements, but at that time I didn’t think about it (no idea why – I didn’t work much with LogMiner before 9i).

What I got from V$LOGMNR_CONTENTS was a redo sequence (RBASQN) and SCN. So if LogMiner doesn’t let me know what those statements are, I need to dump redo blocks using:

alter system dump logfile '' scn min  scn max ;

We can get from V$ARCHIVED_LOG using the sequence from the RBASQN column; for we can substitute the value from the SCN column.

Looking into the dump, I could recognize that in the first update, the user account was unlocked (ALTER USER ACCOUNT UNLOCK), and in the second update, the password was changed. Here is the content of the block dump with the password change:

REDO RECORD - Thread:1 RBA: 0x000327.000026ac.0010 LEN: 0x02b8 VLD: 0x05
SCN: 0x0571.f1eeec85 SUBSCN:  1 10/10/2006 12:40:30
CHANGE #1 TYP:0 CLS:53 AFN:6 DBA:0x00000091 OBJ:4294967295 SCN:0x0571.f1eeec82 SEQ:  1 OP:5.2
ktudh redo: slt: 0x000b sqn: 0x00000000 flg: 0x0002 siz: 248 fbi: 0
            uba: 0x000002c7.035a.0d    pxid:  0x0000.000.00000000
CHANGE #2 TYP:0 CLS:54 AFN:6 DBA:0x000002c7 OBJ:4294967295 SCN:0x0571.f1eeec82 SEQ:  1 OP:5.1
ktudb redo: siz: 248 spc: 4710 flg: 0x0022 seq: 0x035a rec: 0x0d
            xid:  0x0013.00b.00002630
ktubu redo: slt: 11 rci: 0 opc: 11.1 objn: 22 objd: 10 tsn: 0
Undo type:  Regular undo       Undo type:  Last buffer split:  No
Tablespace Undo:  No
             0x00000000
KDO undo record:
KTB Redo
op: 0x04  ver: 0x01
op: L  itl: xid:  0x000f.005.00004094 uba: 0x000000cd.0a60.10
                      flg: C---    lkc:  0     scn: 0x0571.f1eeec68
KDO Op code: URP row dependencies Disabled
  xtype: XA flags: 0x00000000  bdba: 0x0040005c  hdba: 0x00400059
itli: 2  ispac: 0  maxfr: 4863
tabn: 1 slot: 17(0x11) flag: 0x6c lock: 0 ckix: 14
ncol: 19 nnew: 14 size: 0
col  0: [ 4]  43 55 53 54
col  1: [ 2]  c1 02
col  2: [16]  31 44 42 31 34 31 39 31 38 42 31 36 35 37 35 32
col  3: [ 2]  c1 0b
col  4: [ 2]  c1 07
col  6: [ 7]  78 6a 09 04 01 19 3c
col  7: *NULL*
col  8: [ 7]  78 6a 0a 0a 0d 24 2a
col  9: [ 1]  80
col 11: [ 2]  c1 02
col 14: [ 1]  80
col 15: [ 2]  c1 03
col 16: [22]
 44 45 46 41 55 4c 54 5f 43 4f 4e 53 55 4d 45 52 5f 47 52 4f 55 50
col 18: [ 1]  80
CHANGE #3 TYP:2 CLS: 1 AFN:1 DBA:0x0040005c OBJ:10 SCN:0x0571.f1eeec68 SEQ:  1 OP:11.5
KTB Redo
op: 0x11  ver: 0x01
op: F  xid:  0x0013.00b.00002630    uba: 0x000002c7.035a.0d
Block cleanout record, scn:  0x0571.f1eeec85 ver: 0x01 opt: 0x02, entries follow...
  itli: 2  flg: 2  scn: 0x0571.f1eeec68
KDO Op code: URP row dependencies Disabled
  xtype: XA flags: 0x00000000  bdba: 0x0040005c  hdba: 0x00400059
itli: 2  ispac: 0  maxfr: 4863
tabn: 1 slot: 17(0x11) flag: 0x6c lock: 2 ckix: 14
ncol: 19 nnew: 14 size: 0
col  0: [ 4]  43 55 53 54
col  1: [ 2]  c1 02
col  2: [16]  45 32 30 35 44 37 30 32 32 46 36 33 34 39 42 42
col  3: [ 2]  c1 0b
col  4: [ 2]  c1 07
col  6: [ 7]  78 6a 0a 0a 0d 29 1f
col  7: *NULL*
col  8: [ 7]  78 6a 0a 0a 0d 24 2a
col  9: [ 1]  80
col 11: [ 2]  c1 02
col 14: [ 1]  80
col 15: [ 2]  c1 03
col 16: [22]
 44 45 46 41 55 4c 54 5f 43 4f 4e 53 55 4d 45 52 5f 47 52 4f 55 50
col 18: [ 1]  80

The redo record contains three change vectors. The operation is identified with OP:

• OP 5.2 – marking beginning of transaction
• OP 5.1 – undo info for table data block
• OP 11.5 – data block modification

“col 0” is username. “col 2” is password values. “col 6” corresponds to PTIME – the timestamp of password change.

Just to check that this corresponds to the last password change:

select dump(ptime,16) dmp from sys.user$ where name='CUST';
DMP
----------------------------------------
Typ=12 Len=7: 78,6a,a,a,d,29,1f

Looking at the column SESSION_INFO, I could see that it was a local connection from the oracle unix account using sqlplus. I could also see the terminal and process id.

Next I looked into the system logs to see who was logged in. On Linux I can read /var/log/messages. I figured out that there was a sudo on this terminal from another account a few minutes before the change and an earlier connection established with ssh from certain IP address.

The rest was relatively simple — finding out whose workstation it was and why the password was changed. According to the password-changer, the password wasn’t the one he expected (the one referenced in documentation), and after a certain number of his login attempts, the account was locked. The DBA unlocked it and changed the password to the “correct” one.

As I mentioned above, you don’t need to dump redo blocks if you are on a decent version of Oracle — i.e. 9i or higher. In Oracle8 and 8i, you would have to dump redo blocks — that’s why I kept it this way in the post. Actually, you can even do it in Oracle 7, just using redo block dumps — but it would take a bit longer though and might be more difficult to identify session information.

Anyway, in 9i and higher, the easier approach is:

select * from V$LOGMNR_CONTENTS where operation='DDL' and SEG_TYPE_NAME='USER';

So our client was happy that unknown became known, but gladly accepted the proposal to plan and implement auditing so that these types of issues can be easily investigated in the future. If you don’t have auditing standards set and implemented, this should be a friendly reminder to get back to it.