Saturday, September 03, 2016

How to Automatically Trace a User's Sessions

This post was sponsored by arcserve 

It shows how you can use a logon trigger to automatically trace all sessions for a given user. This can be useful where an application is launched from a desktop but fails before the DBA has had time to identify the SID and SERIAL# to start tracing the session. I tested it in an Oracle 11.1.0.6 database running on Windows 8.

First I created a database user:


SQL> create user ford
  2  identified by fiesta
  3  /

User created.

SQL> grant create session,
  2        create trigger,
  3        alter session to ford
  4  /

Grant succeeded.

SQL>


Then I logged in as the user and created a trigger:

SQL> conn ford/fiesta
Connected.
SQL> create or replace trigger immediate_trace
  2  after logon on ford.schema
  3  begin
  4  execute immediate 'alter session set sql_trace = true';
  5  end;
  6  /

Trigger created.

SQL>


I logged in again and ran some SQL:

SQL> conn ford/fiesta
Connected.
SQL> select sysdate from dual
  2  /

SYSDATE
---------
03-SEP-16

SQL>


This produced a trace file ready for further analysis e.g. by tkprof. It included, among other statements, the following:

=====================
PARSING IN CURSOR #3 len=66 dep=1 uid=89 oct=47 lid=89 tim=16846197344563 hv=836160175 ad='b719a518' sqlid='21fcha0sxdkpg'
begin
execute immediate 'alter session set sql_trace = true';
end;
END OF STMT
EXEC #3:c=0,e=23597,p=0,cr=0,cu=0,mis=1,r=1,dep=1,og=1,tim=16846197344558
=====================


and

=====================
PARSING IN CURSOR #3 len=24 dep=0 uid=89 oct=3 lid=89 tim=16846207456189 hv=2343063137 ad='b71c8490' sqlid='7h35uxf5uhmm1'
select sysdate from dual
END OF STMT
PARSE #3:c=0,e=307,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=16846207456188
EXEC #3:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=16846207456292
FETCH #3:c=0,e=6,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=16846207456323
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
FETCH #3:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=16846207502363

*** 2016-09-03 18:30:07.555
XCTEND rlbk=0, rd_only=1
=====================


Incidentally, if you find a trigger like this and you are not sure what it is for, you can find out as follows:

SQL> conn / as sysdba
Connected.
SQL> l
  1  select description
  2  from dba_triggers
  3  where owner = 'FORD'
  4* and trigger_name = 'IMMEDIATE_TRACE'
SQL> /

DESCRIPTION
--------------------------------------------------
immediate_trace
after logon on ford.schema

SQL> l
  1  select trigger_body
  2  from dba_triggers
  3  where owner = 'FORD'
  4* and trigger_name = 'IMMEDIATE_TRACE'
SQL> /

TRIGGER_BODY
----------------------------------------------------------
begin
execute immediate 'alter session set sql_trace = true';
end;

SQL>
 


So far so good but the observant among you may notice that the above is simply a replacement for a couple of posts I published some time ago. You may be wondering what has changed since then. Well, I need to trace sessions for a database user again but this time:

(1) The database produces lots of other trace files which I don't want to look at.
(2) Several OS users log in with this database user but I only want trace files to be produced for one of them, who happens to be called Tobias.

I modified the logon trigger as follows:


SQL> conn ford/fiesta
Connected.
SQL> l
  1  create or replace trigger immediate_trace
  2  after logon on ford.schema
  3  declare
  4    osuser varchar2(200);
  5  begin
  6    select sys_context('USERENV', 'OS_USER')
  7      into osuser from dual;
  8    if osuser = 'NEWPC\Tobias'
  9      then
 10      execute immediate
 11        'alter session set tracefile_identifier = FORD';
 12      execute immediate
 13        'alter session set sql_trace = true';
 14    end if;
 15* end;
SQL> /

Trigger created.

SQL>


Then using my usual OS user i.e. Andrew, I logged into the database user:

SQL> conn ford/fiesta
Connected.
SQL> l
  1  select sys_context('USERENV', 'OS_USER')
  2* from dual
SQL> /

SYS_CONTEXT('USERENV','OS_USER')
--------------------------------------------------

NEWPC\Andrew

SQL> select 'Andrew was here' from dual
  2  /

'ANDREWWASHERE'
---------------
Andrew was here

SQL>


This did not create a trace file.

I went to the Windows 8 account creation screen and set up a user called Tobias. This isn't a Microsoft blog so I'm not going to show you how to do that. I connected to Windows with this new OS user and logged into the database with it:


SQL> conn ford/fiesta
Connected.
SQL> l
  1  select sys_context('USERENV', 'OS_USER')
  2* from dual
SQL> /

SYS_CONTEXT('USERENV','OS_USER')
--------------------------------------------------

NEWPC\Tobias

SQL> select 'Tobias was here' from dual
  2  /

'TOBIASWASHERE'
---------------
Tobias was here

SQL>


This created a trace file, which I could easily see among the other trace files as it was called:

orcl_ora_2548_FORD

... and when I looked inside it, I could see that it had been created by Tobias, not by Andrew:

=====================
PARSING IN CURSOR #4 len=34 dep=0 uid=89 oct=3 lid=89 tim=16850923590446 hv=3733526637 ad='b2ff1f78' sqlid='80cq653g8k63d'
select 'Tobias was here' from dual
END OF STMT
PARSE #4:c=0,e=343,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=16850923590444
EXEC #4:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=16850923590540
FETCH #4:c=0,e=5,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=16850923590565
STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
FETCH #4:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=16850923590715

*** 2016-09-03 20:06:37.565
XCTEND rlbk=0, rd_only=1
=====================

No comments: