Implementing Logging in a DB2 Native SQL Stored Procedure

Introduction

If you have ever done any development in the .NET or JAVA you may have been exposed to a logging utility from a company called Apache called log4net™, for more information there is a link at the end of this article. This is an open source logging utility which can be used to create very extensive logging from within an application. When we were developing COBOL or PLI External Stored Procedures we were able to use the DISPLAY option in those languages.

However, within SQLPL we no longer have the ability to use something like a DISPLAY command and get information from within the execution of our new DB2 Native SQL stored procedures.

What this article is written to describe is how logging can be implemented into DB2 Native SQL stored procedures. It will also describe some of the concepts that are included in the overall design. These concepts were incorporated into the DB2 Native SQL stored procedures from my own experience in using the log4net utility with several C# applications which I have written. My logging examples consist of 3 basic components, and an example on how to add the logging to a DB2 Native SQL stored procedure. The diagram below, shown as Figure 1, identifies the components and how they interact within the scheme of creating a log entry.

Fig 1.jpg

This article will walk you through how you can implement a similar logging methodology from within your DB2 Native SQL stored procedure. There is one drawback to this process. It will only work if you are on DB2 11 for z/OS New Function Mode, or DB2 9.7 for LUW. That is because it requires the ability to use the new Autonomous stored procedure feature.

Task One

Create 2 DB2 tables which will be used to accept and control log entries from your stored procedures. Figure 1 shows a DB2 for z/OS example table that could be used to store log entries from your stored procedures, and a table which allows you to control the level of logging for a program. Figure 2 shows a sample table.

CREATE TABLE “schema”.STORE_PROC_LOG
(
Id INTEGER GENERATED ALWAYS AS IDENTITY PRIMARY KEY NOT NULL
,Date TIMESTAMP (6) WITHOUT TIME ZONE NOT NULL
,Application VARCHAR(50) NOT NULL
,Level VARCHAR(50) NOT NULL
,Logger VARCHAR(255) NOT NULL
,Message VARCHAR(4000) NOT NULL
,Exception VARCHAR(2000) NULL
,NDC VARCHAR(255) NOT NULL
)
IN database.tablespace
APPEND NO              
NOT VOLATILE CARDINALITY
DATA CAPTURE CHANGES   
AUDIT NONE             
CCSID EBCDIC;          

Figure 2 –Example Log table definition

CREATE TABLE “schema”.STORE_PROC_LOG_CNTL
(
Id INTEGER GENERATED ALWAYS AS IDENTITY PRIMARY KEY NOT NULL
,Application VARCHAR(50) NOT NULL
,ProgramName VARCHAR(50) NOT NULL
,LogFlag     SMALLINT NOT NULL
)
IN database.tablespace
APPEND NO              
NOT VOLATILE CARDINALITY
DATA CAPTURE CHANGES   
AUDIT NONE             
CCSID EBCDIC;          

Figure 3 –Example Log Control table definition

Task Two

Create an Autonomous DB2 Native SQL stored procedure which will create the log entry in the STORE_PROC_LOG table. The example below, shown as Figure 3, uses individual parameters as input and can serve as a basis for you to use to create your own stored procedure.

CREATE PROCEDURE SP_LOGGER(IN p_Application VARCHAR(50)
  ,IN p_StorProc VARCHAR(128) 
  ,IN p_Level VARCHAR(50)
  ,IN p_Logger VARCHAR(255)
  ,IN p_Message VARCHAR(4000)
  ,IN p_Exception VARCHAR(2000)
  ,IN p_NDC VARCHAR(255))
    VERSION V1
    ISOLATION LEVEL CS
    RESULT SETS 0
    LANGUAGE SQL
    AUTONOMOUS
    QUALIFIER “schema
 
P1: BEGIN
 
    SELECT LogFlag
      INTO v_LogFlag
      FROM STORE_PROC_LOG_CNTL
     WHERE Application = p_Application
       AND ProgramName = p_StorProc
 
    IF v_LogFlag = 4 THEN
        BEGIN
            INSERT INTO STORE_PROC_LOG
                  (Date
                  ,Application
                  ,Level
                  ,Logger
                  ,Message
                  ,Exception
                  ,NDC)
            VALUES
                  (CURRENT DATE
                  ,p_Application
                  ,p_Level
                  ,p_Logger
                  ,p_Message
                  ,p_Exception
                  ,p_NDC);
        END;
    ELSE
        BEGIN
            IF p_Level <> ‘DEBUG’ THEN
                INSERT INTO STORE_PROC_LOG
                      (Date
                      ,Application
                      ,Level
                      ,Logger
                      ,Message
                      ,Exception
                      ,NDC)
                VALUES
                      (CURRENT DATE
                      ,p_Application
                      ,p_Level
                      ,p_Logger
                      ,p_Message
                      ,p_Exception
                      ,p_NDC);
            END IF;
        END;
    END IF; 
END P1

Figure 4 – DB2 Native SQL Stored procedure to insert logging entries.

Task Three

Implement the code to invoke the new logging stored procedure and to pass it the information that you want to use to create a log entry. In the LOG4NET utility, there are four basic log entries. They are INFO, DEBUG, WARN, and ERROR. There are a couple of additional types; however they would require a lot more logic in your stored procedure to implement them. The basic four will give you more than enough options to satisfy your requirements. The example below, shown as Figure 4, shows how to call your logging stored procedure using individual parameters instead of a XML Document to insert a log entry.

CREATE PROCEDURE SP_LOG_EXAMPLE(IN  p_LocNbr             INTEGER,
                                IN  p_DeptNbr            SMALLINT,
                                IN  p_VndNumericDesc     SMALLINT,
                                IN  p_Pid                CHAR(20),
                                OUT p_SqlCode            INTEGER,
                                OUT p_RtrnCd             SMALLINT,
                                OUT p_MessageText        CHAR(132))
 
    ASUTIME LIMIT 3332200
    LANGUAGE SQL
    ISOLATION LEVEL CS
    PACKAGE OWNER ADADC
    WITH EXPLAIN
    RESULT SETS 1
    QUALIFIER schema
   
P1: BEGIN
 
    DECLARE SQLCODE                 INTEGER;
    DECLARE V_PROCESSNAME        CHAR(30) DEFAULT 'Start of Procedure';
    DECLARE V_MESSAGETEXT        CHAR(132);
    DECLARE v_XMLdoc XML;
    DECLARE v_APPID                   VARCHAR(50);
    DECLARE v_APPNAME                 VARCHAR(50);
    DECLARE v_ERRORLEVEL              VARCHAR(50);
    DECLARE v_Logger                  VARCHAR(255);
    DECLARE v_Message                 VARCHAR(4000);
    DECLARE v_ERRORMSG          VARCHAR(2000);
    DECLARE v_NDC              VARCHAR(255);
    DECLARE v_PROCESSTEXT          VARCHAR(3000);
    DECLARE v_StartTime          TIMESTAMP;
    DECLARE v_ElapsedTime             INTEGER;
    DECLARE v_Ident            VARCHAR(50);
    DECLARE v_IntValue    INTEGER;
   
    ------------------------------------------------------------------------
    -- Declare common condition handlers in case of an exception
    ------------------------------------------------------------------------
    --Declare SQL exception handler
    ------------------------------------------------------------------------
    DECLARE EXIT HANDLER FOR SQLEXCEPTION
        BEGIN
            GET DIAGNOSTICS CONDITION 1
                p_MessageText = MESSAGE_TEXT;
            SET v_ERRORLEVEL = 'ERROR';
            SET v_Ident = 'E1';
            SET v_Logger = v_APPNAME || '/' || v_Ident;
            SET v_PROCESSTEXT = ' ';
            SET v_Message = v_APPNAME || ' - ' || v_PROCESSTEXT;
            SET v_ERRORMSG = p_MessageText;
            CALL SP_LOGGER(RTRIM(v_APPID),
                           RTRIM(v_APPNAME),
                           RTRIM(v_ERRORLEVEL),
                           RTRIM(v_Logger),
                           RTRIM(v_Message),
                           RTRIM(v_ERRORMSG),
                           RTRIM(v_NDC));
            SET v_ERRORLEVEL = 'INFO';
            SET v_Ident = 'P1/A1';
            SET v_Logger = v_APPNAME || '/' || v_Ident;
            SET v_PROCESSTEXT = ' - Finished.';
            SET v_Message = v_APPNAME || ' - ' || v_PROCESSTEXT;
            SET v_ERRORMSG = '';

           
            CALL SP_LOGGER(RTRIM(v_APPID),
                           RTRIM(v_APPNAME),
                           RTRIM(v_ERRORLEVEL),
                           RTRIM(v_Logger),
                           RTRIM(v_Message),
                           RTRIM(v_ERRORMSG),
                           RTRIM(v_NDC));
        END;
           
    ------------------------------------------------------------------------
    -- Declare Not Found condition handler
    ------------------------------------------------------------------------
    DECLARE CONTINUE HANDLER FOR NOT FOUND
        BEGIN
            SET p_SqlCode = SQLCODE;
            SET p_RtrnCd = 7;
            SET v_ERRORLEVEL = 'WARN';
            SET v_Ident = 'W1';
            SET v_Logger = v_APPNAME || '/' || v_Ident;
            SET v_PROCESSTEXT = ' ';
            SET v_Message = v_APPNAME ||
                            ' - ' ||
                            p_SqlCode || ‘ – ‘ ||
                            v_PROCESSTEXT;
            SET v_ERRORMSG = '';
            CALL SP_LOGGER(RTRIM(v_APPID),
                           RTRIM(v_APPNAME),
                           RTRIM(v_ERRORLEVEL),
                           RTRIM(v_Logger),
                           RTRIM(v_Message),
                           RTRIM(v_ERRORMSG),
                           RTRIM(v_NDC));
        END;
       
    ------------------------------------------------------------------------
    -- Declare processing logic
    ------------------------------------------------------------------------
 
    A1: BEGIN
 
        SET v_APPID = 'TST';
        SET v_APPNAME = 'SP_LOG_EXAMPLE';
        SET v_NDC = CHAR(p_LocNbr) || ‘~’ || CHAR(p_DeptNbr) || ‘~’ ||
                    CHAR(p_VndNumericDesc) || ‘~’ || p_Pid ;
 
        SET v_ERRORLEVEL = 'INFO';
        SET v_Ident = 'P1/A1';
        SET v_Logger = v_APPNAME || '/' || v_Ident;
        SET v_PROCESSTEXT = ' - Begin';
        SET v_Message = v_APPNAME || ' - ' || v_PROCESSTEXT;
        SET v_ERRORMSG = '';
       
        CALL SP_LOGGER(RTRIM(v_APPID),
                       RTRIM(v_APPNAME),
                       RTRIM(v_ERRORLEVEL),
                       RTRIM(v_Logger),
                       RTRIM(v_Message),
                       RTRIM(v_ERRORMSG),
                       RTRIM(v_NDC));
       
        SET v_ERRORLEVEL = 'DEBUG';
        SET v_Ident = 'P1/A1';
        SET v_Logger = v_APPNAME || '/' || v_Ident;
        SET v_PROCESSTEXT = ' - Divide b into a';
        SET v_Message = v_APPNAME || ' - ' || v_PROCESSTEXT;
        SET v_ERRORMSG = '';
       
        CALL SP_LOGGER(RTRIM(v_APPID),
                       RTRIM(v_APPNAME),
                       RTRIM(v_ERRORLEVEL),
                       RTRIM(v_Logger),
                       RTRIM(v_Message),
                       RTRIM(v_ERRORMSG),
                       RTRIM(v_NDC));
       
        SET v_IntValue = 5 / 0;       
        SET v_ERRORLEVEL = 'INFO';
        SET v_Ident = 'P1/A1';
        SET v_Logger = v_APPNAME || '/' || v_Ident;
        SET v_PROCESSTEXT = ' - Finished.';
        SET v_Message = v_APPNAME || ' - ' || v_PROCESSTEXT;
        SET v_ERRORMSG = '';
       
        CALL SP_LOGGER(RTRIM(v_APPID),
                       RTRIM(v_APPNAME),
                       RTRIM(v_ERRORLEVEL),
                       RTRIM(v_Logger),
                       RTRIM(v_Message),
                       RTRIM(v_ERRORMSG),
                       RTRIM(v_NDC));
       
    END A1;
END P1

Figure 5 - DB2 Native SQL Stored procedure to demonstrate how to use logging with parameters.

Log Results

The example below, shown as Figure 8, shows what the log information would look like when you query the log table.

Fig 6.jpg

As can be seen by the example output from the Log table, this execution of the sample stored procedure shows that the stored procedure encountered a -802 SQL code due to a divide by zero error.

Conclusion

As you may have noted, I used all four of the log entries to display different types of information. The difference is in how and where I used them. As you may have noticed, I used the ‘INFO’ log type at the beginning and end of the stored procedure. Then within the stored procedure at various points during the execution path, I used the ‘DEBUG’ log type and provided additional information so that the stored procedure execution path can be studied whenever there is a problem with the execution of the stored procedure. I used the ‘WARN’ log type whenever a CONTINUE HANDLER was invoked within the stored procedure indicating that something occurred that was not what was expected, but was not severe enough to warrant termination of the stored procedure execution. Finally, I used the ‘ERROR’ log type whenever an EXIT HANLDER was invoked to terminate the stored procedure execution. By using these four log types in various combinations, you can create some very sophisticated logging for your DB2 Native SQL stored procedures.

The amount of logging which can be added to a native SQL stored procedure is only limited by the requirements of your organization. The more that you add the more insight you will have into the functioning of your stored procedures. Some additional things that can be done to limit the amount of log entries is to add an input parameter to your stored procedure which will allow you to selectively determine if you want to insert ‘DEBUG’ entries. Therefore, those debugging messages are issued only when you are actively testing your stored procedures, and during normal execution all that will be inserted will be ‘INFO’, ‘ERROR’, and ‘WARN’ level log entries.

In addition, the NDC column can be created with anything that you want to add to help you decipher what entered into the log. When I have used the LOG4NET utility in non-DB2 applications I have placed parameter values into that column delimited by a tilde (‘~’) character. This has allowed me to take the output from the log table into a Microsoft Excel spreadsheet, and gave me the ability to slice and dice the information to fit my needs.

The first thing that most people might say is that it will take too much time to implement logging in a stored procedure. That is the same complaint that is given when a developer is tasked to add documentation to an application. However, the time spent in doing both of these tasks are very often recovered the first time that a production issue in a DB2 Native SQL stored procedure requires some research to debug.

I hope that this article will provide an insight into how beneficial it can be to implement a logging methodology into your organizations DB2 Native SQL stored procedures.

For more information on the Apache log4net utility click on this link

Elwin Harrison

Elwin.Harrison@macys.com

1 Like
Recent Stories
Db2 for z/OS locking basics

A Beginners Guide to Locks, Latches, Claims and Drains in DB2 for z/OS by Steve Thomas

Fun with Date Ranges