Tuesday, February 01, 2011

Using Oracle's SERVERERROR to catch unlogged application errors

In an ideal world, when an application hits an exception it will write a log message indicating what it was doing and what error was reported.

In the real world, that doesn't always happen. There are reasons for not showing these details to the user, both from a user-interaction point of view (who wants to see an Oracle error message on a web site) and a security aspect (why tell them what database you use and, potentially, details about table and column structures). They should end up in a log file though.

But if the application developer's haven't done their job, you can do it for them with a SERVERERROR trigger.

If the server process returns an error to the client process the trigger is fired. It doesn't fire for "No Rows Returned" or if the error is caught and handled in PL/SQL. If you have a habit of using PL/SQL procedures which return a success/failure parameter with an error message, then stop. It is a bad idea.

My standard setup includes a table to which I can write debug or log messages.

I use a sequence generated id as a "key", but also have TIMESTAMP column . I also use a whole bunch of SYS_CONTEXT values as column defaults. I love SYS_CONTEXT defaults. Very handy for tracking batch jobs too.

REM Create a default sequence for ordering of data
CREATE SEQUENCE track_seq;

REM Create a table to which log text can be written
CREATE TABLE track_detail
  (ID                       NUMBER,     
  TRACK_TIME                TIMESTAMP,  
  DETAIL                    VARCHAR2(4000),

  ACTION                    VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','ACTION'),
  AUTHENTICATED_IDENTITY    VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','AUTHENTICATED_IDENTITY'),
  AUTHENTICATION_METHOD     VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','AUTHENTICATION_METHOD'),
  JOB_ID                    VARCHAR2(256) DEFAULT

                              NVL(SYS_CONTEXT('USERENV','BG_JOB_ID'),SYS_CONTEXT('USERENV','FG_JOB_ID')),
  CLIENT_IDENTIFIER         VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','CLIENT_IDENTIFIER'),
  CLIENT_INFO               VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','CLIENT_INFO'),
  /* 11gR2 CURRENT_EDITION_ID        VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','CURRENT_EDITION_ID'), */
  CURRENT_SCHEMA            VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','CURRENT_SCHEMA'),
  CURRENT_SQL               VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','CURRENT_SQL'),
  CURRENT_USER              VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','CURRENT_USER'),
  DB_NAME                   VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','DB_NAME'),
  HOST                      VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','HOST'),
  IP_ADDRESS                VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','IP_ADDRESS'),
  LANGUAGE                  VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','LANGUAGE'),
  MODULE                    VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','MODULE'),
  NLS_DATE_FORMAT           VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','NLS_DATE_FORMAT'),
  NLS_DATE_LANGUAGE         VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','NLS_DATE_LANGUAGE'),
  NLS_SORT                  VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','NLS_SORT'),
  NLS_TERRITORY             VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','NLS_TERRITORY'),
  OS_USER                   VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','OS_USER'),
  PROXY_USER                VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','PROXY_USER'),
  SERVER_HOST               VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','SERVER_HOST'),
  SESSION_USER              VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','SESSION_USER'),
  SID                       VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','SID'),
  TERMINAL                  VARCHAR2(256) DEFAULT SYS_CONTEXT('USERENV','TERMINAL')
);

GRANT SELECT ON track_detail TO PUBLIC;



I use an autonomous procedure to do the writing. I'm content with one that only does logging through a simple INSERT...VALUES without querying the database.


REM Create a procedure to write to the log table without interrupting or interfering with the current transaction
CREATE OR REPLACE PROCEDURE track (p_text IN VARCHAR2) IS
  PRAGMA AUTONOMOUS_TRANSACTION;
BEGIN
  INSERT INTO track_detail   (id, track_time, detail)
  VALUES (track_seq.NEXTVAL, SYSTIMESTAMP, p_text);
  COMMIT;
END;
/

REM Grant to all so it can be universally used. You may not want this.
GRANT EXECUTE ON track TO PUBLIC;


The trigger is pretty simple. I use a schema level one because I don't want it firing all over the database. I leave it disabled most of the time. If you have any automated processes for re-enabling disabled triggers, it will be safer to drop it when you don't need it.


It firstly grabs the entire error stack (not just the SQLERRM) but also logs the SQL statement that has failed.

REM -- Create trigger to log any errors from this user's sessions to table
REM -- Only errors raised to the client are picked up.

REM -- Doesn't work in Apex where errors are caught to generate HTML
CREATE OR REPLACE TRIGGER log_err AFTER servererror ON SCHEMA
DECLARE
  v_stack    VARCHAR2(2000) := SUBSTR(DBMS_UTILITY.FORMAT_ERROR_STACK,1,2000);
  v_num      NUMBER;
  v_sql_text ora_name_list_t;
BEGIN
  v_stack := TRANSLATE(v_stack,'''','"');
  track(v_stack);
  v_num  := ora_sql_txt(v_sql_text);
  BEGIN
    FOR i IN 1..v_num LOOP
      track(TO_CHAR(i,'0000')||':'||v_sql_text(i));
    END LOOP;
  EXCEPTION
    WHEN VALUE_ERROR THEN NULL;
  END;
END;
/


Finally a quick test:

TRUNCATE TABLE track_detail;
SELECT * FROM sdsd;
SELECT detail FROM track_detail;


All ready to go. But don't forget to drop or disable that trigger or your log table will get very big. 

3 comments:

Anonymous said...

I'd probably re-raise the error just in case something in the application code outside of the database is going to handle it.

Harel

Gary Myers said...

Ah, I didn't make that clear.

The exception still gets raised to the client even if you do the logging. You don't need to do anything to re-raise it.

It is purely a 'snooper' and won't be noticed by the client app.

Anonymous said...

Hi Gary,

We used a similar trigger see code below which was throwing errors on .net application.

The application is a 3rd party application and someone enabled this trigger and it started throwing errors to the front end application. When we disabled all was fine. Also, we do not have control over the delivered packages. My question is how can enabling a servererror trigger throw errors and not allow the pages to load, Strange!

create or replace
trigger catch_errors_jp
after servererror on database
declare
sql_text ora_name_list_t;
msg_ varchar2(2000) := null;
stmt_ varchar2(2000) := null;
begin

for depth in 1 .. ora_server_error_depth loop
msg_ := msg_ || ora_server_error_msg(depth);
end loop;

for i in 1 .. ora_sql_txt(sql_text) loop
stmt_ := stmt_ || sql_text(i);
end loop;

insert into
caught_errors (dt , username ,msg ,stmt )
values (sysdate, ora_login_user,msg_,stmt_);

commit;
end;

Thanks,
VS.