SQLServerCentral Article

Logging and Error Handling for SQL Stored Procedures

,

Frequently I have been called upon to write SQL Stored Procedures (SP) that will be run by SQL Agent on a scheduled basis.  Since no one and nothing (like an application front-end) are watching such SPs as they go about their duties, it is incumbent upon the intrepid developer to ensure that they perform their work flawlessly, and in those hopefully few cases where they don’t, leave a trail of bread crumbs through which their failed exploits can be tracked.

Many of my SPs must go through multiple data transformation and manipulation steps.  In theory, the SP could fail at any step, although I take great pains to ensure that they fail on none of them.  Proper usage of TRY/CATCH blocks are essential to making sure that failures are gracefully handled.  Good logging leaves us our trail of bread crumbs, from which forensic analysis of the process failure will hopefully shed light on the cause of the failure. 

I think of my SQL Agent SPs as “batch jobs,” probably because my early years were spent on IBM mainframes running OS MVS, and people that understood IBM’s Job Control Language (JCL) were king.  Much of my nomenclature uses that terminology, so now you know where it comes from.

Let me say right up front, that what I am proposing is one possible way, but certainly not the only way to handle the subject topics.  Improvements can no doubt be made and circumstances may dictate other specifics that I have not covered.  Consider this a foundation for developing your own logging and error trapping standards, in the event that you don’t already have them.

Setting up for Logging

When I do logging, I use a permanent user-defined table that is common for all batch jobs within a database.  Each log entry will contain a row detailing each step for each batch job run.  I’ve identified some specific information useful at each step; however I have not taken this to the next level, which would be to log job-related records in one table and step-related records in a secondary, child table.  Personally I don’t feel that data normalization is necessary, because hopefully you won’t need to use the logs very often.  When you do need to use them, you’ll find that you need to construct ad-hoc queries under time pressure and you don’t want to have to worry about remembering niceties like JOIN criterion and which columns are foreign keys into the parent table.

So let’s define a table that we can use to capture our logging.  In the next section, we’ll get into populating this table with useful information.

CREATE TABLE ProcessLogs
(
    JobStepID       BIGINT          IDENTITY PRIMARY KEY
    ,JobName        VARCHAR(128)    NOT NULL
    ,JobStartDT     DATETIME        NOT NULL
    ,StepStartDT    DATETIME        NOT NULL
    ,StepEndDT      DATETIME        NOT NULL
    ,StepName       VARCHAR(50)     NOT NULL
    ,Row_Count      INT             NOT NULL
    ,[ERROR_NUMBER] INT             NULL
    ,ERROR_MSG      NVARCHAR(4000)  NULL
    ,[ERROR_LINE]   INT             NULL
    ,ERROR_PROC     NVARCHAR(128)   NULL
    ,ERROR_SEV      INT             NULL
    ,[ERROR_STATE]  INT             NULL
    ,Specifics1     SQL_VARIANT     NULL
    ,Specifics2     SQL_VARIANT     NULL
    ,Specifics3     SQL_VARIANT     NULL
    ,Specifics4     SQL_VARIANT     NULL
    ,Spid           INT             NOT NULL
    ,Kpid           INT             NOT NULL
    ,[Status]       VARCHAR(50)     NOT NULL
    ,Hostname       VARCHAR(50)     NOT NULL
    ,[Dbid]         INT             NOT NULL
    ,Cmd            VARCHAR(50)     NOT NULL
);
GO
CREATE TYPE Process_Log AS TABLE
(
    JobName         VARCHAR(128)    NOT NULL
    ,JobStartDT     DATETIME        NOT NULL
    ,StepStartDT    DATETIME        NOT NULL
    ,StepEndDT      DATETIME        NOT NULL
    ,StepName       VARCHAR(50)     NOT NULL
    ,Row_Count      INT             NOT NULL
    ,[ERROR_NUMBER] INT             NULL
    ,ERROR_MSG      NVARCHAR(4000)  NULL
    ,[ERROR_LINE]   INT             NULL
    ,ERROR_PROC     NVARCHAR(128)   NULL
    ,ERROR_SEV      INT             NULL
    ,[ERROR_STATE]  INT             NULL
    ,Specifics1     SQL_VARIANT     NULL
    ,Specifics2     SQL_VARIANT     NULL
    ,Specifics3     SQL_VARIANT     NULL
    ,Specifics4     SQL_VARIANT     NULL
    ,Spid           INT             NOT NULL
    ,Kpid           INT             NOT NULL
    ,[Status]       VARCHAR(50)     NOT NULL
    ,Hostname       VARCHAR(50)     NOT NULL
    ,[Dbid]         INT             NOT NULL
    ,Cmd            VARCHAR(50)     NOT NULL
);
GO

In our CREATE TABLE statement, you’ll see a few columns whose names are also SQL keywords, so these have been [bracketed].

In the second batch, the Data Definition Language (DDL) command is creating a TABLE TYPE.  You may be familiar with TABLE TYPEs being a means to pass a TABLE into a SP.  In this case, we’ll be using it for something else that we’ll describe later.  Notice how its structure is quite similar to our ProcessLogs TABLE, except that the column in ProcessLogs that is the PRIMARY KEY has been omitted.

If you’ve worked with TABLE TYPEs before, you probably already know they can be exposed in SQL Server Management Studio (SSMS) by clicking through the object browser: [Your Database] > Programmability > Types > User-defined Table Types, and from there you can view Columns, Keys, Constraints and Indexes for each defined TABLE TYPE.

You may also want to tuck away into your toolbox the following little script of my own design, which will expose most of the important information, particularly about the columns, for all of your defined TABLE TYPEs.

SELECT TableTypeName=CASE rn WHEN 1 THEN TableTypeName ELSE '' END
    ,ColumnName, ColumnType, max_length
    ,[precision], scale, collation_name
    ,[Nulls Allowed]=CASE is_nullable WHEN 1 THEN 'YES' ELSE 'NO' END
    ,[Is Identity]=CASE is_identity WHEN 1 THEN 'YES' ELSE 'NO' END
    ,[Is In Primary Key]=CASE WHEN index_column_id IS NULL THEN 'NO' ELSE 'YES' END
    ,[Primary Key Constraint Name]=CASE rn WHEN 1 THEN ISNULL(PKName, '') ELSE '' END
FROM
(
    SELECT TableTypeName=a.name, ColumnName=b.name, ColumnType=UPPER(c.name)
        ,b.max_length, b.[precision], b.scale
        ,collation_name=COALESCE(b.collation_name, a.collation_name, '')
        ,rn=ROW_NUMBER() OVER (PARTITION BY a.name ORDER BY b.column_id)
        ,b.column_id
        ,b.is_nullable
        ,b.is_identity
        ,e.index_column_id
        ,PKName = d.name
    FROM sys.table_types a
    JOIN sys.columns b ON b.[object_id] = a.type_table_object_id
    JOIN sys.types c
        ON c.system_type_id = b.system_type_id
    LEFT JOIN sys.key_constraints d ON b.[object_id] = d.parent_object_id
    LEFT JOIN sys.index_columns e
        ON b.[object_id] = e.[object_id] AND e.index_column_id = b.column_id
    WHERE c.system_type_id = c.user_type_id
) a
--WHERE a.TableTypeName = 'Process_Log'
ORDER BY a.TableTypeName, column_id;

Running that script with the WHERE clause uncommented yields a display that looks like this for the TABLE TYPE we just defined.

If you modify the structure of the ProcessLogs TABLE, you should make the identical modifications to the Process_Log TABLE TYPE.  It may be possible to set up a DDL TRIGGER to handle this for you, but that level of sophistication is beyond the scope of this article.

Additional details about the columns we’ve defined will be provided as our discussion progresses.

A Sample Batch Job Stored Procedure

We’ll now move on to creating a template we can use for any SP we’ll develop in the future to perform a batch job or process.  The assumption is that your SP will contain multiple SQL steps, and that some of those steps must be enclosed within a TRANSACTION because they’re doing some kind of change to underlying data tables.  Our skeleton SP will require no parameters, as those will typically be unique to the batch processing requirements, and none are required to support logging or error handling.

Let’s start our SP template with the preamble, or in other words the CREATE PROCEDURE statement along with the DECLAREs we’ll need to do our logging.

Note the similarity between our local variable names and the column names we’ve defined in our process tables.  The only one that is omitted is StepName, and the reason for that will be apparent in a moment.

CREATE PROCEDURE MyBatchJobProcess
AS
BEGIN
    DECLARE @ProcessLog         dbo.Process_Log;
   
    DECLARE @JobName            VARCHAR(128)    = 'MyBatchJobProcess'
        ,@JobStartDT            DATETIME        = GETDATE()
        ,@StepStartDT           DATETIME
        ,@StepEndDT             DATETIME    
        ,@Row_Count             INT
        ,@ERROR_NUMBER          INT             = NULL            
        ,@ERROR_MSG             NVARCHAR(4000)  = NULL 
        ,@ERROR_LINE            INT             = NULL            
        ,@ERROR_PROC            NVARCHAR(128)   = NULL  
        ,@ERROR_SEV             INT             = NULL
        ,@ERROR_STATE           INT             = NULL
        ,@Specifics1            SQL_VARIANT     = NULL
        ,@Specifics2            SQL_VARIANT     = NULL
        ,@Specifics3            SQL_VARIANT     = NULL
        ,@Specifics4            SQL_VARIANT     = NULL
        ,@Spid                  INT             = @@SPID            
        ,@Kpid                  INT            
        ,@Status                VARCHAR(50)   
        ,@Hostname              VARCHAR(50)    
        ,@Dbid                  INT          
        ,@Cmd                   VARCHAR(50);    
    -- Some system process variables that we will include with each log record
    SELECT TOP 1 @Kpid=kpid, @Status=[status], @Hostname=hostname, @Dbid=[dbid], @Cmd=cmd
    FROM master..sysprocesses
    WHERE spid = @Spid;
    -- Other initializations required to handle your SP's functional requirements go here
    WAITFOR DELAY '00:00:01';   -- Remove this once you convert the template to a real SP.
END

In our preamble, we’ve set the @JobStartDT to the current time once, as it will remain the same throughout the execution of our SP.  Likewise @JobName is just the static name of our SP.  All of our local variables prefixed as @ERROR_ (and a few others) are set to NULL and we sincerely hope the @ERROR_ variables will stay that way as our SP executes.  The WAITFOR DELAY statement can be removed when you’ve defined some actual work to be done during the initialization step.

Note that in our preamble we have also defined a local table variable @ProcessLog based on the TABLE TYPE we created earlier.  The reason why we created this as a TABLE TYPE should now be apparent.  We expect to have many batch SPs in our application that will share the same logging table, so we have simplified the declaration of our local table variable using the TABLE TYPE.  We’ll describe why we need this local table variable when we get to error handling a little later.

The intent of the remainder of the code in the preamble should be explained by the comments.

Completing our Logging Template

We will now develop our SP template to include all of the aspects we’ll need for logging.  We’ll show only the SQL code for each part, explaining it in turn (i.e., without the preamble).  At the end we’ll present the entire template.

Looking at the last comment in the preamble, you see that we’ve reserved a place for initializing all the local variables, temp or table variables, etc. that your SP needs to satisfy the functional requirements it is delivering.  After the initialization is complete, we’ll want to create an initial log entry like this:

SELECT @StepStartDT = @JobStartDT, @StepEndDT = GETDATE(), @Row_Count = 0;
INSERT INTO dbo.ProcessLogs
(
    JobName, JobStartDT, StepStartDT, StepEndDT, StepName
    ,Row_Count
    ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
    ,Specifics1, Specifics2, Specifics3, Specifics4
    ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'JOB INITIALIZATION COMPLETE'
    ,@Row_Count
    ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
    ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
    ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;

You can see now why we didn’t need the @StepName local variable – we’ve simply hard-coded the step description in our logging INSERT, and we’ll do this for each log entry.

Depending on what your initialization does, you may want to set @Row_Count to the results (@@ROWCOUNT) from a query or set some of the @Specifics variables to record what went on during the initialization.  You’ll see examples of this as we progress through the next parts of the template.

-- First job step (outside of a transaction)
-- Do the work, SELECT ... INTO ... FROM ... (replace the WAITFOR)
SELECT @StepStartDT = GETDATE();
WAITFOR DELAY '00:00:02';   -- Remove this once you convert the template to a real SP.
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
-- Capture any specifics about the step now.
INSERT INTO dbo.ProcessLogs
(
    JobName, JobStartDT, StepStartDT, StepEndDT, StepNameh
    ,Row_Count
    ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
    ,Specifics1, Specifics2, Specifics3, Specifics4
    ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 1: DESC OF STEP 1'
    ,@Row_Count
    ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
    ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
    ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
SELECT @Specifics1=NULL, @Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL;

The above performs the work of the first step in our job (simulated by the WAITFOR DELAY statement).  You may also want to capture some specifics of the step, like maybe creating a delimited list of the keys of data you retrieved into a temporary table, or the current value of an IDENTITY column using @@IDENTITY.  Now you see why we chose our Specifics columns to be of TYPE SQL_VARIANT – there’s no telling what kind of useful information we might want to save there.  Generally the job step should consist of a single SQL query, so that @Row_Count is indicative of the work performed.

Subsequent job steps, which we’ll include within a TRANSACTION, will be essentially identical to the first.  When we introduce error handling, these will change somewhat.

BEGIN TRANSACTION T1;
-- Second job step (inside of a transaction)
-- Do the work, INSERT/UPDATE/DELETE/MERGE or whatever (replace the WAITFOR)
SELECT @StepStartDT = GETDATE();
WAITFOR DELAY '00:00:03';   -- Remove this once you convert the template to a real SP.
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
-- Capture any specifics about the step now.
INSERT INTO dbo.ProcessLogs
(
    JobName, JobStartDT, StepStartDT, StepEndDT, StepName
    ,Row_Count
    ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
    ,Specifics1, Specifics2, Specifics3, Specifics4
    ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 2: DESC OF STEP 2'
    ,@Row_Count
    ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
    ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
    ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
SELECT @Specifics1=NULL, @Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL;
-- Third job step (inside of a transaction)
-- Do the work, INSERT/UPDATE/DELETE/MERGE or whatever (replace the WAITFOR)
SELECT @StepStartDT = GETDATE();
WAITFOR DELAY '00:00:04';   -- Remove this once you convert the template to a real SP.
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
-- Capture any specifics about the step now.
INSERT INTO dbo.ProcessLogs
(
    JobName, JobStartDT, StepStartDT, StepEndDT, StepName
    ,Row_Count
    ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
    ,Specifics1, Specifics2, Specifics3, Specifics4
    ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 3: DESC OF STEP 3'
    ,@Row_Count
    ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
    ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
    ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
SELECT @Specifics1=NULL, @Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL;
COMMIT TRANSACTION T1;

Finally, at the end of our template we’re going to want to do two things: 1) purge the log history that’s old and probably no longer useful and 2) write a final log entry indicating the job completed.  You’ll need to decide how long to keep your log entries but usually 30-60 days is sufficient.

-- Penultimate job step (purge the log)
SELECT @StepStartDT = GETDATE();
DELETE dbo.ProcessLogs
WHERE JobName = @JobName AND JobStartDT < DATEADD(day, -30, @JobStartDT);
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
INSERT INTO dbo.ProcessLogs
(
    JobName, JobStartDT, StepStartDT, StepEndDT, StepName
    ,Row_Count
    ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
    ,Specifics1, Specifics2, Specifics3, Specifics4
    ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP x: PURGE LOG'
    ,@Row_Count
    ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
    ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
    ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
-- Final step to note job complete
INSERT INTO dbo.ProcessLogs
(
    JobName, JobStartDT, StepStartDT, StepEndDT, StepName
    ,Row_Count
    ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
    ,Specifics1, Specifics2, Specifics3, Specifics4
    ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
)
SELECT @JobName, @JobStartDT, GETDATE(), GETDATE(), 'JOB COMPLETE'
    ,0
    ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
    ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
    ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;

We’ve recorded the total number of process log rows purged in the penultimate step and set step start date/time and step end/date time to the same time on the final step. 

Our complete logging template now looks like this:

CREATE PROCEDURE dbo.MyBatchJobProcess
AS
BEGIN
    DECLARE @ProcessLog         dbo.Process_Log;
   
    DECLARE @JobName            VARCHAR(128)    = 'MyBatchJobProcess'
        ,@JobStartDT            DATETIME        = GETDATE()
        ,@StepStartDT           DATETIME
        ,@StepEndDT             DATETIME    
        ,@Row_Count             INT
        ,@ERROR_NUMBER          INT             = NULL            
        ,@ERROR_MSG             NVARCHAR(4000)  = NULL 
        ,@ERROR_LINE            INT             = NULL            
        ,@ERROR_PROC            NVARCHAR(128)   = NULL  
        ,@ERROR_SEV             INT             = NULL
        ,@ERROR_STATE           INT             = NULL
        ,@Specifics1            SQL_VARIANT     = NULL
        ,@Specifics2            SQL_VARIANT     = NULL
        ,@Specifics3            SQL_VARIANT     = NULL
        ,@Specifics4            SQL_VARIANT     = NULL
        ,@Spid                  INT             = @@SPID            
        ,@Kpid                  INT            
        ,@Status                VARCHAR(50)   
        ,@Hostname              VARCHAR(50)    
        ,@Dbid                  INT          
        ,@Cmd                   VARCHAR(50);    
    -- Some system process variables that we will include with each log record
    SELECT TOP 1 @Kpid=kpid, @Status=[status], @Hostname=hostname, @Dbid=[dbid], @Cmd=cmd
    FROM master..sysprocesses
    WHERE spid = @Spid;
    -- Other initializations required to handle your SP's functional requirements go here
    WAITFOR DELAY '00:00:01';   -- Remove this once you convert the template to a real SP.
    SELECT @StepStartDT = @JobStartDT, @StepEndDT = GETDATE(), @Row_Count = 0;
    INSERT INTO dbo.ProcessLogs
    (
        JobName, JobStartDT, StepStartDT, StepEndDT, StepName
        ,Row_Count
        ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
        ,Specifics1, Specifics2, Specifics3, Specifics4
        ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
    )
    SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'JOB INITIALIZATION COMPLETE'
        ,@Row_Count
        ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
        ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
        ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
    -- First job step (outside of a transaction)
    -- Do the work, SELECT ... INTO ... FROM ... (replace the WAITFOR)
    SELECT @StepStartDT = GETDATE();
    WAITFOR DELAY '00:00:02';   -- Remove this once you convert the template to a real SP.
    SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
    -- Capture any specifics about the step now.
    INSERT INTO dbo.ProcessLogs
    (
        JobName, JobStartDT, StepStartDT, StepEndDT, StepName
        ,Row_Count
        ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
        ,Specifics1, Specifics2, Specifics3, Specifics4
        ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
    )
    SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 1: DESC OF STEP 1'
        ,@Row_Count
        ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
        ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
        ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
    SELECT @Specifics1=NULL, @Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL;
   
    BEGIN TRANSACTION T1;
    -- Second job step (inside of a transaction)
    -- Do the work, INSERT/UPDATE/DELETE/MERGE or whatever (replace the WAITFOR)
    SELECT @StepStartDT = GETDATE();
    WAITFOR DELAY '00:00:03';   -- Remove this once you convert the template to a real SP.
    SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
    -- Capture any specifics about the step now.
    INSERT INTO dbo.ProcessLogs
    (
        JobName, JobStartDT, StepStartDT, StepEndDT, StepName
        ,Row_Count
        ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
        ,Specifics1, Specifics2, Specifics3, Specifics4
        ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
    )
    SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 2: DESC OF STEP 2'
        ,@Row_Count
        ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
        ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
        ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
    SELECT @Specifics1=NULL, @Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL;
    -- Third job step (inside of a transaction)
    -- Do the work, INSERT/UPDATE/DELETE/MERGE or whatever (replace the WAITFOR)
    SELECT @StepStartDT = GETDATE();
    WAITFOR DELAY '00:00:04';   -- Remove this once you convert the template to a real SP.
    SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
    -- Capture any specifics about the step now.
    INSERT INTO dbo.ProcessLogs
    (
        JobName, JobStartDT, StepStartDT, StepEndDT, StepName
        ,Row_Count
        ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
        ,Specifics1, Specifics2, Specifics3, Specifics4
        ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
    )
    SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 3: DESC OF STEP 3'
        ,@Row_Count
        ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
        ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
        ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
    SELECT @Specifics1=NULL, @Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL;
    COMMIT TRANSACTION T1;
   
    -- Penultimate job step (purge the log)
    SELECT @StepStartDT = GETDATE();
    DELETE dbo.ProcessLogs
    WHERE JobName = @JobName AND JobStartDT < DATEADD(day, -30, @JobStartDT);
    SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
    INSERT INTO dbo.ProcessLogs
    (
        JobName, JobStartDT, StepStartDT, StepEndDT, StepName
        ,Row_Count
        ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
        ,Specifics1, Specifics2, Specifics3, Specifics4
        ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
    )
    SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP x: PURGE LOG'
        ,@Row_Count
        ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
        ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
        ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
    -- Final step to note job complete
    INSERT INTO dbo.ProcessLogs
    (
        JobName, JobStartDT, StepStartDT, StepEndDT, StepName
        ,Row_Count
        ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
        ,Specifics1, Specifics2, Specifics3, Specifics4
        ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
    )
    SELECT @JobName, @JobStartDT, GETDATE(), GETDATE(), 'JOB COMPLETE'
        ,0
        ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
        ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
        ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
END

At this time, we could actually run the SP and see some results created in the log.  Note that the run will take about 10 seconds to complete.

Adding Error Handling to our SP Template

Our next step will be to add a skeleton for error handling, using TRY/CATCH, to the code within the TRANSACTION.  We could also include it for initialization or step one, however for this article we’ll omit that, because the important thing to demonstrate is how the transaction should be rolled back in the event an error occurs.

To support error handling, we’ll need to add one additional local variable to those DECLAREd in our preamble.  Initially, we’ll show how to implement only the TRY/CATCH blocks around the work being done for step two:

DECLARE @Error_Count        INT             = 0;
-- Second job step (inside of a transaction)
-- Do the work, INSERT/UPDATE/DELETE/MERGE or whatever (replace the WAITFOR)
SELECT @StepStartDT = GETDATE();
BEGIN TRY
    WAITFOR DELAY '00:00:03';   -- Remove this once you convert the template to a real SP.
    SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
   
    -- Capture any specifics about the step now (within the TRY).
END TRY
BEGIN CATCH
    SELECT @ERROR_NUMBER    = ERROR_NUMBER()
  ,@ERROR_PROC        = ERROR_PROCEDURE()
  ,@ERROR_SEV         = ERROR_SEVERITY()
  ,@ERROR_STATE       = ERROR_STATE()
  ,@ERROR_LINE        = ERROR_LINE()
  ,@ERROR_MSG         = ERROR_MESSAGE()
  ,@Error_Count       = @Error_Count + 1
  ,@Row_Count         = 0
  ,@StepEndDT         = GETDATE();
END CATCH
-- Within the transaction we want to capture logging to the TABLE variable
-- so it can be used upon ROLLBACK
INSERT INTO @ProcessLog
(
    JobName, JobStartDT, StepStartDT, StepEndDT, StepName
    ,Row_Count
    ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
    ,Specifics1, Specifics2, Specifics3, Specifics4
    ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 2: DESC OF STEP 2'
    ,@Row_Count
    ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
    ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
    ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
SELECT @Specifics1=CASE WHEN @Error_Count <> 0 THEN 'STEP SKIPPED DUE TO PRIOR ERRORS' END
    ,@Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL
    ,@ERROR_NUMBER=NULL, @ERROR_MSG=NULL, @ERROR_LINE=NULL
    ,@ERROR_PROC=NULL, @ERROR_SEV=NULL, @ERROR_STATE=NULL;

We have chosen to add a TRY/CATCH block around each SQL step within the transaction.  An alternative approach would put all of those steps into a single TRY block, but personally I like this better because it offers more granular control at a small price in logic complexity.

Note that we are no longer inserting into our permanent ProcessLogs TABLE; rather now we are inserting into our TABLE variable @ProcessLog (declared as TYPE @Process_Log).  The reason we’ve done this is because in the (hopefully) unlikely event we need to ROLLBACK our transaction, we don’t want to lose our logged information (TABLE variables are not subject to ROLLBACKs like a temporary or permanent table would be).

Step three (the second step in the transaction will now be executed only if @Error_Count = 0, and note how at the end of the prior bit of code we put a message into @Specifics1 to show that the next step will be skipped.  Here is how the transaction now looks including checking whether and executing a ROLLBACK when needed.

BEGIN TRANSACTION T1;
-- Second job step (inside of a transaction)
-- Do the work, INSERT/UPDATE/DELETE/MERGE or whatever (replace the WAITFOR)
SELECT @StepStartDT = GETDATE();
BEGIN TRY
    WAITFOR DELAY '00:00:03';   -- Remove this once you convert the template to a real SP.
    SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
    -- Capture any specifics about the step now (within the TRY).
END TRY
BEGIN CATCH
    SELECT @ERROR_NUMBER    = ERROR_NUMBER()
        ,@ERROR_PROC        = ERROR_PROCEDURE()
        ,@ERROR_SEV         = ERROR_SEVERITY()
        ,@ERROR_STATE       = ERROR_STATE()
        ,@ERROR_LINE        = ERROR_LINE()
        ,@ERROR_MSG         = ERROR_MESSAGE()
        ,@Error_Count       = @Error_Count + 1
        ,@Row_Count         = 0
        ,@StepEndDT         = GETDATE();
END CATCH
-- Within the transaction we want to capture logging to the TABLE variable
-- so it can be used upon ROLLBACK
INSERT INTO @ProcessLog
(
    JobName, JobStartDT, StepStartDT, StepEndDT, StepName
    ,Row_Count
    ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
    ,Specifics1, Specifics2, Specifics3, Specifics4
    ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 2: DESC OF STEP 2'
    ,@Row_Count
    ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
    ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
    ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
SELECT @Specifics1=CASE WHEN @Error_Count <> 0 THEN 'STEP SKIPPED DUE TO PRIOR ERRORS' END
    ,@Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL
    ,@ERROR_NUMBER=NULL, @ERROR_MSG=NULL, @ERROR_LINE=NULL
    ,@ERROR_PROC=NULL, @ERROR_SEV=NULL, @ERROR_STATE=NULL;
-- Third job step (inside of a transaction)
IF @Error_Count = 0
BEGIN       
    -- Do the work, INSERT/UPDATE/DELETE/MERGE or whatever (replace the WAITFOR)
    SELECT @StepStartDT = GETDATE();
    BEGIN TRY
        WAITFOR DELAY '00:00:04';   -- Remove this once you convert the template to a real SP.
        SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
        -- Capture any specifics about the step now.
    END TRY
    BEGIN CATCH
        SELECT @ERROR_NUMBER    = ERROR_NUMBER()
            ,@ERROR_PROC        = ERROR_PROCEDURE()
            ,@ERROR_SEV         = ERROR_SEVERITY()
            ,@ERROR_STATE       = ERROR_STATE()
            ,@ERROR_LINE        = ERROR_LINE()
            ,@ERROR_MSG         = ERROR_MESSAGE()
            ,@Error_Count       = @Error_Count + 1
            ,@Row_Count         = 0
            ,@StepEndDT         = GETDATE();
    END CATCH
END
INSERT INTO @ProcessLog
(
    JobName, JobStartDT, StepStartDT, StepEndDT, StepName
    ,Row_Count
    ,[ERROR_NUMBER], ERROR_MSG, [ERROR_LINE], ERROR_PROC, ERROR_SEV, [ERROR_STATE]
    ,Specifics1, Specifics2, Specifics3, Specifics4
    ,Spid, Kpid, [Status], Hostname, [Dbid], Cmd  
)
SELECT @JobName, @JobStartDT, @StepStartDT, @StepEndDT, 'STEP 3: DESC OF STEP 3'
    ,@Row_Count
    ,@ERROR_NUMBER, @ERROR_MSG, @ERROR_LINE, @ERROR_PROC, @ERROR_SEV, @ERROR_STATE
    ,@Specifics1, @Specifics2, @Specifics3, @Specifics4
    ,@Spid, @Kpid, @Status, @Hostname, @Dbid, @Cmd;
-- Set @Specifics1 here like shown after step 2 if > 2 steps in the trans
SELECT @Specifics1=NULL, @Specifics2=NULL, @Specifics3=NULL, @Specifics4=NULL
    ,@ERROR_NUMBER=NULL, @ERROR_MSG=NULL, @ERROR_LINE=NULL
    ,@ERROR_PROC=NULL, @ERROR_SEV=NULL, @ERROR_STATE=NULL;
IF @Error_Count = 0 AND XACT_STATE() = 1 COMMIT TRANSACTION T1;
ELSE IF XACT_STATE() <> 0 ROLLBACK TRANSACTION T1;
   
INSERT INTO ProcessLogs
SELECT * FROM @ProcessLog;

If you now run the SP again and display the log, you’ll see another six records added to the ProcessLogs TABLE because we INSERTed all the rows from our TABLE variable into it.  Our template is now complete and this can be found in the resources file as: CREATE PROCEDURE MyBatchJobProcess.sql.

Simulating Some Real Work and an Error Condition

In our SP template, we have four WAITFOR commands to simulate initialization, the first job step (outside the transaction) and two for our two steps inside of the transaction.  We’ll copy the code for the second step inside of our transaction down to create a third step inside the transaction, so we can see what happens when an error occurs in the second transaction step.  The new WAITFOR in our third transaction step we’ll leave as is, otherwise the other four WAITFORs will be replaced by the following simulated work:

-- Other initializations required to handle your SP's functional requirements go here
--WAITFOR DELAY '00:00:01';
SELECT TOP 5000 @Error_Count = 0 * ROW_NUMBER() OVER (ORDER BY (SELECT NULL))
FROM sys.all_columns a CROSS JOIN sys.all_columns b;
-- First job step (outside of a transaction)
--WAITFOR DELAY '00:00:02';
SELECT *
INTO #Temp
FROM dbo.ProcessLogs;
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
DROP TABLE #Temp;
-- Second job step (inside of a transaction)
--WAITFOR DELAY '00:00:03';  
UPDATE dbo.ProcessLogs
SET JobStartDT = DATEADD(millisecond, 3, JobStartDT);
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();
-- Third job step (inside of a transaction)
--WAITFOR DELAY '00:00:04';
SELECT 1/0;
SELECT @Row_Count = @@ROWCOUNT, @StepEndDT = GETDATE();

Note how we simulate an error in the third job step by doing a division by 0.  We could have used RAISERROR of course, but we didn’t want to go into the details of how to make that work.

The new SP is in the SQL resource file: CREATE PROCEDURE MyBatchJobProcess2.sql.  If you are following along and trying to do this yourself, you should see how close you came to the version in this SQL file.

When we now run this new SP and select all the rows in our ProcessLogs table, we should see something like the following:

Row counts have been recorded now in steps 1 and 2 (13 and 14, respectively), indicating the work that was completed.  Note that the work done in step 2 is actually rolled back because it is inside of the transaction.

Notice how the error number, message and line are all recorded for Step 3.  If we were to scroll right, we’d see the message “STEP SKIPPED DUE TO PRIOR ERRORS” recorded for step 4 in the Specifics1 column.  Effectively, when step 3 failed, step 2 was rolled back and step 4 was skipped.

We have now completed an example of modifying our template to be an actual stored procedure that does some work.

Summary/Recap

We have described how to create a template of a multi-step SQL stored procedure that does logging for each step.  Some of the steps occur inside of a transaction, and some outside.  We have introduced error handling to all steps within the transaction and crafted that error handling so that it carefully records which steps are executed and errors associated with any step that fails.

We hope that the information presented here is useful to our valued readers when you must tackle projects requiring multiple step SPs to do batch work.

Dwain Camps

SQL Enthusiast

Resources

Rate

4.05 (43)

You rated this post out of 5. Change rating

Share

Share

Rate

4.05 (43)

You rated this post out of 5. Change rating