Logging Package

Being able to properly log all details about your processes is essential with regard to backtracking of issues or tuning the performance. With a proper log, you can easily see where the bottleneck is and most often even what needs to be done to tackle it.

Please find the script below with which you can easily trace your processes. Feel free to modify it, distribute it or do whatever you want with it. If you have any improvements you want to share, please feel free to reach me out ūüôā

These scripts consist of 2 objects (Log table and log_package) plus a package as an example of how to use it.

LOG table

CREATE TABLE schema.load_log (	
    RUN_ID NUMBER NOT NULL, 
    RUN_NAME VARCHAR2(255 CHAR) NOT NULL, 
    STEP_ID NUMBER NOT NULL, 
    STEP_DESC VARCHAR2(255 CHAR) NOT NULL, 
    DAY_TO_CHECK DATE, 
    START_DT DATE, 
    STOP_DT DATE, 
    RUN_TIME VARCHAR2(20 CHAR), 
    REC_CNT NUMBER, 
    NOTE VARCHAR2(500 CHAR), 
    ERROR_MSG VARCHAR2(500 CHAR),
    PROXY_USER VARCHAR2(255 CHAR) DEFAULT user NOT NULL,
    USER_NAME VARCHAR2(255 CHAR) DEFAULT nvl(sys_context('USERENV','PROXY_USER'), user) NOT NULL
 ) 
PCTFREE 0
;
 
CREATE UNIQUE INDEX schema.idx_load_log ON schema.load_log(run_id, step_id);


CREATE SEQUENCE schema.load_log_seq
 START WITH     1
 INCREMENT BY   1
 CACHE 100
 NOCYCLE;

Package LOGGER

-- package spec
CREATE OR REPLACE PACKAGE pckg_cw_log_action IS

   PROCEDURE init_log(p_d2check DATE, p_run_name VARCHAR2);
   
   PROCEDURE write_log(
                        p_d2check             DATE,   
                        p_step_description    VARCHAR2,
                        p_start_dt            DATE,
                        p_stop_dt             DATE,
                        p_rec_cnt             NUMBER,
                        p_note                VARCHAR2,
                        p_error_msg           VARCHAR2  
                       );
                       
END pckg_cw_log_action;
/
-- package body
CREATE OR REPLACE PACKAGE BODY pckg_cw_log_action IS
/****************************************************************************************************************************
    NAME:      PCKG_CW_LOG_ACTION
    PURPOSE:    Package to handle logging for other objects
    REVISIONS:
    Ver        Date        Author           Description
    ---------  ----------  ---------------  ---------------------------------------------------------------------------------
    1.0        10/01/2018  OracleWorld      1. Created this package.

****************************************************************************************************************************/
    v_day_to_check date;
    v_run_id number;
    v_step_id number;
    v_step_start date;
    v_step_desc varchar2(100);
    v_run_name varchar2(100);

/****
 *
 *  Calculate the run_time -> the time between start_time and stop_time
 *
 ****/
FUNCTION get_run_time (v_run_start timestamp, v_run_stop timestamp) RETURN string as
   v_run_time interval day to second := v_run_stop - v_run_start;
BEGIN

  return (lpad(to_char(extract (hour from v_run_time)),2,'0'))
            ||':'||
         (lpad(to_char(extract (minute from v_run_time)),2,'0'))
            ||':'||
         (lpad(to_char(extract (second from v_run_time)),2,'0'));
END;


/****
 *
 * write process events in the load_log table
 *
 *****/
PROCEDURE write_log (
                      p_d2check             DATE,
                      p_step_description    VARCHAR2,
                      p_start_dt            DATE,
                      p_stop_dt             DATE,
                      p_rec_cnt             NUMBER,
                      p_note                VARCHAR2,
                      p_error_msg           VARCHAR2
                    )
      IS

      v_error_msg  varchar(1000);
      v_run_time varchar (20);
      v_date_to_check_ch DATE;
BEGIN
   -- calculate the time duration of procedure - if start_dt and stop_dt is filled
   IF p_start_dt IS NOT NULL AND p_stop_dt IS NOT NULL THEN
      v_run_time := get_run_time( p_start_dt, p_stop_dt );
   END IF;

   v_date_to_check_ch := p_d2check;

   -- get next step id
   SELECT nvl(max(step_id),0)+1 INTO v_step_id FROM gas.load_log WHERE run_id = v_run_id;

   -- sync log data
   MERGE INTO schema.load_log trg
   USING (
           SELECT v_run_id as run_id
           , v_run_name as run_name
           , v_step_id as step_id
           , p_step_description as step_description
           , v_date_to_check_ch as day_to_check
           , p_start_dt as start_dt
           , p_stop_dt as stop_dt
           , v_run_time as run_time
           , p_rec_cnt as rec_cnt
           , p_note as note
           , p_error_msg as error_msg
           , user as proxy_user
           , nvl(sys_context('USERENV','PROXY_USER'), user) as user_name
           FROM dual
         ) src
   ON (
        trg.run_id = src.run_id
          AND
        trg.step_desc = src.step_description
      )
   WHEN NOT MATCHED THEN
   INSERT
        (trg.run_id, trg.run_name, trg.step_id, trg.step_desc, trg.day_to_check, trg.start_dt, trg.stop_dt, trg.run_time, trg.rec_cnt, trg.note, trg.error_msg, trg.proxy_user, trg.user_name)
   VALUES
        (src.run_id, src.run_name, src.step_id, src.step_description, src.day_to_check, src.start_dt, src.stop_dt, src.run_time, src.rec_cnt, src.note, src.error_msg, src.proxy_user, src.user_name)
   WHEN MATCHED THEN
     UPDATE SET trg.stop_dt     = src.stop_dt,
                trg.run_time    = src.run_time,
                trg.rec_cnt     = src.rec_cnt,
                trg.note        = src.note,
                trg.error_msg   = src.error_msg,
                trg.proxy_user  = src.proxy_user,
                trg.user_name   = src.user_name
    ;

    COMMIT;

    EXCEPTION
      WHEN OTHERS
      THEN
         ROLLBACK;
         v_error_msg := SQLERRM || ';' || DBMS_UTILITY.FORMAT_ERROR_STACK || DBMS_UTILITY.FORMAT_ERROR_BACKTRACE;

         -- write down the error in log_tbl
         INSERT INTO schema.load_log
                     (run_id, run_name, step_id, step_desc, day_to_check, note, error_msg, proxy_user, user_name)
              VALUES (v_run_id, v_run_name, v_step_id, p_step_description, v_day_to_check, 'Error in procedure write log ' || v_error_msg, v_error_msg, user, nvl(sys_context('USERENV','PROXY_USER'), user));

         COMMIT;

END write_log;


/****
 *
 *   init log
 *
 *****/
PROCEDURE init_log(p_d2check DATE, p_run_name VARCHAR2)
IS
    v_date_to_check_ch varchar2(10);
BEGIN

    v_step_start := sysdate;
    v_step_desc := 'init_log_run';
    v_step_id := 0; -- init step_id

    -- generate unique run_id
    SELECT schema.load_log_seq.nextval INTO v_run_id
    FROM dual;

    v_run_name := p_run_name;

    write_log (p_d2check, v_step_desc, v_step_start, sysdate, 0, '', '');


END init_log;


END;
/

Example of usage

-- package spec
CREATE OR REPLACE PACKAGE pckg_test_log IS
  PROCEDURE run_ctl(p_day_run date);
END pckg_test_log;
/

-- package body
CREATE OR REPLACE PACKAGE BODY pckg_test_log IS
/****************************************************************************************************************************
    NAME:      PCKG_TEST_LOG
    PURPOSE:      Logger demonstration
    REVISIONS:
    Ver        Date        Author           Description
    ---------  ----------  ---------------  ---------------------------------------------------------------------------------
    1.0        10/1/2018  OracleWorld      1. Created this package.
    
    
****************************************************************************************************************************/ 

    -- general variables declaration
    v_day_to_check date;
    v_run_id number;
    v_step_id number;
    v_step_start date;
    v_step_desc varchar2(100);
    v_error_note varchar2(1000);
    v_run_name varchar2(100) := 'LogTester';                                


/****
 *
 *   procedure name + description
 *
 *****/
PROCEDURE prcd_test (
    v_error_code OUT varchar2
    ) 
IS 
    v_sql_rowcount number;
    v_return number;
    v_date_to_check_ch varchar2(10);   
BEGIN 

    v_step_start := sysdate;
    v_step_desc :=  'step test'; -- IMPORTANT!!! This is your single step description (change the description here only)
    
    pckg_cw_log_action.write_log(p_d2check => v_day_to_check, p_step_description => v_step_desc, p_start_dt => v_step_start, p_stop_dt => NULL, p_rec_cnt => 0, p_note => '', p_error_msg => '');

    v_date_to_check_ch := to_char ( v_day_to_check, 'YYYYMMDD' ) ;

    /****
     *
        code goes here
     *
     ******/
    
    
    v_sql_rowcount := sql%rowcount;
    
    commit;   
    
    pckg_cw_log_action.write_log(p_d2check => v_day_to_check, p_step_description => v_step_desc, p_start_dt => v_step_start, p_stop_dt => SYSDATE, p_rec_cnt => v_sql_rowcount, p_note => '', p_error_msg => '');          

    EXCEPTION
    WHEN OTHERS THEN
        ROLLBACK;
        v_error_code := sqlcode ||';'|| sqlerrm; 
        v_error_note := 'Unexpected error';         
        pckg_cw_log_action.write_log(p_d2check => v_day_to_check, p_step_description => v_step_desc, p_start_dt => v_step_start, p_stop_dt => SYSDATE, p_rec_cnt => 0, p_note => v_error_note, p_error_msg => v_error_code); 

END prcd_test;   

/****
 *
 *   procedure name + description
 *
 *****/
PROCEDURE prcd_another_test (
    v_error_code OUT varchar2
    ) 
IS 
    v_sql_rowcount number;
    v_return number;
    v_date_to_check_ch varchar2(10);   
BEGIN 

    v_step_start := sysdate;
    v_step_desc :=  'step another test'; -- IMPORTANT!!! This is your single step description (change the description here only)
    
    pckg_cw_log_action.write_log(p_d2check => v_day_to_check, p_step_description => v_step_desc, p_start_dt => v_step_start, p_stop_dt => NULL, p_rec_cnt => 0, p_note => '', p_error_msg => '');

    v_date_to_check_ch := to_char ( v_day_to_check, 'YYYYMMDD' ) ;

    /****
     *
        code goes here
     *
     ******/
    
    
    v_sql_rowcount := sql%rowcount;
    
    commit;   
    
    pckg_cw_log_action.write_log(p_d2check => v_day_to_check, p_step_description => v_step_desc, p_start_dt => v_step_start, p_stop_dt => SYSDATE, p_rec_cnt => v_sql_rowcount, p_note => '', p_error_msg => '');          

    EXCEPTION
    WHEN OTHERS THEN
        ROLLBACK;
        v_error_code := sqlcode ||';'|| sqlerrm; 
        v_error_note := 'Unexpected error';         
        pckg_cw_log_action.write_log(p_d2check => v_day_to_check, p_step_description => v_step_desc, p_start_dt => v_step_start, p_stop_dt => SYSDATE, p_rec_cnt => 0, p_note => v_error_note, p_error_msg => v_error_code); 

END prcd_another_test;                         





PROCEDURE run_ctl (p_day_run date)
IS

  v_error_code varchar2(1000);
  v_current_run_cnt number; 
  v_ex_custom EXCEPTION;  
  v_ex_already_loaded EXCEPTION;

BEGIN

    v_step_start := sysdate;
    v_day_to_check := p_day_run;           
    
    -- IMPORTANT!!! This is the initialization of the logging (you don’t need to change anything here) 
    ap_it.pckg_cw_log_action.init_log(
                                      p_d2check => v_day_to_check,
                                      p_run_name => v_run_name
                                     );
        
    -- ##########################  
    -- Check if the particular day already exists in the table 
    /*
    SELECT count (*) INTO v_current_run_cnt 
    FROM tbl_target
    WHERE 1=1
    AND date_key = to_char (v_day_to_check , 'YYYYMMDD');
    
    IF v_current_run_cnt > 0 THEN 
        RAISE v_ex_already_loaded;
    ELSE
    */
    --########################## 
    
    
    -- #######
    -- run procedures here 
    -- To keep then chained, let the IF part uncommented (error will be raised and rest of steps will be skipped) 
    -- other wise, comment the IF part out and all steps will proceed           
        prcd_test (v_error_code); IF v_error_code IS NOT NULL THEN  RAISE v_ex_custom; END IF;
            
        prcd_another_test (v_error_code); IF v_error_code IS NOT NULL THEN  RAISE v_ex_custom; END IF; 
    
    --############
    --END IF;   
    --############
    
    
    
    
    EXCEPTION  
              
    WHEN v_ex_custom THEN
        v_error_note := 'ERROR - Custom exception';
        pckg_cw_log_action.write_log(p_d2check => v_day_to_check, p_step_description => v_step_desc, p_start_dt => v_step_start, p_stop_dt => SYSDATE, p_rec_cnt => 0, p_note => v_error_note, p_error_msg => v_error_code);  
             
    WHEN v_ex_already_loaded THEN   
        v_error_note := 'ERROR - Date already loaded - aborting script';        
        pckg_cw_log_action.write_log(p_d2check => v_day_to_check, p_step_description => v_step_desc, p_start_dt => v_step_start, p_stop_dt => SYSDATE, p_rec_cnt => 0, p_note => v_error_note, p_error_msg => v_error_code);  
                                           
    WHEN OTHERS THEN
        ROLLBACK;
        v_error_code := sqlcode ||';'|| sqlerrm;
        v_error_note := 'Unexpected error'; 
        pckg_cw_log_action.write_log(p_d2check => v_day_to_check, p_step_description => v_step_desc, p_start_dt => v_step_start, p_stop_dt => SYSDATE, p_rec_cnt => 0, p_note => v_error_note, p_error_msg => v_error_code);  
        

END run_ctl;

END;
/

You can use this as a template and there is actually no need to change anything there. The only parts you should change are STEP_NAME for each procedure to describe (name) the step (it will be seen in the log), run_name which describes the process name and those parts inside procedures that states “CODE GOES HERE”. The rest is a generic template and assures a smooth run of the package with logging and other stuff. There is one limitation you should know about and it is that all step description must differ within¬†a procedure/package/function if you do not want to overwrite the log. Because the RUN_ID together with STEP_DESCRIPTION is the pairing key; as you can see in the LOGGER package.