Trace session using login trigger

Friday, June 26, 2009

We have a Web application which is connecting to database, executes some statements and closes after a few secs. It is very hard to trace this sessions and catch what were they doing on database without some help.
To help myself I wrote simple login trigger which starts tracing on login and inserts information about tracefile into the info table.



First to create info table:

SQL> CREATE TABLE login_audit_info
(
logon_time DATE         ,
username   VARCHAR2(100),
tracefile  VARCHAR2(100)
);


Now to create login trigger which catches sessions executed by user "MSUTIC". Of course, you must use different database user. This "MSUTIC" user is used only for testing purposes here.
CREATE OR REPLACE TRIGGER audit_login_trigger
AFTER LOGON ON DATABASE
DECLARE
l_user        dba_users.username%TYPE   := USER;
l_sql         VARCHAR2 (500);
l_tracefile   VARCHAR2 (100);
l_time        DATE;
BEGIN
l_sql :=
'alter session set events '
|| CHR (39)
|| '10046 trace name context forever, level 12'
|| CHR (39);
l_time := SYSDATE;

IF (l_user = 'MSUTIC')
THEN
EXECUTE IMMEDIATE l_sql;

SELECT    pa.VALUE
|| '/'
|| LOWER (SYS_CONTEXT ('userenv', 'instance_name'))
|| '_ora_'
|| p.spid
|| '.trc'
INTO l_tracefile
FROM v$session s, v$process p, v$parameter pa
WHERE pa.NAME = 'user_dump_dest'
AND s.paddr = p.addr
AND s.audsid = SYS_CONTEXT ('USERENV', 'SESSIONID');

INSERT INTO login_audit_info
(logon_time, username, tracefile
)
VALUES (l_time, l_user, l_tracefile
);

COMMIT;
END IF;
END;
/


Now simple test.

$ sqlplus /nolog

SQL*Plus: Release 11.1.0.7.0 - Production on Fri Jun 26 14:22:47 2009

Copyright (c) 1982, 2008, Oracle.  All rights reserved.

SQL> connect msutic@test11
Enter password: ******
Connected.
SQL> select count(*) from test;

COUNT(*)
----------
1

SQL> exit


I executed "select count(*) from test" and made quick logoff.

SQL> set lines 200
SQL> col logon_time for a20
SQL> col username for a15
SQL> col tracefile for a150
SQL> select * from login_audit_info;

SQL> select to_char(logon_time,'dd.mm.yyyy hh24:mi:ss'),username,tracefile from login_audit_info;

TO_CHAR(LOGON_TIME, USERNAME        TRACEFILE
------------------- --------------- ------------------------------------------------------------
26.06.2009 14:25:59 MSUTIC          /oracle/diag/rdbms/test11/test11/trace/test11_ora_31218.trc


As you can see, my trigger fired and inserted one row into the table.

To examine specified trace file:


vi /oracle/diag/rdbms/test11/test11/trace/test11_ora_31218.trc
...
...
*** 2009-06-26 14:26:07.877
WAIT #0: nam='SQL*Net message from client' ela= 8173860 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=1246019167877543
=====================
PARSING IN CURSOR #2 len=25 dep=0 uid=84 oct=3 lid=84 tim=1246019167868491 hv=297253644 ad='3ac91a38' sqlid='7b2twsn8vgfsc'
select count(*) from test
END OF STMT
PARSE #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1950795681,tim=1246019167868491
EXEC #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1950795681,tim=1246019167868491
WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=1246019167878005
FETCH #2:c=0,e=0,p=0,cr=7,cu=0,mis=0,r=1,dep=0,og=1,plh=1950795681,tim=1246019167868491
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=7 pr=0 pw=0 time=0 us)'
STAT #2 id=2 cnt=1 pid=1 pos=1 obj=76970 op='TABLE ACCESS FULL TEST (cr=7 pr=0 pw=0 time=0 us cost=3 size=0 card=1)'
WAIT #2: nam='SQL*Net message from client' ela= 265 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=1246019167878544
FETCH #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1950795681,tim=1246019167868491
WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=-1 tim=1246019167878647
...
...


I have valid trace and now I can do detailed examination.

If you don't need tracing any more just disable trigger (don't drop it) and later when you need tracing again just enable it.
alter trigger audit_login_trigger disable;


Share/Bookmark

0 comments:

Post a Comment