This segment of the framework builds onto what we have already created in Part 2 of the T-SQL Framework. That post showed you how to build the Error Engine, or build in tasks to do our error handling for us. In building the T-SQL Activity Log, we will leverage some of the structures and processes we have already built and tested. If you have not gone through and created the initial T-SQL Framework from part two, please go back and do that now.
The Activity Log will log every routine we create. This includes logging:
- The start of the routine
- The name of the routine
- Who initiated the process
- Where the process was started
- When the process started
- Error codes if any that the process encountered (this will be from our error engine we developed in part 2)
- When the routine completed so we will have a baseline at least in time of how long it takes the process to run
Create the T-SQL Activity Log Table
Let’s jump right in and create the table we will need in order to build the T-SQL activity log information, shown in code:
/*============================================================================*/
/****** Object: Table [dbo].[TU_ActivityLog] Script Date: 2019-10-15 ******/
/*============================================================================*/
PRINT CHAR(10) + CHAR(13) + 'Creating table [dbo].[TU_ActivityLog].';
CREATE TABLE [dbo].[TU_ActivityLog]
(
[ActivityLog_ID] [BIGINT] IDENTITY (1, 1) NOT NULL
CONSTRAINT [PK_ActivityLog_ID]
PRIMARY KEY CLUSTERED
,[System] [NVARCHAR](100) COLLATE SQL_Latin1_General_CP1_CI_AS NULL
,[Error_ID] [INT] NULL
CONSTRAINT [FK_TU_ActivityLog_Error_ID]
FOREIGN KEY ([Error_ID])
REFERENCES [TU_Error]([Error_ID])
,[DB] [NVARCHAR](100) COLLATE SQL_Latin1_General_CP1_CI_AS NULL
,[Obj] [NVARCHAR](100) COLLATE SQL_Latin1_General_CP1_CI_AS NULL
,[App] [NVARCHAR](100) COLLATE SQL_Latin1_General_CP1_CI_AS NULL
,[USER] [NVARCHAR](100) COLLATE SQL_Latin1_General_CP1_CI_AS NULL
,[SPID] [NVARCHAR](100) COLLATE SQL_Latin1_General_CP1_CI_AS NULL
,[Description] [NVARCHAR](512) COLLATE SQL_Latin1_General_CP1_CI_AS NULL
,[StartTime] [DATETIME] NULL
,[EndTime] [DATETIME] NULL
,[Active] [BIT] NOT NULL
CONSTRAINT [DF_ActivityLog_Active]
DEFAULT (1)
,[DateCreated] [DATETIME] NOT NULL
CONSTRAINT [DF_ActivityLog_DateCreated]
DEFAULT GETDATE()
,[DateModified] [DATETIME] NOT NULL
CONSTRAINT [DF_ActivityLog_DateModified]
DEFAULT GETDATE()
) ON [PRIMARY];
/* FK Index */
CREATE NONCLUSTERED INDEX idxfk_TU_ActivityLog_Error_ID ON [TU_ActivityLog]([Error_ID])Looking at the table definition, you can see we have several columns that were variables in the original framework when we created the error engine. We used most of those variables to define our customized error if we went into the begin catch part of the procedure orchestrated through the template we developed. The point is that we can use the variables outside of the scope of just the error handling.
We are reusing variables that we defined in the framework to facilitate information between features but doing so in a way that all roads lead back to Rome. When you use this methodology, you will find it makes your code simpler and easier for others to read. Most importantly, if we have developed and tested variables from one feature that we need in another, we don’t have to retest if we did our job correctly the first time. That cuts down on development/troubleshooting time as well. Enough about theory and methodology, let’s get back to some development!
Create Two Procedures
The next thing we need are two procedures: one to insert into the activity log, and another to update the activity log when we are done with the process — either at a successful completion or at the end of our Begin Catch if there was an error. The first stored procedure is the Insert, shown below:
USE DBCATCH
GO
IF EXISTS(SELECT 1
FROM [dbo].[sysobjects] (NOLOCK)
WHERE [id] = OBJECT_ID(N'[dbo].[PU_ActivityLog_ADD]')
AND OBJECTPROPERTY([id], N'IsProcedure') = 1)
BEGIN
DROP PROCEDURE [dbo].[PU_ActivityLog_ADD];
PRINT '<<< DROPPED PROCEDURE [dbo].[PU_ActivityLog_ADD] >>>';
END
GO
CREATE PROC [dbo].[PU_ActivityLog_ADD]
@p_System [NVARCHAR](100) = NULL
,@p_Error_ID [INT] = NULL
,@p_DB [NVARCHAR](100) = NULL
,@p_Obj [NVARCHAR](100) = NULL
,@p_App [NVARCHAR](100) = NULL
,@p_User [NVARCHAR](100) = NULL
,@p_SPID [NVARCHAR](100) = NULL
,@p_Description [NVARCHAR](512) = NULL
,@p_StartTime [DATETIME] = NULL
,@p_EndTime [DATETIME] = NULL
,@p_ActivityLog_ID [BIGINT] OUTPUT
WITH ENCRYPTION
AS
/*************************************************************************************************/
/* Name : PU_ActivityLog_ADD */
/* Version : 1.0 */
/* Author : Jared Kirkpatrick */
/* Date : 2019-10-15 */
/* Description : Adds a record to the Activity Log */
/*************************************************************************************************/
/* Date : Version: Who: Description */
/*************************************************************************************************/
/* 2019-10-15 : 1.0 : REB: Initial Release. */
/*************************************************************************************************/
SET NOCOUNT ON
/* Declare Variables */
DECLARE @v_Error [INT]
,@v_MSG [NVARCHAR](2500);
BEGIN TRANSACTION
BEGIN TRY
INSERT [DBCATCH].[dbo].[TU_ActivityLog]
(
[System],
[Error_ID],
[DB],
[Obj],
[App],
[USER],
[SPID],
[Description],
[StartTime],
[EndTime]
)
VALUES
(
@p_System,
@p_Error_ID,
@p_DB,
@p_Obj,
@p_App,
@p_User,
@p_SPID,
@p_Description,
@p_StartTime,
@p_EndTime
)
SELECT @p_ActivityLog_ID = @@IDENTITY;
END TRY
BEGIN CATCH
SELECT @p_Obj = '[DBCATCH].[dbo].[TU_ActivityLog]';
SELECT @v_Error = 100001
,@v_MSG = CONVERT(NVARCHAR(2500),
'Error: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_NUMBER(), -1)) +
' Severity: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_SEVERITY(), -1)) +
' State: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_STATE(), -1)) +
' Line: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_LINE(), -1)) +
' Procedure: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_PROCEDURE(), @p_Obj)) +
' MSG: Error Inserting into [DBCATCH].[dbo].[TU_ActivityLog] with error:' + ISNULL(ERROR_MESSAGE(), ''));
EXEC [DBCATCH].[dbo].[PU_ErrorLog_ADD]
@p_Error_ID = @v_Error,
@p_System = @p_System,
@p_DB = @p_DB,
@p_Obj = @p_Obj,
@p_App = @p_App,
@p_User = @p_User,
@p_ErrorMsg = @v_MSG;
ROLLBACK TRAN;
RETURN @v_Error;
END CATCH;
COMMIT TRANSACTION;
GO
IF OBJECT_ID('[dbo].[PU_ActivityLog_ADD]') IS NOT NULL
BEGIN
PRINT '<<< CREATED PROCEDURE [dbo].[PU_ActivityLog_ADD] >>>';
END;
ELSE
BEGIN
PRINT '<<< FAILED TO CREATE PROCEDURE [dbo].[PU_ActivityLog_ADD] >>>';
END;
GOTake a closer look at the error and error message in the “begin try” part of the procedure.
As you can see, we have changed the error number to match what we defined as our errors in TU_Error, as this error deals with an Insert. We also customized the error message to show it came while inserting into the activity log. The rest of the error will capture the server’s definition but this way we have set up our visuals where, if we see this in the error log, we will know where to look for answers.
We will do this with the update as well. Every time the code runs, it is running with a customized error handler to the routine at hand. Just a few seconds of time makes this a truly powerful tool, not only in development but through the lifecycle of the software process running on the server.
The Update Procedure
Next is the update procedure:
USE DBCATCH
GO
IF EXISTS(SELECT 1
FROM [dbo].[sysobjects] (NOLOCK)
WHERE [id] = OBJECT_ID(N'[dbo].[PU_ActivityLog_UPD]')
AND OBJECTPROPERTY([id], N'IsProcedure') = 1)
BEGIN
DROP PROCEDURE [dbo].[PU_ActivityLog_UPD];
PRINT '<<< DROPPED PROCEDURE [dbo].[PU_ActivityLog_UPD] >>>';
END
GO
CREATE PROC [dbo].[PU_ActivityLog_UPD]
@p_ActivityLog_ID [BIGINT],
@p_System [NVARCHAR](100) = NULL,
@p_Error_ID [INT] = NULL,
@p_DB [NVARCHAR](100) = NULL,
@p_Obj [NVARCHAR](100) = NULL,
@p_App [NVARCHAR](100) = NULL,
@p_User [NVARCHAR](100) = NULL,
@p_Description [NVARCHAR](512) = NULL,
@p_StartTime [DATETIME] = NULL,
@p_EndTime [DATETIME] = NULL,
@p_Active [BIT] = 0,
@p_DateModified [DATETIME]
WITH ENCRYPTION
AS
/*************************************************************************************************/
/* Name : PU_ActivityLog_UPD */
/* Version : 1.0 */
/* Author : Jared Kirkpatrick */
/* Date : 2019-05-24 */
/* Description : Updating the activity log */
/*************************************************************************************************/
/* Date : Version: Who: Description */
/*************************************************************************************************/
/* 2019-05-24 : 1.0 : REB: Initial Release. */
/*************************************************************************************************/
SET NOCOUNT ON;
/* Declare Variables */
DECLARE @v_Error [INT]
,@v_MSG [NVARCHAR](2500);
BEGIN TRANSACTION
BEGIN TRY
UPDATE [DBCATCH].[dbo].[TU_ActivityLog] WITH (ROWLOCK)
SET [System] = ISNULL(@p_System, [System]),
[Error_ID] = ISNULL(@p_Error_ID, [Error_ID]),
[DB] = ISNULL(@p_DB, [DB]),
[Obj] = ISNULL(@p_Obj, [Obj]),
[App] = ISNULL(@p_App, [App]),
[USER] = ISNULL(@p_User, [USER]),
[Description] = ISNULL(@p_Description, [Description]),
[StartTime] = ISNULL(@p_StartTime, [StartTime]),
[EndTime] = ISNULL(@p_EndTime, [EndTime]),
[Active] = ISNULL(@p_Active, [Active]),
[DateModified] = ISNULL(@p_DateModified, GETDATE())
WHERE [ActivityLog_ID] = @p_ActivityLog_ID;
END TRY
BEGIN CATCH
SELECT @p_Obj = '[DBCATCH].[dbo].[TU_ActivityLog]';
SELECT @v_Error = 100002
,@v_MSG = CONVERT(NVARCHAR(2500),
'Error: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_NUMBER(), -1)) +
' Severity: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_SEVERITY(), -1)) +
' State: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_STATE(), -1)) +
' Line: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_LINE(), -1)) +
' Procedure: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_PROCEDURE(), @p_Obj)) +
' MSG: Error Updating [DBCATCH].[dbo].[TU_ActivityLog] with error:' + ISNULL(ERROR_MESSAGE(), ''));
EXEC [DBCATCH].[dbo].[PU_ErrorLog_ADD]
@p_Error_ID = @v_Error,
@p_System = @p_System,
@p_DB = @p_DB,
@p_Obj = @p_Obj,
@p_App = @p_App,
@p_User = @p_User,
@p_ErrorMsg = @v_MSG;
ROLLBACK TRAN;
RETURN @v_Error;
END CATCH;
COMMIT TRANSACTION;
GO
IF OBJECT_ID('[dbo].[PU_ActivityLog_UPD]') IS NOT NULL
BEGIN
PRINT '<<< CREATED PROCEDURE [dbo].[PU_ActivityLog_UPD] >>>';
END;
ELSE
BEGIN
PRINT '<<< FAILED TO CREATE PROCEDURE [dbo].[PU_ActivityLog_UPD] >>>';
END;
GO
Once again, we changed the error number and the custom message for this routine. Plan on always updating these two areas on the template as you create each new procedure. Speaking of the template, it’s time to add some code to the template so that we can add this feature, writing to the activity log.
USE DBCATCH
GO
IF EXISTS(SELECT 1
FROM [dbo].[sysobjects] (NOLOCK)
WHERE [id] = OBJECT_ID(N'[dbo].[<Name, SYSNAME, PU_DB_ADD>]')
AND OBJECTPROPERTY([id], N'IsProcedure') = 1)
BEGIN
DROP PROCEDURE [dbo].[<Name, SYSNAME, PU_DB_ADD>];
PRINT '>>> DROPPED PROCEDURE [dbo].[<Name, SYSNAME, PU_DB_ADD>] <<<';
END
GO
CREATE PROC [dbo].[<Name, SYSNAME, PU_DB_ADD>]
WITH ENCRYPTION
AS
/******************************************************/
/* Name : <Name, SYSNAME, PU_DB_ADD> */
/* Version : 1.0 */
/* Author : */
/* Date : 2019-07-24 */
/* Description : */
/******************************************************/
/* Date : Version: Who: Description */
/******************************************************/
/* 2019-07-24 : 1.0 : : Initial Release. */
/******************************************************/
SET NOCOUNT ON;
/* Declare Variables */
DECLARE @v_Error [INT]
,@v_MSG [NVARCHAR](500)
,@v_DB [NVARCHAR](100)
,@v_Obj [NVARCHAR](100)
,@v_App [NVARCHAR](100)
,@v_User [NVARCHAR](100)
,@v_Spid [NVARCHAR](100)
,@v_ActivityLog_ID [INT]
,@v_ADesc [NVARCHAR](512)
,@v_Now [DATETIME]
,@v_LastErrorDate [DATETIME]
,@v_SystemName [NVARCHAR](100)
,@v_RowCount [INT]
,@v_Count [INT]
,@v_MinINT [INT]
,@v_MaxINT [INT]
,@v_Version [INT]
,@v_KeyWord [SYSNAME]
,@v_MSSQL_ID [INT]
,@v_Domain [NVARCHAR](100)
,@v_Batch_Type_ID [INT]
,@v_System [NVARCHAR](100)
,@v_SQL [NVARCHAR](4000)
,@v_UserName [NVARCHAR](100)
,@v_PW [NVARCHAR](100)
,@v_Debug [INT];
SELECT @v_Now = GETDATE()
,@v_DB = DB_NAME()
,@v_Obj = '[DBCATCH].[dbo].[<Name, SYSNAME, PU_DB_ADD>]'
,@v_App = APP_NAME()
,@v_User = ISNULL(ORIGINAL_LOGIN(), USER_NAME())
,@v_Spid = CONVERT([NVARCHAR](25), @@SPID)
,@v_System = HOST_NAME()
,@v_Debug = 0;
/* Create Temp Tables */
IF @v_Debug = 1
BEGIN -- debug = 1 Ref: 1
SELECT 'REF:1 - Define Static Variables';
SELECT @v_Now AS [GETDATE]
,@v_DB AS [DB]
,@v_Obj AS [OBJ]
,@v_App AS [APP]
,@v_User AS [USER]
,@v_Spid AS [SPID];
END; -- debug = 1
/* Start the activity_log */
EXEC [DBCATCH].[dbo].[PU_ActivityLog_ADD]
@p_Error_ID = NULL,
@p_System = @v_System,
@p_DB = @v_DB,
@p_Obj = @v_Obj,
@p_App = @v_App,
@p_User = @v_User,
@p_Spid = @v_Spid,
@p_Description = NULL,
@p_StartTime = @v_Now,
@p_EndTime = NULL,
@p_ActivityLog_ID = @v_ActivityLog_ID OUTPUT;
BEGIN TRY
--==>> Start Code Here!
END TRY
BEGIN CATCH
SELECT @v_Error = 100000
,@v_MSG = CONVERT(NVARCHAR(2500),
'Error: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_NUMBER(), -1)) +
' Severity: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_SEVERITY(), -1)) +
' State: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_STATE(), -1)) +
' Line: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_LINE(), -1)) +
' Procedure: ' + CONVERT([NVARCHAR](255), ISNULL(ERROR_PROCEDURE(), @v_Obj)) +
' MSG: Error from [DBCATCH].[dbo].[TU_Errorlog] with error:' + ISNULL(ERROR_MESSAGE(), ''));
EXEC [DBCATCH].[dbo].[PU_ErrorLog_ADD]
@p_Error_ID = @v_Error,
@p_System = @v_System,
@p_DB = @v_DB,
@p_Obj = @v_Obj,
@p_App = @v_App,
@p_User = @v_User,
@p_ErrorMsg = @v_MSG;
EXEC [DBCATCH].[dbo].[PU_ActivityLog_UPD]
@p_ActivityLog_ID = @v_ActivityLog_ID,
@p_EndTime = @v_Now,
@p_Error_ID = @v_Error,
@p_Active = 0,
@p_Description = @v_MSG,
@p_DateModified = @v_Now;
SELECT @v_Msg;
RETURN @v_Error;
END CATCH;
EOF:
/* Cleanup */
/* Update the activity Log */
EXEC [DBCATCH].[dbo].[PU_ActivityLog_UPD]
@p_ActivityLog_ID = @v_ActivityLog_ID,
@p_EndTime = @v_Now,
@p_Active = 0,
@p_DateModified = @v_Now;
GO
IF OBJECT_ID('[dbo].[<Name, SYSNAME, PU_DB_ADD>]') IS NOT NULL
BEGIN
PRINT '>>> CREATED PROCEDURE [dbo].[<Name, SYSNAME, PU_DB_ADD>] <<<';
END;
ELSE
BEGIN
PRINT '>>> FAILED TO CREATE PROCEDURE [dbo].[<Name, SYSNAME, PU_DB_ADD>] <<<';
END;Let’s examine the changes in detail. First, we added the Insert procedure call right after checking our debug values and right before we start developing in our Begin TRY statement.
EXEC [DBCATCH].[dbo].[PU_ActivityLog_ADD]
@p_Error_ID = NULL,
@p_System = @v_System,
@p_DB = @v_DB,
@p_Obj = @v_Obj,
@p_App = @v_App,
@p_User = @v_User,
@p_Spid = @v_Spid,
@p_Description = NULL,
@p_StartTime = @v_Now,
@p_EndTime = NULL,
@p_ActivityLog_ID = @v_ActivityLog_ID OUTPUT;This starts the activity log with the values we defined and used for our error engine. We created an output param for the new identity and stuffed it into @v_ActivityLog_ID so that when we are at the end of the routine, we can update the row uniquely which is what the update proc expects as one of its input params.
Call to Update Procedure
The next change is placing a call to the update procedure right after the error log insert in the TRY CATCH segment as shown below:
The main thing to notice here is that we already have all the information about an error. If an error does happen, and we are already at a point to insert in the error log, and we have to update the activity log anyway, why not insert the error with the activity log?
If we look at the activity log and the error is null, that’s great! Otherwise, we know exactly where to go without going anywhere else, and we know the date and time of the process. If there is an error, we exit the routine directly from the TRY CATCH.
Then, if the process completes successfully, we need to update the activity log with end dates and leave the error id NULL. This is done directly under the cleanup comment as this cleans up our processes getting ready to exit cleanly.
And that is it for the development!
Building the T-SQL Activity Log Demo
All we need to do now is create a new demo from our updated template. We cannot use our old demo because it does not have the activity log feature set we just plugged into our template framework. Let’s save our template, copy it to a new query window, press CTRL + Shift + M to name the procedure and lets name it the same…PU_Demo1.
Our framework has the plumbing to look if it already exists and recreate itself, so let’s not add more demos. We’ll keep the demo procs somewhat manageable. At the ==>> Start Code Here! point, let’s place the code:
SELECT 'This is Demo1';We will leave the error number as 10000 but will change the message:
Error FROM [DBCATCH].[dbo].[TU_Errorlog] WITH error:To:
Error FROM [PU_Demo1] WITH error:And that’s it! Let’s compile and execute the procedure PU_Demo1 and see what we have:
We still have one record in the error log; that did not change. But, now we have a single record in our activity log that shows the start and end times, the who, what, when, and where from. The Error ID is null, so it appears that the process ran successfully. It looks like we have a functional feature added, but we will not know for sure until we test the error update. To do this we will change the code of PU_Demo1 from:
SELECT 'This is Demo1';To:
SELECT 'This is Demo1'
RAISERROR ('Message', 19, 1) WITH LOGRecompile the PU_Demo1 code and then run the procedure so we can analyze the results:
Final Word, and Looking Ahead
We built the T-SQL Activity Log. We have two records in the Error log, and we have two records in the Activity Log. The other thing to notice: not only is the Error_ID populated with the correct error code we used to error out in the TRY CATCH, we also have a description which is the error message that we would also find in the error log.
At this stage we have successfully completed adding the activity logging feature to our framework. Our product is already able to help us develop and troubleshoot closer to an enterprise level, while at the same time reducing the time we have to develop tedious tasks. Well done. Come back as we finish our feature set in T-SQL Framework part 4, where we will add Batching as a feature set to our framework.
