Error logging

Often logging is done by writing to the database. This leads to a problem. A lot of problems really.    I’ll also ask this;  If logging to the database makes sense why does  Oracle log to the file system?

Can’t connect to the database to see the failure

Something failed and a helpdesk person calls in the middle of the night,  reports an error but cannot tell you more as they have no access to the db.   Or the db is so trashed you normal users cannot login to look at the logs.

Logging a failure you want to rollback

So something happened worthy of logging. You want to rollback but if you log to the db then you have to use Autonomous Transactions.  I would rather not use them in production code.  That is why I came up with this method.

Log tables grow and never go away.

There is so much data it the log table you cannot wade through it.  It grows and is never cleaned up.  Not a big deal but who needs the clutter.

Data logged is inconsistent

You have created a table for logging but the usage is inconsistent. Each developer does an insert directly into the table instead of using the nice APIs you have made for him to use.  The API is there but the developer knows what they are doing so just write to the table.

Logging errors from an application

Some developers will even create a connection to the db just to log an error.

So what to do? Log to the OS file system.  But you say then I can’t access the logs from with in the database!   Well use the EXTERNAL TABLE feature and have it all. All will be revealed, but lets start with the package to produce the file.  I build this in a separate utility schema.

CREATE OR REPLACE PACKAGE dev_log AS
    PROCEDURE debug(   loc VARCHAR2,  msg VARCHAR2);
    PROCEDURE debug(   loc VARCHAR2,  msg VARCHAR2, run_no IN OUT NUMBER ) ;
    PROCEDURE info(    loc VARCHAR2,  msg VARCHAR2);
    PROCEDURE info(    loc VARCHAR2,  msg VARCHAR2, run_no IN OUT NUMBER ) ;
    PROCEDURE warning( loc VARCHAR2, err VARCHAR2,  msg VARCHAR2);
    PROCEDURE warning( loc VARCHAR2, err VARCHAR2,  msg VARCHAR2, run_no IN OUT NUMBER ) ;
    PROCEDURE error(   loc VARCHAR2, err VARCHAR2,  msg VARCHAR2);
    PROCEDURE error(   loc VARCHAR2, err VARCHAR2,  msg VARCHAR2, run_no IN OUT NUMBER ) ;
    PROCEDURE daily_reset;
END ;

-- Also create the needed SEQ 
CREATE SEQUENCE  LOG_RUN#;

There are four overloaded API’s and one utility API. More flexibility could be exposed but experience has shown this is a good set to expose to the developers. The parameters are:

  • loc – This is the module making the call
  • msg – a free form message suitable for for the call
  • err – The Oracle error value
  • run_no – To be used if a set of messages are sent so they can be tracked.

The first three should be straight forward, but the use of run_no might need a bit more explications. Suppose your were writing files in a LOOP and wanted to track when you committed.

cntr NUMBER :=1;
myRun NUMBER :=NULL'
LOOP 
    ….
    IF mod( cntr, 100 ) = 0 then 
commit;
dev_log.info( 'MyBatch' , 'committed '|| cntr ||' records so far', myRun  );
    ENDIF
END LOOP

If NULL is passed in a value is assigned and returned. The first time through the loop myRun is NULL so dev_log will assign a number and then in subsequent loops the same value will be used.   Of course you can always pass in zero or an value of your choosing.

Now for the code for the body.

CREATE OR REPLACE PACKAGE BODY dev_log as
   PROCEDURE write_log( filename VARCHAR2, buf VARCHAR2, write_flag CHAR DEFAULT 'A') AS
      F1 UTL_FILE.FILE_TYPE;
   BEGIN
      F1 := Utl_file.Fopen('LOGDIR',Filename,write_flag,32767);
      Utl_file.Put(F1, Buf );
      Utl_file.Fclose( F1 );
   END;

    PROCEDURE any_log( sev VARCHAR2, loc VARCHAR2 ,
     err VARCHAR2, msg VARCHAR2, run_no IN OUT NUMBER )  IS

      filename VARCHAR2( 64 );
      buf      VARCHAR2(32000);
      dt       VARCHAR2(32);
      st       VARCHAR2(32) := to_char(SYSDATE, 'yyyy-mm-dd hh24:MI:SS');
      tab      VARCHAR2(2)  := chr(9);
      ai       VARCHAR2(64) := sys_context('USERENV', 'CLIENT_INFO' );
      sid      VARCHAR2(64) := sys_context('USERENV', 'SID' );
      ser      VARCHAR2(64) := sys_context('USERENV', 'SESSIONID' );
      instance NUMBER        := sys_context('USERENV', 'INSTANCE');
      sev_i    VARCHAR2(32) := upper( sev );
      pdir     VARCHAR2(32) := 'LO' || instance ;
      nl       VARCHAR2(2)  :=chr(13);
   BEGIN
     IF run_no IS NULL THEN
     run_no := log_run#.NEXTVAL;
     END IF;
    SELECT to_char( SYSDATE, 'Dy') INTO dt FROM dual;
    filename := 'dev_util.log.'||dt;
    Buf := Sev_i  || tab ||
       St  || tab ||
      Loc  || tab ||
       Run_no  || tab ||
      Err  || tab ||
       Ai  || tab ||
      Sid  || tab ||
      Ser  || tab ||
      Msg  || nl ;

       write_log( Filename, buf ) ;
    END;



    PROCEDURE ensure_exists AS
       filename VARCHAR2( 64 );
       dt VARCHAR2(32);
    BEGIN
      FOR cntr IN 1..6 LOOP
 SELECT to_char( SYSDATE-cntr, 'Dy') INTO dt FROM dual;
 filename := 'dev_util.log.'||dt;
 write_log( Filename, NULL );

      END LOOP;
    END;


    PROCEDURE daily_reset AS
       F1 UTL_FILE.FILE_TYPE;
       filename VARCHAR2( 64 );
       buf VARCHAR2(32000);
       dt VARCHAR2(32);
       st VARCHAR2(32) := to_char(SYSDATE, 'yyyy-mm-dd hh24:MI:SS');
       tab  VARCHAR2(4) := chr(9);
       ai varchar2(64) := sys_context('USERENV', 'CLIENT_INFO' );
       sid varchar2(64) := sys_context('USERENV', 'SID' );
       ser varchar2(64) := sys_context('USERENV', 'SESSIONID' );
       instance NUMBER := sys_context('USERENV', 'INSTANCE');
       sev_i VARCHAR2(32) := 'RESET';
       nl CHAR(2) :=chr(13);
    BEGIN
       ensure_exists;
     SELECT to_char( SYSDATE, 'Dy') INTO dt FROM dual;
     filename := 'dev_util.log.'||dt;
     Buf := Sev_i  || tab ||
      'RESET'    || tab ||
        0    || tab ||
  'ORA-00000'    || tab ||
        Ai    || tab ||
       Sid    || tab ||
       Ser    || tab ||
'Daily Reset'    || nl;
     write_log( Filename, buf, 'W' );
    END;



    PROCEDURE debug(   loc VARCHAR2,  msg VARCHAR2) AS
       run_no NUMBER :=0;
    BEGIN
       debug( loc, msg, run_no);
    END;
    PROCEDURE debug(   loc VARCHAR2,  msg VARCHAR2, run_no IN OUT NUMBER ) AS
    BEGIN
       any_log( 'DEBUG', loc, 'ORA-00000', msg,run_no );
    END;



    PROCEDURE info(    loc VARCHAR2,  msg VARCHAR2) AS
       run_no NUMBER :=0;
    BEGIN
       info( loc, msg,run_no);
    END;
    PROCEDURE info(loc VARCHAR2,  msg VARCHAR2, run_no IN OUT NUMBER ) AS
    BEGIN
       any_log( 'INFO', loc, 'ORA-00000', msg,run_no );
    END;


    PROCEDURE warning( loc VARCHAR2, err VARCHAR2,  msg VARCHAR2) AS
       run_no NUMBER :=0;
    BEGIN
       warning( loc, err,  msg, run_no );
    END;
    PROCEDURE warning( loc VARCHAR2, err VARCHAR2,  msg VARCHAR2, run_no IN OUT NUMBER ) AS
    BEGIN
       any_log( 'WARNING', loc, err, msg,run_no );
    END;


    PROCEDURE error(   loc VARCHAR2, err VARCHAR2,  msg VARCHAR2) AS
       run_no NUMBER :=0;
    BEGIN
       error(loc, err, msg, run_no );
    END;
    PROCEDURE error(   loc VARCHAR2, err VARCHAR2,  msg VARCHAR2, run_no IN OUT NUMBER ) AS
    BEGIN
       any_log( 'ERROR', loc, err, msg,run_no );
    END;
END ;

 

 

So there are several functions that are not exposed:

 

  • write_log
  • log_any
  • daily_reset
  • ensure_exists

 

write_log does that, takes a filename and a string and writes it to the file.

 

 

 

log_any is called by all the exposed API, formats the data as a tab delimited string and calls write_log.  It also captures some environmental data using the the SYS_CONTEXT function.

If the application has written Application Info then it is captured as is USER, SID, and Serial

 

daily_reset, create an entry early in the day and is called from a job.

 

ensure_exists is called by daily_reset and write a non-record  to the file. This makes sure the file is there. If it is not then the EXTERNAL table fails.

So to create a default set of files

var jobno number
exec dbms_job.submit( :jobno, 'begin dev_log.daily_reset; end;' , trunc(sysdate+1), 'trunc(sysdate+1)' ) ;
commit; 
exec dbms_job.run( :jobno ) ; 

Now create the table, so the data can be seen in the database.

CREATE TABLE db_logs ( 
    sev varchar2(24), 
    time_log date, 
    module varchar2(128), 
    run_no NUMBER  , -- Sequence 
    err_no varchar2(16), -- Oracle Error like ORA-06502 ! 
    ai varchar2(64),     -- additional infor 
    sid number, 
    serial number, 
    msg varchar2(4000) )  ORGANIZATION EXTERNAL( 
       TYPE ORACLE_LOADER 
       DEFAULT DIRECTORY LOGDIR 
              ACCESS PARAMETERS 
       ( 
         records delimited by newline 
         badfile LOGDIR:'dev_logt%a_%p.bad' 
         logfile LOGDIR:'dev_log%a_%p.log' 
         fields terminated BY   '       ' 
         missing field values are null 
         ( sev, time_log char date_format date mask "yyyy-mm-dd hh24:MI:SS", module, run_no, err_no, ai, sid, serial, msg ) 
       ) 
       location ( 
 'dev_util.log.Mon', 
 'dev_util.log.Tue',
 'dev_util.log.Wed',
 'dev_util.log.Thu',
 'dev_util.log.Fri',
 'dev_util.log.Sat',
 'dev_util.log.Sun' )  ) 
PARALLEL 
     REJECT LIMIT UNLIMITED 
/

Now adding the calls, something like the following to your code

begin
...
   dev_log.info( 'My Module' ,  'This is a test ' );
...
EXCEPTION WHEN OTHERS -- use of WHEN OTHERS is not encouraged 
   THEN  
     dev_log.waring( 'My Module' , sqlcode, sqlerrm  );
     RAISE;
END;

Create appropriate synonyms and grant to public, or individual schema and you good to go.    This is a method I have used since 9i and has served me well.   This is just a start on logging.  There may be more data points your organization needs to track.  Maybe you want longer term retention, you could add code to daily_reset to permanently save some records based on some criteria.  Add an API in your Java code and log all the Java errors.

 

 

Bookmark the permalink.

Leave a Reply