Tracing Enabled for Sessions After Instance Restart

12 02 2010

February 12, 2010

An recent thread in the comp.databases.oracle.server Usenet group brought up an interesting question.  What would cause a 10046 trace at level 12 and and errorstack trace at level 3 for event 21700 to be enabled for sessions every time the original poster bounced the Oracle XE instance?  Is this possibly a sign that someone modified an initialization parameter?  Did someone modify the application to enabling tracing to log files?  Is it a bug in Oracle XE? 

Fortunately, the OP provided a portion of one of the trace files, as shown below:

*** SERVICE NAME:(SYS$USERS) 2010-02-02 09:46:36.593
*** SESSION ID:(31.46) 2010-02-02 09:46:36.593
=====================
PARSING IN CURSOR #6 len=69 dep=2 uid=0 oct=42 lid=0 tim=80934443123 hv=3164292706 ad='6688fd70'
alter session set events '10046 trace name context forever, level 12'
END OF STMT
EXEC #6:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934443118
=====================
PARSING IN CURSOR #6 len=71 dep=2 uid=0 oct=42 lid=0 tim=80934681241 hv=681663222 ad='6b8cb08c'
alter session set events '21700 trace name errorstack forever, level 3'
END OF STMT
PARSE #6:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934681236
BINDS #6:
EXEC #6:c=0,e=8426,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934748960
=====================
PARSING IN CURSOR #6 len=34 dep=2 uid=0 oct=42 lid=0 tim=80934753347 hv=1152259314 ad='66a0f058'
alter session set sql_trace = TRUE
END OF STMT
PARSE #6:c=0,e=59,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934753343
BINDS #6:
EXEC #6:c=0,e=29497,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934836162
=====================
PARSING IN CURSOR #7 len=435 dep=1 uid=0 oct=47 lid=0 tim=80934862347 hv=545826169 ad='6b897000'
begin
      execute immediate 'alter session set max_dump_file_size = unlimited';
      execute immediate 'alter session set tracefile_identifier = ''10046via_app''';
      execute immediate 'alter session set events ''10046 trace name context forever, level 12''';
      execute immediate 'alter session set events ''21700 trace name errorstack forever, level 3''';
      execute immediate 'alter session set sql_trace = TRUE';
  end;
END OF STMT

So, from the above trace file, is the tracing caused by:

  • A bug in Oracle XE
  • An application that was modified
  • A modified parameter in the spfile/pfile
  • None of the above

The number following dep= in the trace file is a significant clue.  SQL statements that are submitted by client application code will appear in 10046 trace files with dep= set to 0, so that probably rules out a change to the application code, unless of course the application is executing a PL/SQL block.  The discrete ALTER SESSION statements in the trace file that are wrapped in EXECUTE IMMEDIATE statements probably rules out the possibility of a parameter that was modified in the spfile/pfile and probably also rules out the possibilty of a bug in Oracle XE.  So, what might the next step be to find the cause of the trace files?

Another possibility is either a LOGON or STARTUP trigger that is enabling the trace.  The OP mentioned in the thread that he had enabled tracing earlier to troubleshoot a problem.  The tracing is apparently enabled in a PL/SQL procedure or anonymous PL/SQL block based on the value of dep= and the EXECUTE IMMEDIATE calls, so either a LOGON or STARTUP trigger is a possibility.  To test this possibility, you might execute a SQL statement like this:

SELECT
  TRIGGER_NAME,
  TRIGGER_TYPE,
  TRIGGERING_EVENT
FROM
  DBA_TRIGGERS
WHERE
  OWNER='SYS'
  AND TRIGGER_TYPE IN ('BEFORE EVENT','AFTER EVENT')
  AND SUBSTR(TRIGGERING_EVENT,1,5) IN ('START','LOGON');

TRIGGER_NAME           TRIGGER_TYPE TRIGGERING_EVENT
---------------------- ------------ ----------------
LOGON_FIX_MYAPP_PERF   AFTER EVENT  LOGON
LOGON_CAPTURE_10046    AFTER EVENT  LOGON
ENABLE_OUTLINES_TRIG   AFTER EVENT  STARTUP

If the above returned no rows, there is still a very small chance that a logon trigger or startup trigger is owned by a user other than SYS, so it might make sense to repeat the SQL statement without the OWNER=’SYS’ predicate in the WHERE clause.  In my case the SQL statement returned three rows – two logon triggers and one startup trigger.  The logon trigger name LOGON_CAPTURE_10046 is a significant indicator that a trigger is present that will enable a 10046 trace when the user logs into the database – it helps to use a consistent and descriptive naming convention.

The OP did not show the output of the above SQL statement, but did state that he found and removed a logon trigger that enabled the two traces.  If such a trigger is found, and you know that the trigger does not belong in the database, the trigger may be removed by connecting to the database as the SYS user and dropping the trigger:

DROP TRIGGER LOGON_CAPTURE_10046;







Follow

Get every new post delivered to your Inbox.

Join 143 other followers