SQL Server – TSQL Code Logging To Table

Update (Jan 18, 2017):

I was able to add “autonomous transaction” type support to the logger using the means available in SQL Server (a loopback linked server). The new and updated code is available on GitHub. https://github.com/SQLJana/TSQL_Logger

….main post continues below

Logging is one of those things no two people can agree on one way to do! Everyone has their own take on it and nothing is ever good enough. By logging, I mean, logging activity to a table. When I first looked around, the best post I found on Logging was by Aaron Bertrand. I liked the post for its simplicity but ironically, I also wanted to expand it to make it do more things and hence more complex! So, this is my expanded version of the original. I apologize if I over-complicated it!

Why did I (re)create yet another logger?!

There are quite a few things I wanted to accomplish with this logging variant

  • Be easy to use with defaults yet have all options for the advanced user
  • Logging basic information to table (basic need)
  • Recording both start and end times and hence know the duration
  • Recording ConnectionId information for SQL Server session context
  • Setting context information that is visible outside the connection (SET CONTEXT_INFO) when querying DMV’s
  • Record application agnostic way of recording application specific context data via XML that is queryable
  • Exception handler being aware of and recording errors automatically
  • Ability to track things at different levels. For example:
    • ANONYMOUS BLOCK
    • BATCH
    • PROCESS
    • APPLICATION
    • MODULE
    • PROCEDURE
    • FUNCTION
    • STEP
    • SQL
    • LOOP
  • Shared code be traceable across applications in their own context with timing
  • Find what is ACTIVE at any point in time using DMV’s
  • Use central logging across all databases in an instance
  • Basic views for analytics
  • Uniquely identify all log entries generated by a specific connection’s session
  • Establish hierarchy of calls with ParentObjectId
  • Automatically know number of rows affected by the operation prior to the step that was logged (without any effort)
  • Know the context of execution minutia without passing in any parameters
  • Ability to PRINT the seemingly irrelevant yet critical context information in any shared code without infringing on the shared nature of shared code. Phew!

This is not a fluffed-up list but rather something I set-out to do. Let us see how this was accomplished without making the implementation overly complex.

Enough of theoretical stuff. Let us see the actors.

Actor #1 – The logging schema and the Log table

Create the schema named Logging and table named Log in a common database. “master” is NOT a recommended home for this since the FileGroup can quickly get filled-up with log information and you would find yourself affecting everyone using the instance! Ideally, you should create a separate FileGroup just for this purpose and use it.

  • Logging.StartLog – Start log at the beginning of procedure, step, loop etc
  • Logging.EndLog – End the corresponding log started (to capture end time)

The code looks like a lot but MOST of it is detailed usage examples and not actual code itself!

--
-- Author: Jana Sattainathan [Twitter: @SQLJana] [Blog: sqljana.wordpress.com] - Initial Release
-- Notes: Create the core objects (Log table, procedures and views) in a central database,
--			then, create synonyms pointing to these from other databases as shown at the end (commented) of this file
--
--
--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
--BEGIN: Schema
--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

IF EXISTS (SELECT * FROM sys.schemas WHERE name = 'Logging')
	DROP SCHEMA Logging;
GO

CREATE SCHEMA Logging;
GO

--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
--BEGIN: Table
--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'U' AND name = 'Log' AND schema_id = SCHEMA_ID('Logging'))
	DROP TABLE Logging.Log
GO

CREATE TABLE Logging.Log (
	LogId BIGINT IDENTITY(1, 1) PRIMARY KEY						--Running sequence
	,LogDate DATETIME2 NOT NULL DEFAULT CURRENT_TIMESTAMP
	,ServerName SYSNAME NOT NULL DEFAULT @@SERVERNAME			--Helps with reporting when aggregating log data across servers for analysis
	,SPID INT NOT NULL DEFAULT @@SPID							--The server process ID number of the current process.
	,ConnectionId UNIQUEIDENTIFIER NOT NULL						--Stays constant for a session. Gets reset if disconnect and run after reconnection. Used to identify active sessions
	,DatabaseName NVARCHAR(400) DEFAULT DB_NAME(DB_ID())		--This could be other databases outside this central database where logging module exists
	,AppContextInfo VARCHAR(128)								--Set by top level caller exactly once!
	,Tag XML													--XML context info for log entry to query/filter by later
	,ObjectID INT												--Object ID of caller of logging. @@PROCID for procedure, the step ID for a package step, and so on. Object should exist in 'DatabaseName' logged for
	,ParentObjectID INT											--The parent Object ID. Eg: Proc A calls Proc B, then A is the parent of B
	,LogType NVARCHAR(20) NOT NULL DEFAULT 'PROCEDURE'			--See check constraint CK_Log for possible allowed values
	,ObjectName NVARCHAR(400)									--Name is stored based on ObjectId since, Id's could change over time if dropped and recreated
	,ParentObjectName NVARCHAR(400)
	,EndDateTime DATETIME2
	,RowsAffected INT
	,ErrorLine INT
	,ErrorMessage NVARCHAR(MAX)
	,AdditionalInfo NVARCHAR(MAX)
	-----Computed columns-----------
	,[DurationMilliseconds] AS
		DATEDIFF(ms, LogDate, EndDateTime)
	,[Status] AS
		CASE
			WHEN EndDateTime IS NULL
				THEN 'Running'
			WHEN ErrorMessage IS NOT NULL
				THEN 'Error'
			ELSE 'Complete'
		END
	) ON [PRIMARY];

ALTER TABLE Logging.Log ADD CONSTRAINT CK_Log CHECK (
	LogType IN (
		'ANONYMOUS BLOCK'
		,'BATCH'
		,'PROCESS'
		,'APPLICATION'
		,'MODULE'
		,'PROCEDURE'
		,'FUNCTION'
		,'STEP'
		,'SQL'
		,'PACKAGE'
		,'LOOP'
		)
	)
GO

CREATE INDEX ncx_Log_LogDate ON Logging.Log (LogDate);
GO

CREATE INDEX ncx_Log_ObjectId ON Logging.Log (ObjectId);
GO

GO

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'Log')
	DROP SYNONYM Log
GO

CREATE SYNONYM Log FOR Logging.Log;
GO

Each of the columns in the table is explained with a comment beside it. Feel free to expand on the list of allowed values for LogType to fit your needs!

Actor #2 – The procedures – Start and Stop log

  • Logging.StartLog – Start Logging at procedure/loop/step etc. level
  • Logging.StopLog – Stop Logging the appropriate start
--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
--BEGIN: Procedures
--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
IF EXISTS (SELECT * FROM sys.objects WHERE type = 'P' AND name = 'StartLog' AND schema_id = SCHEMA_ID('Logging'))
	DROP PROCEDURE Logging.StartLog
GO

CREATE PROCEDURE Logging.StartLog
	@DatabaseID BIGINT = NULL
	,@ObjectID BIGINT
	,@ParentObjectID BIGINT = NULL
	,@Tag XML = NULL
	,@LogType NVARCHAR(20) = 'PROCEDURE'
	,@RowsAffected INT = NULL
	,@AdditionalInfo NVARCHAR(MAX) = NULL
	,@LogID BIGINT OUTPUT
	---------------------------------------
	,@InferTag BIT = 1
	,@InferParentObjectId BIT = 1
AS
BEGIN
	-- =============================================================================================
	-- Original Idea By:	Aaron Bertrand
	-- Updated By: Jana Sattainathan [Twitter: @SQLJana] [Blog: sqljana.wordpress.com]
	--				Apr 06, 2014 - Added additional columns ServerName, SID, LogType, Tag, Duration etc
	--							 - Added additional procedure EndLog for tracking begin/end time by closing an existing log entry
	--							 - Mar 31, 2015: ....plus a lot more. Take a look at the original link to see the differences
	-- Original Reference:  http://www.mssqltips.com/sqlservertip/2003/simple-process-to-track-and-log-sql-server-stored-procedure-use/
	-- Create date: Apr 06, 2014
	-- Description:	Procedure that logs procedure calls
	-- Additional Info:
	--		A more advanced logging version is here
	--		http://www.mrmarkos.com/2014/02/07/a-simple-sql-server-stored-procedure-logging-framework/
	-- Usage:
	/*

	--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

	---------------
	--Example 0 - A complete example. See the other examples below this example for simpler, step by step understanding
	---------------

		--Drop and recreate if our temporary demo procedures already exist..we will call it later to illustrate
		-------------------------------------------------------------------------------------------------------------

		IF object_id('TEMPDB.DBO.#MainProc') IS NOT NULL
			DROP PROCEDURE #MainProc;
		GO

		CREATE PROCEDURE #MainProc
		AS
		BEGIN
			------------------------ Begin: Logging related ------------------------
			--Setting context for application (Do this only once in the entry-point procedure for the whole application/batch)
			--	***** W A R N I N G *****: DO NOT SET THIS IN EVERY PROCEDURE!!

			DECLARE @AppContextInfo VARBINARY(128) =  CAST('My Test Application' AS  VARBINARY(128))

			--This information will be associated with the session and will be accessible in SQL Server system views
			SET CONTEXT_INFO @AppContextInfo		

			DECLARE @Tag VARCHAR(512) = '<TestApplication> ' +
											'<ProcessName>Test process</ProcessName>' +
											'<ReportToDate><<REPORTTODATE>></ReportToDate>' +
											'<LogId><<LOGID>></LogId>' +
											'<RunNumber><<RUNNUMBER>></RunNumber>' +
										'</TestApplication>';
			DECLARE @CallerProcId BIGINT = @@PROCID;			

			EXEC Logging.SetAttribute @AttributeName='Log.ParentObjectId', @AttributeValue=@CallerProcId, @AttributeType='BIGINT', @AttributeFormat=NULL;
			------------------------ End: Logging related ------------------------

			------------------------ Begin: Tag ------------------------
			--Replace placeholders in the Tag
			SET @Tag = REPLACE(@Tag, '<<REPORTTODATE>>', CONVERT(VARCHAR,getdate()));
 			SET @Tag = REPLACE(@Tag, '<<LOGID>>', 232121);
			--SET @Tag = REPLACE(@Tag, '<<RUNNUMBER>>', NEXT VALUE FOR MySchema.RunNumberSeq);		--MySchema.RunNumberSeq is a pre-defined sequence object
			SET @Tag = REPLACE(@Tag, '<<RUNNUMBER>>', 12);

			EXEC Logging.SetAttribute @AttributeName='Log.Tag', @AttributeValue=@Tag, @AttributeType='XML', @AttributeFormat=NULL;
			------------------------ End: Tag ------------------------

			--Call chain 1: Say procedure A calls procedure B, B calls C and so on...as part of Batch process 1
			--Call chain 2: As part of Batch process 2, procedure Z could call procedure B, B calls C and so on...the same chain..
			--However the context is different for both call chains. Different context info should be set for each chain..
			--All log entries made as part of Chain 1 will have the same AppContextInfo in Log
			--...and all log entries made as part of Chain 2 will have a different AppContextInfo in Log even for steps that are common for both chains!

			--Pass the tag along to all called procedures...so that log entries will have associated information recorded...and it will be querable later
			--EXEC #LoggingTestProc @CallerTag = @Tag, @CallerProcId = @@PROCID;

			--Can forego passing tag and calling proc info and it will be inferred since we SetAttributes for Log.Tag and Log.ParentObjectId
			--		but the ParentObjectId will be this top level procedure for all called procedures in the call tree but it works!
			EXEC #LoggingTestProc
		END
		GO

		-------------------------------------------------------------------------------------------------------------

		IF object_id('TEMPDB.DBO.#LoggingTestProc') IS NOT NULL
			DROP PROCEDURE #LoggingTestProc;
		GO

		CREATE PROCEDURE #LoggingTestProc
		(
			@CallerTag VARCHAR(512) = NULL,
			@CallerProcId BIGINT = NULL
		)
		AS
		BEGIN

			------------------------ Begin: Logging related ------------------------
			DECLARE @DBId BIGINT = DB_ID();
			DECLARE @ObjId BIGINT = @@PROCID
			DECLARE @ParentObjId BIGINT = @CallerProcId		--Set to NULL if no @CallerProcId parameter
			DECLARE @LogId BIGINT;
			DECLARE @Msg VARCHAR(255);
			DECLARE @StepLogId BIGINT;
			DECLARE @StepMsg VARCHAR(255);
			DECLARE @Tag VARCHAR(512) = @CallerTag;			--Set to NULL if no @CallerTag parameter
			------------------------ End: Logging related ------------------------

			BEGIN TRY
				SET @Msg = 'Starting procedure that calculates distance to moon!'
				EXEC StartLog @DatabaseId = @DBId, @Tag = @Tag, @ObjectID = @ObjId, @ParentObjectId = @ParentObjId, @LogType = 'ANONYMOUS BLOCK', @AdditionalInfo = @Msg, @LogId = @LogId OUTPUT		--Log procedure start

				---------------
				----STEP 1 ----
				---------------
				--Do something that produces an error
				BEGIN TRY
					SET @StepMsg = 'Finding the center of gravity on moon'
					EXEC StartLog @DatabaseId = @DBId, @Tag = @Tag, @ObjectID = @ObjId, @ParentObjectId = @ParentObjId, @LogType = 'STEP', @AdditionalInfo = @StepMsg, @LogId = @StepLogId OUTPUT		--Log step start

					DECLARE @Test INT = 1/0;

					EXEC EndLog @LogID = @StepLogId;	--Log step end
				END TRY
				BEGIN CATCH
					--Error message is automatically captured in the record for current @StepLogId
					EXEC EndLog @LogID = @StepLogId;
				END CATCH;

				---------------
				----STEP 2 ----
				---------------
				--Do something that completes fine - run dynamic SQL

				DECLARE @SQL NVARCHAR(255) = 'select top 1 * from sys.tables'

				SET @StepMsg = @SQL
				EXEC StartLog @DatabaseId = @DBId, @Tag = @Tag, @ObjectID = @ObjId, @ParentObjectId = @ParentObjId, @LogType = 'SQL', @AdditionalInfo = @StepMsg, @LogId = @StepLogId OUTPUT		--Log step start

				--Pretend that the SQL takes 4 seconds to run
				WAITFOR DELAY '00:00:04';
				--EXEC sp_executesql @SQL

				EXEC EndLog @LogID = @StepLogId;	--Log step end

				---------------
				----STEP 3 ----
				---------------
				--Unhandled error in this step

				SET @StepMsg = @SQL
				EXEC StartLog @DatabaseId = @DBId, @Tag = @Tag, @ObjectID = @ObjId, @LogType = 'SQL', @AdditionalInfo = @StepMsg, @LogId = @StepLogId OUTPUT		--Log step start

				-- RAISERROR with severity 11-19 will cause execution to jump to the CATCH block.
				RAISERROR ('Moon stuff is too complex! Giving up.', -- Message text.
						   16, -- Severity.
						   1 -- State.
						   );

				EXEC EndLog @LogID = @StepLogId;	--Log step end

				EXEC EndLog @LogID = @LogId;		--Log procedure end

			END TRY
			BEGIN CATCH
				--Log the error to the procedure log
				IF (@LogId IS NOT NULL)
					EXEC EndLog @LogId = @LogId;		--Log procedure end
				IF (@StepLogId IS NOT NULL)
					EXEC EndLog @LogId = @StepLogId;	--Log step end

				--Comment/uncomment the version of "Rethrow" based on the version of SQL Server you are using

				--Rethrow: SQL Server versions below 2012
				--Get the details of the error--that invoked the CATCH block
				DECLARE
					@ErMessage NVARCHAR(2048),
					@ErSeverity INT,
					@ErState INT
				SELECT
					@ErMessage = ERROR_MESSAGE(),
					@ErSeverity = ERROR_SEVERITY(),
					@ErState = ERROR_STATE();

				--Should be able to replace with a single THROW statement in SQL 2012
				RAISERROR (@ErMessage, @ErSeverity, @ErState );

				--Rethrow: SQL Server versions 2012 and above
				--THROW;

			END CATCH;
		END;
		GO

		-------------------------------------------------------------------------------------------------------------

		--Test call...
		EXEC #MainProc

		--Select from the log to show what was logged
		SELECT * FROM Log ORDER BY 1 DESC

		DROP PROCEDURE #LoggingTestProc;
		DROP PROCEDURE #MainProc;

	--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

	---------------
	--Example 1
	---------------
	--This is an example of "fire and forget" logging. We do not care about getting back to the logged entry.
		--Example 1.1 - Simplest call
		DECLARE @LogId BIGINT;
		EXEC StartLog @ObjectID = @@PROCID, @LogId = @LogId OUTPUT;

		--Example 1.2 - ..+ Status message is included
		DECLARE @LogId BIGINT;
		EXEC StartLog @ObjectID = @@PROCID, @AdditionalInfo = 'Some status message', @LogId = @LogId OUTPUT;

		--Example 1.3 - ..+ Status message + Log type is included
		DECLARE @LogId BIGINT;
		EXEC StartLog @ObjectID = @@PROCID, @LogType = 'PROCEDURE', @AdditionalInfo = 'Some status message', @LogId = @LogId OUTPUT;

		--Example 1.4 - ..+ ParentObjectID is included
		DECLARE @LogId BIGINT;
		DECLARE @ParentObjectId BIGINT;

		SET @ParentObjectId = OBJECT_ID('[CLT2EVE_Transforms].[WorkTransformExclude].[Claims_RetroReceiptChangeHistory]')
		EXEC StartLog @ObjectID = @@PROCID, @ParentObjectID = @ParentObjectId, @LogType = 'PROCEDURE', @AdditionalInfo = 'Some status message', @LogId = @LogId OUTPUT;

		--Example 1.4 - ..+ DatbaseID is included
		DECLARE @LogId BIGINT;
		DECLARE @DatabaseId BIGINT;
		DECLARE @ParentObjectId BIGINT;

		SET @DatabaseId = DB_ID()
		SET @ParentObjectId = OBJECT_ID('[CLT2EVE_Transforms].[WorkTransformExclude].[Claims_RetroReceiptChangeHistory]')
		EXEC StartLog @DatabaseId = @DatabaseId, @ObjectID = @@PROCID, @ParentObjectID = @ParentObjectId, @LogType = 'PROCEDURE', @AdditionalInfo = 'Some status message', @LogId = @LogId OUTPUT;

	--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

	---------------
	--Example 2
	---------------
	--In this example, we set context info once at the beginning of the session and use that to tie all log entries...
	--		This context info, could be different for the same procedure for calls made from different applications!! That is the beauty of this.
	--		The context info can also be changed mid-way through a process if that is the requirement!

		DECLARE @LogId BIGINT;
		DECLARE @Msg VARCHAR(255) = 'Process customer records';
		DECLARE @AppContextInfo VARBINARY(128) =  CAST('My Fancy Application' AS  VARBINARY(128))

		SET CONTEXT_INFO @AppContextInfo

		--Register start
		EXEC StartLog @ObjectID = @@PROCID, @AdditionalInfo = @Msg, @LogId = @LogId OUTPUT;		

		--Take a look that log entry's AppContextInfo column!
		SELECT AppContextInfo FROM Log WHERE LogId = @LogId;

	--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

	---------------
	--Example 3
	---------------
	--In this example, we want to track the start and end time for the procedure (using OUTPUT variable @LogId)
		DECLARE @LogId BIGINT;
		DECLARE @Msg VARCHAR(255) = 'Process customer records';

		--Register start
		EXEC StartLog @ObjectID = @@PROCID, @AdditionalInfo = @Msg, @LogId = @LogId OUTPUT;		

		--<<Make the actual call to process customer record here>>

		--Register end
		EXEC EndLog @LogID = @LogId;

		--At this point, you can select the log entry from Log
		SELECT * FROM Log WHERE LogId = @LogId;

	--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

	---------------
	--Example 4
	---------------
	--In this example, we want to track the start and end time for the procedure (using OUTPUT variable @LogId)
	--		+ we want to track the start and end time of every step within the procedure..

		DECLARE @LogId BIGINT;
		DECLARE @Msg VARCHAR(255) = 'Process customer records';

		DECLARE @StepLogId INT;
		DECLARE @StepMsg VARCHAR(255);

		--Register ***procedure*** start
		EXEC StartLog @ObjectID = @@PROCID, @AdditionalInfo = @Msg, @LogId = @LogId OUTPUT;		

		--Register ***Step 1*** start
		SET @StepMsg = 'About to run step 1 for procedure!'
		EXEC StartLog @ObjectID = @@PROCID, @LogType = 'STEP', @AdditionalInfo = @StepMsg, @LogId = @StepLogId OUTPUT
		--Register ***Step 1*** end
		EXEC EndLog @LogId = @StepLogId;

		--Register ***Step 2*** start
		SET @StepMsg = 'About to run step 2 for procedure!'
		EXEC StartLog @ObjectID = @@PROCID, @LogType = 'STEP', @AdditionalInfo = @StepMsg, @LogId = @StepLogId OUTPUT
		--Register ***Step 2*** end
		EXEC EndLog @LogId = @StepLogId;

		--Register ***procedure*** end
		EXEC EndLog @LogID = @LogId;

		--At this point, you can select the log entry from Log
		SELECT * FROM Log ORDER BY 1 DESC;

	--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

	---------------
	--Example 5
	---------------
	--In this example, we record a lot of additional information in a structured manner (XML) in the Tag column that is queryable later
	--		Notice, how "MontlyRetroRun" is used as the root node and later query against the log table uses that

		DECLARE @LogId BIGINT;
		DECLARE @Msg VARCHAR(255) = 'Process customer records';

		DECLARE @Tag VARCHAR(512) = '<MonthlyRetroRun> ' +
										'<ProcessName>MonthlyRetro</ProcessName>' +
										'<ReportToDate><<REPORTTODATE>></ReportToDate>' +
										'<RetroCessionMonthlyActivityLogId><<RETROCESSIONMONTHLYACTIVITYLOGID>></RetroCessionMonthlyActivityLogId>' +
										'<BatchNumber><<BATCHNUMBER>></BatchNumber>' +
										'<RunSequenceNumber><<RUNSEQUENCENUMBER>></RunSequenceNumber>' +
									'</MonthlyRetroRun>';

		------------------------ Begin: Tag ------------------------
		--Replace placeholders in the Tag
		SET @Tag = REPLACE(@Tag, '<<REPORTTODATE>>', CONVERT(VARCHAR,getdate()));
 		SET @Tag = REPLACE(@Tag, '<<RETROCESSIONMONTHLYACTIVITYLOGID>>', 232121);
 		SET @Tag = REPLACE(@Tag, '<<BATCHNUMBER>>', LTRIM(STR(11)));
 		SET @Tag = REPLACE(@Tag, '<<RUNSEQUENCENUMBER>>', LTRIM(STR(99999)));

		SET @Msg = 'Fetch/decide on values for decision making variables!'
		EXEC StartLog @Tag = @Tag, @ObjectID = @@PROCID, @LogType = 'PROCEDURE', @AdditionalInfo = @Msg, @LogId = @LogId OUTPUT		--Log procedure start
		------------------------ End: Tag ------------------------	

		--At this point, you can select the log entry from Log where
		SELECT r.value('RunSequenceNumber[1]','INT') AS RunNumber,
				r.value('ReportToDate[1]','DateTime') AS ReportToDate,
				l.*
		FROM   Log l
			CROSS APPLY Tag.nodes('/MonthlyRetroRun') AS Runs(r)

	--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

	-------------------------------------------
	--Examples that illustrate working with XML
	-------------------------------------------

	--Example 1
	-- Querying XML data column "Tag"
		--If Log.Tag column has the value "<MonthlyRetroRun RunId="1">Test</MonthlyRetroRun>", one could query like this.
		-- Reference: http://thegrayzone.co.uk/blog/2010/03/querying-sql-server-xml-data/
		SELECT r.value('MonthlyRetroRun[1]','varchar(15)')
		FROM   Log
		CROSS APPLY Tag.nodes('/') AS Runs(r)

	--Example 2
	-- Somewhat more complex querying of XML data column "Tag"
		UPDATE Log
		SET Tag = '<MonthlyRetroRun ReportToDate="' + CONVERT(VARCHAR(25), CONVERT(datetime, '2014-02-28 00:00:00.000')) + '"> ' +
										'<ReportToDate>' + CONVERT(VARCHAR(25), CONVERT(datetime, '2014-02-28 00:00:00.000')) + '</ReportToDate>' +
										'<RunNumber>1</RunNumber>' +
										'<BatchSize>' + LTRIM(STR(1000)) + '</BatchSize>' +
										'<MaxRecords>' + LTRIM(STR(50000)) + '</MaxRecords>' +
									'</MonthlyRetroRun>'
		WHERE LogId	= 4							

		SELECT r.value('RunNumber[1]','INT') AS RunNumber,
				r.value('ReportToDate[1]','DateTime') AS ReportToDate
		FROM   Log
			CROSS APPLY Tag.nodes('/MonthlyRetroRun') AS Runs(r)
		WHERE LogId	= 4							

	--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

*/

	-- ================================================================================================
	DECLARE @DBId BIGINT = COALESCE(@DatabaseId, DB_ID());
	DECLARE @ObjectName NVARCHAR(400) = NULL;
	DECLARE @ParentObjectName NVARCHAR(400) = NULL;
	DECLARE @NewParentObjectId BIGINT = @ParentObjectId;
	DECLARE @NewTag XML = @Tag;

	--Derive the object name (as object id's get changed if objects are recreated and hence logs become useless)
	IF (@ObjectID IS NOT NULL)
	BEGIN
		SET @ObjectName = COALESCE(QUOTENAME(DB_NAME(@DBId))
									+ '.' + QUOTENAME(OBJECT_SCHEMA_NAME(@ObjectID, @DBId))
									+ '.' + QUOTENAME(OBJECT_NAME(@ObjectID, @DBId))
								, ERROR_PROCEDURE());
	END;

	--Use the Tag stored globally if an empty tag is passed in
	IF (@NewTag IS NULL)
	BEGIN
		IF (@InferTag = 1)
		BEGIN
			DECLARE @TempTag SQL_VARIANT = NULL;
			EXEC GetAttribute @AttributeName='Log.Tag', @AttributeValue=@TempTag OUTPUT, @AttributeType=NULL, @AttributeFormat=NULL, @IgnoreIfAttributeIsMissing=1;

			SET @NewTag = CONVERT(VARCHAR(MAX), @TempTag);
		END;
	END;

	--Use the ParentObjectId stored globally if an empty tag is passed in
	IF (@NewParentObjectId IS NULL)
	BEGIN
		IF (@InferParentObjectId = 1)
		BEGIN
			DECLARE @TempParentObjectId SQL_VARIANT = NULL;
			EXEC GetAttribute @AttributeName='Log.ParentObjectId', @AttributeValue=@TempParentObjectId OUTPUT, @AttributeType=NULL, @AttributeFormat=NULL, @IgnoreIfAttributeIsMissing=1;

			SET @NewParentObjectId = CONVERT(BIGINT, @TempParentObjectId);
		END;
	END;

	IF (@NewParentObjectId IS NOT NULL)
	BEGIN
		SET @ParentObjectName = COALESCE(QUOTENAME(DB_NAME(@DBId))
									+ '.' + QUOTENAME(OBJECT_SCHEMA_NAME(@NewParentObjectId, @DBId))
									+ '.' + QUOTENAME(OBJECT_NAME(@NewParentObjectId, @DBId))
								, ERROR_PROCEDURE());
	END;

	--Create a new entry in the log table
	INSERT Log (
		ServerName
		,SPID
		,ConnectionId
		,DatabaseName
		,AppContextInfo
		,Tag
		,ObjectID
		,ParentObjectID
		,LogType
		,ObjectName
		,ParentObjectName
		,EndDateTime
		,RowsAffected
		,ErrorLine
		,ErrorMessage
		,AdditionalInfo
		)
	SELECT @@SERVERNAME
		,@@SPID
		--Connection_Id uniquely identifies a connection like SID+Serial# in Oracle.
		--	This can be used to detect active sessions based on entries in the log table (and possibly kill if needed).
		,  (
			SELECT Connection_Id
			FROM sys.dm_exec_connections
			WHERE session_id = @@SPID
			)
		,DB_NAME(@DBId)
		,CONTEXT_INFO()		--See http://www.sqlservercentral.com/articles/T-SQL/2765/ for more information on how this is used!
		,@NewTag
		,@ObjectID
		,@NewParentObjectID
		,@LogType
		,@ObjectName
		,@ParentObjectName
		,NULL
		,@RowsAffected		--Caution on what you pass in for @RowsAffected. You do not want to record rowcount for previous operation (using @@ROWCOUNT) rather than the one currenly being logged
		,ERROR_LINE()
		,ERROR_MESSAGE()
		,@AdditionalInfo;

	SET @LogID = @@IDENTITY;

	PRINT CONVERT(VARCHAR, GETDATE()) + ': ' + LTRIM(STR(@LogID)) + ' - ' + @ObjectName + ' - ' + @AdditionalInfo;
END
GO

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'StartLog')
	DROP SYNONYM StartLog
GO

CREATE SYNONYM StartLog FOR Logging.StartLog;
GO

--_________________________________________________________________________________________________________________________________

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'P' AND name = 'EndLog' AND schema_id = SCHEMA_ID('Logging'))
	DROP PROCEDURE Logging.EndLog;
GO

CREATE PROCEDURE Logging.EndLog
 @LogID			BIGINT,
 @RowsAffected	INT = NULL
AS
BEGIN

-- =============================================================================================
-- Original:	Original idea from Aaron Bertrand
-- Created By: Jana Sattainathan
--				Apr 07, 2014 - Created this procedure that will help track duration of activities (by closing an open log entry)
-- Source:  http://www.mssqltips.com/sqlservertip/2003/simple-process-to-track-and-log-sql-server-stored-procedure-use/
-- Create date: Apr 06, 2014
-- Description:	Procedure that ends an open log entry in ProcedureLog table
-- Usage:
/*
	--Example 1
		DECLARE @LogId INT;
		DECLARE @Tag XML = '<MonthlyRetroRun RunId="1">Test</MonthlyRetroRun>';
		DECLARE @Msg VARCHAR(255) = 'Process customer records';
		EXEC StartLog @Tag = @Tag, @ObjectID = @@PROCID, @AdditionalInfo = @Msg, @LogId = @LogId OUTPUT;
		EXEC EndLog @LogID = @LogId;

		SELECT * FROM Log

*/
-- Reference:
--	Working with XML - http://technet.microsoft.com/en-us/library/bb522510.aspx
--
-- ================================================================================================
	DECLARE @Rows INT = COALESCE(@RowsAffected, @@ROWCOUNT);

	UPDATE Logging.Log
	SET EndDateTime = GETDATE(), --DATEDIFF(S, LogDate, GETDATE()),
		RowsAffected = @Rows,
		ErrorLine = ERROR_LINE(),
		ErrorMessage = ERROR_MESSAGE()
	WHERE LogId = @LogID;

	PRINT CONVERT(VARCHAR,GETDATE()) + ': ' + LTRIM(STR(@LogID)) + ' - Call ended';
END
GO

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'EndLog')
	DROP SYNONYM EndLog
GO

CREATE SYNONYM EndLog FOR Logging.EndLog;
GO

Actor #3 – Attributes – Set, Get, Delete, DeleteAll & Display

The procedures here deal with recording attributes that are specific to the run. These attributes that are run-specific, loosely bind a run although the reusable procedures that use these attribute procedures are not tied a single specific business process. The magic is possible with global temp tables. Be careful not to stuff it and abuse this!

  • Logging.SetAttribute – Save off discrete variables that are pertinent
  • Logging.GetAttribute – Get attributes that have been saved (even from other procs)
  • Logging.DeleteAttribute – Delete one saved variable
  • Logging.DeleteAllAttributes – Clears all saved variables
  • Logging.ShowAllAttributes – Display saved variables
--_________________________________________________________________________________________________________________________________

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'P' AND name = 'SetAttribute' AND schema_id = SCHEMA_ID('Logging'))
	DROP PROCEDURE Logging.SetAttribute;
GO

IF object_id('TEMPDB.DBO.##TempAttributesTable') IS NOT NULL
	DROP TABLE ##TempAttributesTable;
GO

CREATE PROCEDURE Logging.SetAttribute
	@AttributeName	VARCHAR(100),
	@AttributeValue SQL_VARIANT,
	@AttributeType VARCHAR(25) = 'VARCHAR',			--For convenience only. Conversion is your responsibility.
	@AttributeFormat VARCHAR(100) = NULL				--For convenience only. E.g., store date format
AS
BEGIN

-- =============================================================================================
-- Created By: Jana Sattainathan
-- Create date: Apr 09, 2015
-- Description:	Procedure that sets the current value of certain attributes that can be fetched later in other procedures.
--					Typically used when information cannot be passed into called sub-programs that operate independently but values need to be shared.
--					Please see the information in GetAttribute
-- Usage:
/*
	---------------
	--Example 1
	---------------
		Logging.SetAttribute @AttributeName='TEST', @AttributeValue='DAFSFASFSA', @AttributeType='VARCHAR', @AttributeFormat=NULL;
		SELECT * FROM ##TempAttributesTable;

*/
-- ================================================================================================

	--Create a temp table to hold the values
	IF object_id('TEMPDB.DBO.##TempAttributesTable') IS NULL
	BEGIN
		CREATE TABLE ##TempAttributesTable
			(
				[ConnectionId] UNIQUEIDENTIFIER NOT NULL,
				[Name]  VARCHAR(100) NOT NULL,
				[Value] SQL_VARIANT,
				[Type] VARCHAR(25),
				[Format]  VARCHAR(100),
				[At] DATETIME2 NOT NULL DEFAULT CURRENT_TIMESTAMP
			);
	END;

	DECLARE @ConnectionId UNIQUEIDENTIFIER = (
					SELECT Connection_Id
					FROM sys.dm_exec_connections
					WHERE session_id = @@SPID
					);

	--Insert/Update based on whether the attribute exists
	IF EXISTS (
				SELECT *
				FROM ##TempAttributesTable
				WHERE
					ConnectionId = @ConnectionId
					AND Name = @AttributeName
			)
	BEGIN
		UPDATE ##TempAttributesTable
		SET
			[Value] = @AttributeValue,
			[Type] = @AttributeType,
			[Format] = @AttributeFormat
		WHERE
			[ConnectionId] = @ConnectionId
			AND [Name] = @AttributeName;
	END
	ELSE
	BEGIN
		INSERT INTO ##TempAttributesTable ([ConnectionId], [Name], [Value], [Type], [Format])
		VALUES (@ConnectionId, @AttributeName, @AttributeValue, @AttributeType, @AttributeFormat);
	END

	--PRINT CONVERT(VARCHAR,GETDATE()) + ': Set ' + @AttributeName + ' attribute';
END;
GO

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'SetAttribute')
	DROP SYNONYM SetAttribute;
GO

CREATE SYNONYM SetAttribute FOR Logging.SetAttribute;
GO

--_________________________________________________________________________________________________________________________________

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'P' AND name = 'GetAttribute' AND schema_id = SCHEMA_ID('Logging'))
	DROP PROCEDURE Logging.GetAttribute;
GO

CREATE PROCEDURE Logging.GetAttribute
	@AttributeName	VARCHAR(100),
	@AttributeValue SQL_VARIANT OUTPUT,
	@AttributeType VARCHAR(25) OUTPUT,			--For convenience only. Conversion is your responsibility.
	@AttributeFormat VARCHAR(100) OUTPUT,		--For convenience only. E.g., store date format
	@IgnoreIfAttributeIsMissing BIT = 0			--When set to 1, returns NULL's if attributes asked for dont exist
AS
BEGIN

-- =============================================================================================
-- Created By: Jana Sattainathan
-- Create date: Apr 09, 2015
-- Description:	Procedure that gets the current value of certain attributes that were possibly set in other procedures in this session.
--					Typically used in conjuction with SetAttribute when information cannot be passed into called sub-programs that operate independently but values need to be shared.
--					Set attribute values and in the calling proc and used them in called procs with GetAttribute.
-- Usage:
/*
	---------------
	--Example 1 - Set and Get a simple string that happens to be XML. Need to do conversion yourself. Notice SQL_VARIANT to VARCHAR(200) conversion for @AttributeValue
	---------------

		--Set some attribute in Procedure A.
		-----------------------------------
		DECLARE @Tag VARCHAR(200)= '<TestApplication> ' +
										'<ProcessName>Test process</ProcessName>' +
										'<LogId>1214</LogId>' +
										'<RunNumber>22</RunNumber>' +
									'</TestApplication>';
		EXEC Logging.SetAttribute @AttributeName='Tag', @AttributeValue=@Tag, @AttributeType='XML', @AttributeFormat=NULL;

		EXEC Logging.ShowAllAttributes;

		--Get the value of that attribute in Procedure B
		-----------------------------------
		DECLARE @AttributeName	VARCHAR(100) = 'Tag';
		DECLARE @AttributeValue SQL_VARIANT;
		DECLARE @AttributeType VARCHAR(25);
		DECLARE @AttributeFormat VARCHAR(100);

		EXEC Logging.GetAttribute @AttributeName='Tag', @AttributeValue=@AttributeValue OUTPUT, @AttributeType=@AttributeType OUTPUT, @AttributeFormat=@AttributeFormat OUTPUT, @IgnoreIfAttributeIsMissing=1

		PRINT @AttributeName;
		PRINT CONVERT(VARCHAR(200), @AttributeValue);
		PRINT @AttributeType;
		PRINT @AttributeFormat;

	---------------
	--Example 1 - Set and Get a simple string but ignore things like type, format etc that we dont care about
	---------------

		--Set some attribute
		-----------------------------------
		DECLARE @Tag VARCHAR(200)= '<TestApplication> ' +
										'<ProcessName>Test process</ProcessName>' +
										'<LogId>1214</LogId>' +
										'<RunNumber>22</RunNumber>' +
									'</TestApplication>';
		EXEC Logging.SetAttribute @AttributeName='Log.Tag', @AttributeValue=@Tag, @AttributeType='XML', @AttributeFormat=NULL;

		EXEC Logging.ShowAllAttributes;

		--Get the value of that attribute in another procedure
		-----------------------------------
		DECLARE @AttributeName	VARCHAR(100) = 'Log.Tag1';
		DECLARE @AttributeValue SQL_VARIANT;
		EXEC Logging.GetAttribute @AttributeName=@AttributeName, @AttributeValue=@AttributeValue OUTPUT, @AttributeType=NULL, @AttributeFormat=NULL, @IgnoreIfAttributeIsMissing=1

		PRINT @AttributeName;
		PRINT CONVERT(VARCHAR(200), @AttributeValue);

*/
--================================================================================================
	DECLARE @AttributeFetched BIT = 0;

	--Create a temp table to hold the values
	IF object_id('TEMPDB.DBO.##TempAttributesTable') IS NOT NULL
	BEGIN
		--Select values out of the global temp table for given attribute
		IF EXISTS (
					SELECT *
					FROM ##TempAttributesTable
					WHERE Name = @AttributeName
				)
		BEGIN
			DECLARE @ConnectionId UNIQUEIDENTIFIER = (
					SELECT Connection_Id
					FROM sys.dm_exec_connections
					WHERE session_id = @@SPID
					);

			IF EXISTS(
						SELECT *
						FROM ##TempAttributesTable
						WHERE
							ConnectionId = @ConnectionId
							AND [Name] = @AttributeName
					)
			BEGIN
				SELECT
					@AttributeValue = [Value],
					@AttributeType = [Type],
					@AttributeFormat = [Format]
				FROM ##TempAttributesTable
				WHERE
					ConnectionId = @ConnectionId
					AND [Name] = @AttributeName;

				SET @AttributeFetched = 1;
			END;
		END;
	END;

	--Raise an error if @IgnoreIfAttributeIsMissing = 0 and attribute to delete does not exist for whatever reason
	IF ((@AttributeFetched = 0) AND (@IgnoreIfAttributeIsMissing = 0))
	BEGIN
		-- RAISERROR with severity 11-19 will cause execution to jump to the CATCH block.
		DECLARE @Msg VARCHAR(200) = 'Attribute ' + @AttributeName + ' does not exist. Cannot get attribute value!'
		RAISERROR (@Msg, -- Message text.
					16, -- Severity.
					1 -- State.
					);
	END;
	ELSE IF (@AttributeFetched = 0)
	BEGIN
		SET @AttributeValue = NULL;
		SET @AttributeType = NULL;
		SET @AttributeFormat = NULL;
	END;

	PRINT CONVERT(VARCHAR,GETDATE()) + ': Get ' + @AttributeName + ' attribute';
END;
GO

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'GetAttribute')
	DROP SYNONYM GetAttribute;
GO

CREATE SYNONYM GetAttribute FOR Logging.GetAttribute;
GO

--_________________________________________________________________________________________________________________________________

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'P' AND name = 'DeleteAttribute' AND schema_id = SCHEMA_ID('Logging'))
	DROP PROCEDURE Logging.DeleteAttribute;
GO

CREATE PROCEDURE Logging.DeleteAttribute
	@AttributeName	VARCHAR(100),
	@IgnoreIfAttributeIsMissing BIT = 1
AS
BEGIN

-- =============================================================================================
-- Created By: Jana Sattainathan
-- Create date: Apr 09, 2015
-- Description:	Procedure that deletes one of the attributes.
-- Usage:
/*
	---------------
	--Example 1
	---------------

		EXEC Logging.SetAttribute @AttributeName='TEST', @AttributeValue='Test value', @AttributeType='VARCHAR', @AttributeFormat=NULL;

		EXEC Logging.DeleteAttribute @AttributeName='TEST'

		EXEC Logging.ShowAllAttributes

*/
-- ================================================================================================

	DECLARE @AttributeDeleted BIT = 0;

	--Create a temp table to hold the values
	IF object_id('TEMPDB.DBO.##TempAttributesTable') IS NOT NULL
	BEGIN

		DECLARE @ConnectionId UNIQUEIDENTIFIER = (
					SELECT Connection_Id
					FROM sys.dm_exec_connections
					WHERE session_id = @@SPID
					);

		--Select values out of the global temp table for given attribute
		IF EXISTS (
					SELECT *
					FROM ##TempAttributesTable
					WHERE
						ConnectionId = @ConnectionId
						AND Name = @AttributeName
				)
		BEGIN

			IF EXISTS(SELECT *
						FROM ##TempAttributesTable
						WHERE
							ConnectionId = @ConnectionId
							AND [Name] = @AttributeName)
			BEGIN
				DELETE
				FROM ##TempAttributesTable
				WHERE
					ConnectionId = @ConnectionId
					AND [Name] = @AttributeName;

				SET @AttributeDeleted = 1;
			END;
		END;
	END;

	--Raise an error if @IgnoreIfAttributeIsMissing = 0 and attribute to delete does not exist for whatever reason
	IF ((@AttributeDeleted = 0) AND (@IgnoreIfAttributeIsMissing = 0))
	BEGIN
		-- RAISERROR with severity 11-19 will cause execution to jump to the CATCH block.
		DECLARE @Msg VARCHAR(200) = 'Attribute ' + @AttributeName + ' does not exist. Cannot delete attribute!'
		RAISERROR (@Msg, -- Message text.
					16, -- Severity.
					1 -- State.
					);
	END;

	PRINT CONVERT(VARCHAR,GETDATE()) + ': Delete ' + @AttributeName + ' attribute';
END;
GO

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'DeleteAttribute')
	DROP SYNONYM DeleteAttribute;
GO

CREATE SYNONYM DeleteAttribute FOR Logging.DeleteAttribute;
GO

--_________________________________________________________________________________________________________________________________

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'P' AND name = 'ShowAllAttributes' AND schema_id = SCHEMA_ID('Logging'))
	DROP PROCEDURE Logging.ShowAllAttributes;
GO

CREATE PROCEDURE Logging.ShowAllAttributes
	@ShowGlobal	BIT = 0						--Show the attributes for everyone or just this connection
AS
BEGIN

-- =============================================================================================
-- Created By: Jana Sattainathan
-- Create date: Apr 09, 2015
-- Description:	Procedure that shows all of the attributes.
-- Usage:
/*
	---------------
	--Example 1 - Show all the attributes of current connection
	---------------

		EXEC Logging.SetAttribute @AttributeName='TEST', @AttributeValue='Test value', @AttributeType='VARCHAR', @AttributeFormat=NULL;

		EXEC Logging.ShowAllAttributes

	---------------
	--Example 2 - Show all the attributes of all connections
	---------------

		EXEC Logging.SetAttribute @AttributeName='TEST', @AttributeValue='Test value', @AttributeType='VARCHAR', @AttributeFormat=NULL;

		EXEC Logging.ShowAllAttributes @ShowGlobal = 1

*/
-- ================================================================================================

	IF object_id('TEMPDB.DBO.##TempAttributesTable') IS NOT NULL
	BEGIN

		DECLARE @ConnectionId UNIQUEIDENTIFIER = (
				SELECT Connection_Id
				FROM sys.dm_exec_connections
				WHERE session_id = @@SPID
				);

		SELECT *
		FROM ##TempAttributesTable
		WHERE
			ConnectionId = CASE WHEN @ShowGlobal = 1
								THEN ConnectionId
								ELSE @ConnectionId
							END;
	END
	ELSE
	BEGIN
		PRINT CONVERT(VARCHAR,GETDATE()) + ': No attributes exist. SetAttribute has never been called!';
	END;
END;
GO

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'ShowAllAttributes')
	DROP SYNONYM ShowAllAttributes;
GO

CREATE SYNONYM ShowAllAttributes FOR Logging.ShowAllAttributes;
GO

--_________________________________________________________________________________________________________________________________

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'P' AND name = 'DeleteAllAttributes' AND schema_id = SCHEMA_ID('Logging'))
	DROP PROCEDURE Logging.DeleteAllAttributes;
GO

CREATE PROCEDURE Logging.DeleteAllAttributes
AS
BEGIN

-- =============================================================================================
-- Created By: Jana Sattainathan
-- Create date: Apr 09, 2015
-- Description:	Procedure that Deletes all of the attributes of current connection
-- Usage:
/*
	---------------
	--Example 1 - Delete all the attributes of current connection
	---------------

		EXEC Logging.SetAttribute @AttributeName='TEST', @AttributeValue='Test value', @AttributeType='VARCHAR', @AttributeFormat=NULL;

		EXEC Logging.DeleteAllAttributes

		EXEC Logging.ShowAllAttributes
*/
-- ================================================================================================

	IF object_id('TEMPDB.DBO.##TempAttributesTable') IS NOT NULL
	BEGIN

		DECLARE @ConnectionId UNIQUEIDENTIFIER = (
				SELECT Connection_Id
				FROM sys.dm_exec_connections
				WHERE session_id = @@SPID
				);

		DELETE
		FROM ##TempAttributesTable
		WHERE
			ConnectionId = @ConnectionId;
	END
	ELSE
	BEGIN
		PRINT CONVERT(VARCHAR,GETDATE()) + ': No attributes exist. SetAttribute has never been called!';
	END;
END;
GO

IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'DeleteAllAttributes')
	DROP SYNONYM DeleteAllAttributes;
GO

CREATE SYNONYM DeleteAllAttributes FOR Logging.DeleteAllAttributes;
GO

Actor #4 – Views for monitoring/analyzing

These are some basic views to look at what is happening or what already happened. Feel free to expand these as your needs dictate

  • Logging.vwActiveLoggingSessions – Active connections that are logging now!
  • Logging.vwLogOfActiveSessions – The logs corresponding to the currently active sessions
  • Logging.vwLogOfActiveSessionLatestEntry – The latest log entry of the active sessions
  • Logging.vwLogSummaryByLogType – Summary information of log data by Log Type
  • Logging.vwLogSummaryByStep – Summary information of log data by Step

--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
--BEGIN: Views
--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

IF EXISTS(SELECT * FROM sys.views WHERE name = 'vwActiveLoggingSessions')
	DROP VIEW Logging.vwActiveLoggingSessions;
GO

CREATE VIEW Logging.vwActiveLoggingSessions
AS
SELECT
	--CAST(CONTEXT_INFO() AS VARCHAR(128)) AppContextInfo,
	(SELECT TOP 1 AppContextInfo FROM Log WHERE ConnectionId = ec.connection_id) AppContextInfo,
	ec.*
FROM
	sys.dm_exec_connections ec
WHERE
	EXISTS
		(
			SELECT 1
			FROM Log l
			WHERE l.ConnectionId = ec.connection_id
		);
GO

------------------------------------------------------------------------------------------------------------

IF EXISTS(SELECT * FROM sys.views WHERE name = 'vwLogOfActiveSessions')
	DROP VIEW Logging.vwLogOfActiveSessions;
GO

CREATE VIEW Logging.vwLogOfActiveSessions
AS
SELECT
	ec.session_id, ec.connect_time, ec.num_reads, ec.num_writes, ec.last_read, ec.last_write, ec.most_recent_sql_handle,
	l.*
FROM
	Log l
		INNER JOIN sys.dm_exec_connections ec
			ON l.ConnectionId = ec.connection_id
GO

------------------------------------------------------------------------------------------------------------

IF EXISTS(SELECT * FROM sys.views WHERE name = 'vwLogOfActiveSessionLatestEntry')
	DROP VIEW Logging.vwLogOfActiveSessionLatestEntry;
GO

CREATE VIEW Logging.vwLogOfActiveSessionLatestEntry
AS
SELECT l.*
FROM
	Log l INNER JOIN
		(
			--Get the latest log by log type for each active connection
			SELECT  MAX(LogId) LogId
			FROM Logging.vwLogOfActiveSessions
			GROUP BY ConnectionId, LogType
		 ) latest
	ON l.LogId = latest.LogId;
GO	

------------------------------------------------------------------------------------------------------------
IF EXISTS(SELECT * FROM sys.views WHERE name = 'vwLogSummaryByLogType')
	DROP VIEW Logging.vwLogSummaryByLogType;
GO

CREATE VIEW Logging.vwLogSummaryByLogType
AS
SELECT
	DatabaseName,
	LogType,
	AppContextInfo,
	COUNT(DISTINCT ObjectId) DistinctCount,
	COUNT(1) Executions,
	MIN(LogDate) OldestLog,
	MAX(LogDate) NewestLog,
	SUM(DurationMilliSeconds) TotalExecutionMilliSecs,
	MIN(DurationMilliSeconds) FastestExecutionMilliSecs,
	MAX(DurationMilliSeconds) SlowestExecutionMilliSecs,
	AVG(DurationMilliSeconds) AvgExecutionMilliSecs
FROM Log
GROUP BY
	DatabaseName,
	LogType,
	AppContextInfo;
GO
------------------------------------------------------------------------------------------------------------
IF EXISTS(SELECT * FROM sys.views WHERE name = 'vwLogSummaryByStep')
	DROP VIEW Logging.vwLogSummaryByStep;
GO

CREATE VIEW Logging.vwLogSummaryByStep
AS
SELECT
	DatabaseName,
	LogType,
	AppContextInfo,
	AdditionalInfo,
	COUNT(1) Executions,
	MIN(LogDate) OldestLog,
	MAX(LogDate) NewestLog,
	MIN(DurationMilliSeconds) FastestExecutionMilliSecs,
	MAX(DurationMilliSeconds) SlowestExecutionMilliSecs,
	AVG(DurationMilliSeconds) AvgExecutionMilliSecs
FROM Log
GROUP BY
	DatabaseName,
	LogType,
	AppContextInfo,
	AdditionalInfo;

GO
------------------------------------------------------------------------------------------------------------

Actor #5 – Synonym references from other databases (Optional, on SQL 2008 and above)

To make the usage easier you can create synonyms from other databases outside the database that hosts the Logging framework (on the same instance). This makes it transparent to the user thus allowing you to move the logging framework around without affecting functionality by just updating the synonyms! Please do substitute  [Your_Outside_Database] with the database home of Logging. This should in fact be the standard way of doing it to insulate the location from the users of Logging.

--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
--BEGIN: Synonyms in other Databases
--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

--Use this to create synonyms for the Logging related objects in other databases

--
--Table: Logging.Log
--
IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'Log')
	DROP SYNONYM Log
GO

CREATE SYNONYM Log FOR [Your_Outside_Database].Logging.Log;
GO

--
--StoredProc: Logging.StartLog
--
IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'StartLog')
	DROP SYNONYM StartLog
GO

CREATE SYNONYM StartLog FOR [Your_Outside_Database].Logging.StartLog;
GO

--
--StoredProc: Logging.EndLog
--
IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'EndLog')
	DROP SYNONYM EndLog
GO

CREATE SYNONYM EndLog FOR [Your_Outside_Database].Logging.EndLog;
GO

--
--StoredProc: Logging.SetAttribute
--
IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'SetAttribute')
	DROP SYNONYM SetAttribute;
GO

CREATE SYNONYM SetAttribute FOR [Your_Outside_Database].Logging.SetAttribute;
GO

--
--StoredProc: Logging.GetAttribute
--
IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'GetAttribute')
	DROP SYNONYM GetAttribute;
GO

CREATE SYNONYM GetAttribute FOR [Your_Outside_Database].Logging.GetAttribute;
GO

--
--StoredProc: Logging.DeleteAttribute
--
IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'DeleteAttribute')
	DROP SYNONYM DeleteAttribute;
GO

CREATE SYNONYM DeleteAttribute FOR [Your_Outside_Database].Logging.DeleteAttribute;
GO

--
--StoredProc: Logging.ShowAllAttributes
--
IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'ShowAllAttributes')
	DROP SYNONYM ShowAllAttributes;
GO

CREATE SYNONYM ShowAllAttributes FOR [Your_Outside_Database].Logging.ShowAllAttributes;
GO

--
--StoredProc: Logging.DeleteAllAttributes
--
IF EXISTS (SELECT * FROM sys.objects WHERE type = 'SN' AND name = 'DeleteAllAttributes')
	DROP SYNONYM DeleteAllAttributes;
GO

CREATE SYNONYM DeleteAllAttributes FOR [Your_Outside_Database].Logging.DeleteAllAttributes;
GO

Examples of usage

Okay, I agree. That looks like a lot to take-in but it really is not! Let us look at look at some examples of how to use this. By the way, everything that is shown below is already part of the implementation code above!

Usage Example 1 – A entry-point caller and a called procedure

Here, we create temporary stored procedures (Refer here for a refresher on temporary stored procedures) to illustrate a main entry-point procedure #MainProc calling another procedure named #LoggingTestProc. This example illustrates a few things

  • How any entry-point procedure should look like
  • How a reusable procedure should look like
  • How steps within a procedure should be logged
  • How errors should be handled

At the end of the test, we drop everything we create for the test although log entries will be real!


--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

---------------
 --Example 0 - A complete example. See the other examples below this example for simpler, step by step understanding
 ---------------

--Drop and recreate if our temporary demo procedures already exist..we will call it later to illustrate
 -------------------------------------------------------------------------------------------------------------

IF object_id('TEMPDB.DBO.#MainProc') IS NOT NULL
 DROP PROCEDURE #MainProc;
 GO

CREATE PROCEDURE #MainProc
 AS
 BEGIN
 ------------------------ Begin: Logging related ------------------------
 --Setting context for application (Do this only once in the entry-point procedure for the whole application/batch)
 -- ***** W A R N I N G *****: DO NOT SET THIS IN EVERY PROCEDURE!!

DECLARE @AppContextInfo VARBINARY(128) = CAST('My Test Application' AS VARBINARY(128))

--This information will be associated with the session and will be accessible in SQL Server system views
 SET CONTEXT_INFO @AppContextInfo

DECLARE @Tag VARCHAR(512) = '<TestApplication> ' +
 '<ProcessName>Test process</ProcessName>' +
 '<ReportToDate><<REPORTTODATE>></ReportToDate>' +
 '<LogId><<LOGID>></LogId>' +
 '<RunNumber><<RUNNUMBER>></RunNumber>' +
 '</TestApplication>';
 DECLARE @CallerProcId BIGINT = @@PROCID;

EXEC Logging.SetAttribute @AttributeName='Log.ParentObjectId', @AttributeValue=@CallerProcId, @AttributeType='BIGINT', @AttributeFormat=NULL;
 ------------------------ End: Logging related ------------------------

 ------------------------ Begin: Tag ------------------------
 --Replace placeholders in the Tag
 SET @Tag = REPLACE(@Tag, '<<REPORTTODATE>>', CONVERT(VARCHAR,getdate()));
 SET @Tag = REPLACE(@Tag, '<<LOGID>>', 232121);
 --SET @Tag = REPLACE(@Tag, '<<RUNNUMBER>>', NEXT VALUE FOR MySchema.RunNumberSeq); --MySchema.RunNumberSeq is a pre-defined sequence object
 SET @Tag = REPLACE(@Tag, '<<RUNNUMBER>>', 12);

EXEC Logging.SetAttribute @AttributeName='Log.Tag', @AttributeValue=@Tag, @AttributeType='XML', @AttributeFormat=NULL;
 ------------------------ End: Tag ------------------------

 --Call chain 1: Say procedure A calls procedure B, B calls C and so on...as part of Batch process 1
 --Call chain 2: As part of Batch process 2, procedure Z could call procedure B, B calls C and so on...the same chain..
 --However the context is different for both call chains. Different context info should be set for each chain..
 --All log entries made as part of Chain 1 will have the same AppContextInfo in Log
 --...and all log entries made as part of Chain 2 will have a different AppContextInfo in Log even for steps that are common for both chains!

 --Pass the tag along to all called procedures...so that log entries will have associated information recorded...and it will be querable later
 --EXEC #LoggingTestProc @CallerTag = @Tag, @CallerProcId = @@PROCID;

--Can forego passing tag and calling proc info and it will be inferred since we SetAttributes for Log.Tag and Log.ParentObjectId
 -- but the ParentObjectId will be this top level procedure for all called procedures in the call tree but it works!
 EXEC #LoggingTestProc
 END
 GO

-------------------------------------------------------------------------------------------------------------

IF object_id('TEMPDB.DBO.#LoggingTestProc') IS NOT NULL
 DROP PROCEDURE #LoggingTestProc;
 GO

CREATE PROCEDURE #LoggingTestProc
 (
 @CallerTag VARCHAR(512) = NULL,
 @CallerProcId BIGINT = NULL
 )
 AS
 BEGIN

------------------------ Begin: Logging related ------------------------
 DECLARE @DBId BIGINT = DB_ID();
 DECLARE @ObjId BIGINT = @@PROCID
 DECLARE @ParentObjId BIGINT = @CallerProcId --Set to NULL if no @CallerProcId parameter
 DECLARE @LogId BIGINT;
 DECLARE @Msg VARCHAR(255);
 DECLARE @StepLogId BIGINT;
 DECLARE @StepMsg VARCHAR(255);
 DECLARE @Tag VARCHAR(512) = @CallerTag; --Set to NULL if no @CallerTag parameter
 ------------------------ End: Logging related ------------------------

 BEGIN TRY
 SET @Msg = 'Starting procedure that calculates distance to moon!'
 EXEC StartLog @DatabaseId = @DBId, @Tag = @Tag, @ObjectID = @ObjId, @ParentObjectId = @ParentObjId, @LogType = 'ANONYMOUS BLOCK', @AdditionalInfo = @Msg, @LogId = @LogId OUTPUT --Log procedure start

---------------
 ----STEP 1 ----
 ---------------
 --Do something that produces an error
 BEGIN TRY
 SET @StepMsg = 'Finding the center of gravity on moon'
 EXEC StartLog @DatabaseId = @DBId, @Tag = @Tag, @ObjectID = @ObjId, @ParentObjectId = @ParentObjId, @LogType = 'STEP', @AdditionalInfo = @StepMsg, @LogId = @StepLogId OUTPUT --Log step start

 DECLARE @Test INT = 1/0;

EXEC EndLog @LogID = @StepLogId; --Log step end
 END TRY
 BEGIN CATCH
 --Error message is automatically captured in the record for current @StepLogId
 EXEC EndLog @LogID = @StepLogId;
 END CATCH;

 ---------------
 ----STEP 2 ----
 ---------------
 --Do something that completes fine - run dynamic SQL

DECLARE @SQL NVARCHAR(255) = 'select top 1 * from sys.tables'

SET @StepMsg = @SQL
 EXEC StartLog @DatabaseId = @DBId, @Tag = @Tag, @ObjectID = @ObjId, @ParentObjectId = @ParentObjId, @LogType = 'SQL', @AdditionalInfo = @StepMsg, @LogId = @StepLogId OUTPUT --Log step start

 --Pretend that the SQL takes 4 seconds to run
 WAITFOR DELAY '00:00:04';
 --EXEC sp_executesql @SQL

EXEC EndLog @LogID = @StepLogId; --Log step end

---------------
 ----STEP 3 ----
 ---------------
 --Unhandled error in this step

SET @StepMsg = @SQL
 EXEC StartLog @DatabaseId = @DBId, @Tag = @Tag, @ObjectID = @ObjId, @LogType = 'SQL', @AdditionalInfo = @StepMsg, @LogId = @StepLogId OUTPUT --Log step start

-- RAISERROR with severity 11-19 will cause execution to jump to the CATCH block.
 RAISERROR ('Moon stuff is too complex! Giving up.', -- Message text.
 16, -- Severity.
 1 -- State.
 );

EXEC EndLog @LogID = @StepLogId; --Log step end

EXEC EndLog @LogID = @LogId; --Log procedure end

END TRY
 BEGIN CATCH
 --Log the error to the procedure log
 IF (@LogId IS NOT NULL)
 EXEC EndLog @LogId = @LogId; --Log procedure end
 IF (@StepLogId IS NOT NULL)
 EXEC EndLog @LogId = @StepLogId; --Log step end

--Comment/uncomment the version of "Rethrow" based on the version of SQL Server you are using

--Rethrow: SQL Server versions below 2012
 --Get the details of the error--that invoked the CATCH block
 DECLARE
 @ErMessage NVARCHAR(2048),
 @ErSeverity INT,
 @ErState INT
 SELECT
 @ErMessage = ERROR_MESSAGE(),
 @ErSeverity = ERROR_SEVERITY(),
 @ErState = ERROR_STATE();

--Should be able to replace with a single THROW statement in SQL 2012
 RAISERROR (@ErMessage, @ErSeverity, @ErState );

--Rethrow: SQL Server versions 2012 and above
 --THROW;

END CATCH;
 END;
 GO

-------------------------------------------------------------------------------------------------------------

--Test call...
 EXEC #MainProc

--Select from the log to show what was logged
 SELECT * FROM Log ORDER BY 1 DESC

 DROP PROCEDURE #LoggingTestProc;
 DROP PROCEDURE #MainProc;

--++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

Usage Example 2 – Simple “fire and forget”

It can be as simple as you want when you leave-out all the optional parameters or as complex as you want when you want to track the minutia.


---------------
 --Example 1
 ---------------
 --This is an example of "fire & forget" logging. We do not care about getting back to the logged entry.
 --Example 1.1 - Simplest call
 DECLARE @LogId BIGINT;
 EXEC StartLog @ObjectID = @@PROCID, @LogId = @LogId OUTPUT;

--Example 1.2 - ..+ Status message is included
 DECLARE @LogId BIGINT;
 EXEC StartLog @ObjectID = @@PROCID, @AdditionalInfo = 'Some status message', @LogId = @LogId OUTPUT;

 --Example 1.3 - ..+ Status message + Log type is included
 DECLARE @LogId BIGINT;
 EXEC StartLog @ObjectID = @@PROCID, @LogType = 'PROCEDURE', @AdditionalInfo = 'Some status message', @LogId = @LogId OUTPUT;

--Example 1.4 - ..+ ParentObjectID is included
 DECLARE @LogId BIGINT;
 DECLARE @ParentObjectId BIGINT;

SET @ParentObjectId = OBJECT_ID('[CLT2EVE_Transforms].[WorkTransformExclude].[Claims_RetroReceiptChangeHistory]')
 EXEC StartLog @ObjectID = @@PROCID, @ParentObjectID = @ParentObjectId, @LogType = 'PROCEDURE', @AdditionalInfo = 'Some status message', @LogId = @LogId OUTPUT;

--Example 1.4 - ..+ DatbaseID is included
 DECLARE @LogId BIGINT;
 DECLARE @DatabaseId BIGINT;
 DECLARE @ParentObjectId BIGINT;

SET @DatabaseId = DB_ID()
 SET @ParentObjectId = OBJECT_ID('[CLT2EVE_Transforms].[WorkTransformExclude].[Claims_RetroReceiptChangeHistory]')
 EXEC StartLog @DatabaseId = @DatabaseId, @ObjectID = @@PROCID, @ParentObjectID = @ParentObjectId, @LogType = 'PROCEDURE', @AdditionalInfo = 'Some status message', @LogId = @LogId OUTPUT;

Usage Example 3 – Simple “fire and forget” & SET CONTEXT_INFO

SET CONTEXT_INFO is magical and should be used (only in the entry-point procedures IMHO, otherwise it is abuse!). The logger “recognizes” the context information and records it in the log without you making an effort!


--In this example, we set context info once at the beginning of the session and use that to tie all log entries...
 -- This context info, could be different for the same procedure for calls made from different applications!! That is the beauty of this.
 -- The context info can also be changed mid-way through a process if that is the requirement!

DECLARE @LogId BIGINT;
 DECLARE @Msg VARCHAR(255) = 'Process customer records';
 DECLARE @AppContextInfo VARBINARY(128) = CAST('My Fancy Application' AS VARBINARY(128))

SET CONTEXT_INFO @AppContextInfo

--Register start
 EXEC StartLog @ObjectID = @@PROCID, @AdditionalInfo = @Msg, @LogId = @LogId OUTPUT;

--Take a look that log entry's AppContextInfo column!
 SELECT AppContextInfo FROM Log WHERE LogId = @LogId;

Usage Example 4 – Start & Stop with “Duration”

In this example, we don’t “fire and forget” but rather, we store what ID we fired and we close it out to thereby record the duration of the call!


--In this example, we want to track the start and end time for the procedure (using OUTPUT variable @LogId)
 DECLARE @LogId BIGINT;
 DECLARE @Msg VARCHAR(255) = 'Process customer records';

--Register start
 EXEC StartLog @ObjectID = @@PROCID, @AdditionalInfo = @Msg, @LogId = @LogId OUTPUT;

--[Make the actual call to process customer record here]

--Register end
 EXEC EndLog @LogID = @LogId;

--At this point, you can select the log entry from Log
 SELECT * FROM Log WHERE LogId = @LogId;

Usage Example 5 – Multiple level “Durations”

Here, we not only record the duration of the main overall action of the procedure but also the duration of each of the individual steps.


--In this example, we want to track the start and end time for the procedure (using OUTPUT variable @LogId)
 -- + we want to track the start and end time of every step within the procedure..

DECLARE @LogId BIGINT;
 DECLARE @Msg VARCHAR(255) = 'Process customer records';

 DECLARE @StepLogId INT;
 DECLARE @StepMsg VARCHAR(255);

 --Register ***procedure*** start
 EXEC StartLog @ObjectID = @@PROCID, @AdditionalInfo = @Msg, @LogId = @LogId OUTPUT;

--Register ***Step 1*** start
 SET @StepMsg = 'About to run step 1 for procedure!'
 EXEC StartLog @ObjectID = @@PROCID, @LogType = 'STEP', @AdditionalInfo = @StepMsg, @LogId = @StepLogId OUTPUT
 --Register ***Step 1*** end
 EXEC EndLog @LogId = @StepLogId;

--Register ***Step 2*** start
 SET @StepMsg = 'About to run step 2 for procedure!'
 EXEC StartLog @ObjectID = @@PROCID, @LogType = 'STEP', @AdditionalInfo = @StepMsg, @LogId = @StepLogId OUTPUT
 --Register ***Step 2*** end
 EXEC EndLog @LogId = @StepLogId;

--Register ***procedure*** end
 EXEC EndLog @LogID = @LogId;

--At this point, you can select the log entry from Log
 SELECT * FROM Log ORDER BY 1 DESC;

Usage Example 5.2 – Recording in a LOOP

Although we are logging inside the loop, notice how each corresponding “start” is “ended”.


------------------------------------------------------------
SET @StepMsg = 'Loop through ProbeTargetRunIds and process each';
------------------------------------------------------------
EXEC StartLog @DatabaseId = @DBId, @Tag = @Tag, @ObjectID = @ObjId, @ParentObjectId = @ParentObjId, @LogType = 'STEP', @AdditionalInfo = @StepMsg, @LogId = @StepLogId OUTPUT --Log step start

WHILE EXISTS (SELECT 1 FROM #ControlTable)
BEGIN

SELECT TOP 1
@ProbeTargetRunId = ProbeTargetRunId
FROM #ControlTable
ORDER BY ProbeTargetRunId asc;

------------------------------------------------------------
SET @StepMsg = 'Process ProbeTargetRunId: ' + STR(@ProbeTargetRunId);
------------------------------------------------------------
EXEC StartLog @DatabaseId = @DBId, @Tag = @Tag, @ObjectID = @ObjId, @ParentObjectId = @ParentObjId, @LogType = 'LOOP', @AdditionalInfo = @StepMsg, @LogId = @LoopLogId OUTPUT --Log step start

INSERT INTO [Backups].[DBBackupFact]
(--[DBBackupFactKey]
[DBBackupFactAltKey]
,[ProbeTargetRunId]
,[ProbeRunId]
,[SnapshotAgentTime]
,[SnapshotHostTime])
SELECT
[DBBackupFactAltKey]
,[ProbeTargetRunId]
,[ProbeRunId]
,[SnapshotAgentTime]
,[SnapshotHostTime]
FROM
Backups.BackupsFactAllDBsView vw
WHERE
vw.ProbeRunId = @ProbeRunIdToUse
AND vw.ProbeTargetRunId = @ProbeTargetRunId
AND vw.GroupRank = 1;

--Update the statistics on the DBBackupFact table so that queries do not slow down as more and more data gets inserted!
UPDATE STATISTICS [Backups].[DBBackupFact];
DELETE #ControlTable
WHERE ProbeTargetRunId = @ProbeTargetRunId;

EXEC EndLog @LogID = @LoopLogId; --Log loop end
END;

Usage Example 6 – Recording additional run-specific context information

There are reasons to record run-specific information to log. This will later help us examine how long a re-usable procedure or a step took for one business entity related processing vs. another! XML is the glue that makes this magic happen.


--In this example, we record a lot of additional information in a structured manner (XML) in the Tag column that is queryable later
 -- Notice, how "MontlyRetroRun" is used as the root node and later query against the log table uses that

DECLARE @LogId BIGINT;
 DECLARE @Msg VARCHAR(255) = 'Process customer records';

DECLARE @Tag VARCHAR(512) = '<MonthlyRetroRun> ' +
 '<ProcessName>MonthlyRetro</ProcessName>' +
 '<ReportToDate><<REPORTTODATE>></ReportToDate>' +
 '<RetroCessionMonthlyActivityLogId><<RETROCESSIONMONTHLYACTIVITYLOGID>></RetroCessionMonthlyActivityLogId>' +
 '<BatchNumber><<BATCHNUMBER>></BatchNumber>' +
 '<RunSequenceNumber><<RUNSEQUENCENUMBER>></RunSequenceNumber>' +
 '</MonthlyRetroRun>';

------------------------ Begin: Tag ------------------------
 --Replace placeholders in the Tag
 SET @Tag = REPLACE(@Tag, '<<REPORTTODATE>>', CONVERT(VARCHAR,getdate()));
 SET @Tag = REPLACE(@Tag, '<<RETROCESSIONMONTHLYACTIVITYLOGID>>', 232121);
 SET @Tag = REPLACE(@Tag, '<<BATCHNUMBER>>', LTRIM(STR(11)));
 SET @Tag = REPLACE(@Tag, '<<RUNSEQUENCENUMBER>>', LTRIM(STR(99999)));

SET @Msg = 'Fetch/decide on values for decision making variables!'
 EXEC StartLog @Tag = @Tag, @ObjectID = @@PROCID, @LogType = 'PROCEDURE', @AdditionalInfo = @Msg, @LogId = @LogId OUTPUT --Log procedure start
 ------------------------ End: Tag ------------------------

 --At this point, you can select the log entry from Log where
 SELECT r.value('RunSequenceNumber[1]','INT') AS RunNumber,
 r.value('ReportToDate[1]','DateTime') AS ReportToDate,
 l.*
 FROM Log l
 CROSS APPLY Tag.nodes('/MonthlyRetroRun') AS Runs(r)

Usage Example 6.1 – Querying for specifics in XML context

The XML column Tag has XML information related to the specific run which in turn can be queried specifically!


--Example 1
 -- Querying XML data column "Tag"
 --If Log.Tag column has the value "<MonthlyRetroRun RunId="1">Test</MonthlyRetroRun>", one could query like this.
 -- Reference: http://thegrayzone.co.uk/blog/2010/03/querying-sql-server-xml-data/
 SELECT r.value('MonthlyRetroRun[1]','varchar(15)')
 FROM Log
 CROSS APPLY Tag.nodes('/') AS Runs(r)

 --Example 2
 -- Somewhat more complex querying of XML data column "Tag"
 UPDATE Log
 SET Tag = '<MonthlyRetroRun ReportToDate="' + CONVERT(VARCHAR(25), CONVERT(datetime, '2014-02-28 00:00:00.000')) + '"> ' +
 '<ReportToDate>' + CONVERT(VARCHAR(25), CONVERT(datetime, '2014-02-28 00:00:00.000')) + '</ReportToDate>' +
 '<RunNumber>1</RunNumber>' +
 '<BatchSize>' + LTRIM(STR(1000)) + '</BatchSize>' +
 '<MaxRecords>' + LTRIM(STR(50000)) + '</MaxRecords>' +
 '</MonthlyRetroRun>'
 WHERE LogId = 4

SELECT r.value('RunNumber[1]','INT') AS RunNumber,
 r.value('ReportToDate[1]','DateTime') AS ReportToDate
 FROM Log
 CROSS APPLY Tag.nodes('/MonthlyRetroRun') AS Runs(r)
 WHERE LogId = 4 

Usage Example 7 – Setting Attributes

Attributes are variable values that you want to keep track of. They are not recorded in the log automatically but think of them as GLOBAL variables across runs that you don’t have to keep track of.


 Logging.SetAttribute @AttributeName='TEST', @AttributeValue='DAFSFASFSA', @AttributeType='VARCHAR', @AttributeFormat=NULL;
 SELECT * FROM ##TempAttributesTable;

Usage Example 8 – Using Attributes

This example shows how to set and get (USE) an attribute!


---------------
 --Example 1 - Set and Get a simple string that happens to be XML. Need to do conversion yourself. Notice SQL_VARIANT to VARCHAR(200) conversion for @AttributeValue
 ---------------

--Set some attribute in Procedure A.
 -----------------------------------
 DECLARE @Tag VARCHAR(200)= '<TestApplication> ' +
 '<ProcessName>Test process</ProcessName>' +
 '<LogId>1214</LogId>' +
 '<RunNumber>22</RunNumber>' +
 '</TestApplication>';
 EXEC Logging.SetAttribute @AttributeName='Tag', @AttributeValue=@Tag, @AttributeType='XML', @AttributeFormat=NULL;

EXEC Logging.ShowAllAttributes;

--Get the value of that attribute in Procedure B
 -----------------------------------
 DECLARE @AttributeName VARCHAR(100) = 'Tag';
 DECLARE @AttributeValue SQL_VARIANT;
 DECLARE @AttributeType VARCHAR(25);
 DECLARE @AttributeFormat VARCHAR(100);

EXEC Logging.GetAttribute @AttributeName='Tag', @AttributeValue=@AttributeValue OUTPUT, @AttributeType=@AttributeType OUTPUT, @AttributeFormat=@AttributeFormat OUTPUT, @IgnoreIfAttributeIsMissing=1

 PRINT @AttributeName;
 PRINT CONVERT(VARCHAR(200), @AttributeValue);
 PRINT @AttributeType;
 PRINT @AttributeFormat;

Usage Example 9 – Displaying attributes

..another example of how to use an attribute and display it when needed!


--Set some attribute
 -----------------------------------
 DECLARE @Tag VARCHAR(200)= '<TestApplication> ' +
 '<ProcessName>Test process</ProcessName>' +
 '<LogId>1214</LogId>' +
 '<RunNumber>22</RunNumber>' +
 '</TestApplication>';
 EXEC Logging.SetAttribute @AttributeName='Log.Tag', @AttributeValue=@Tag, @AttributeType='XML', @AttributeFormat=NULL;

EXEC Logging.ShowAllAttributes;

--Get the value of that attribute in another procedure
 -----------------------------------
 DECLARE @AttributeName VARCHAR(100) = 'Log.Tag1';
 DECLARE @AttributeValue SQL_VARIANT;
 EXEC Logging.GetAttribute @AttributeName=@AttributeName, @AttributeValue=@AttributeValue OUTPUT, @AttributeType=NULL, @AttributeFormat=NULL, @IgnoreIfAttributeIsMissing=1

 PRINT @AttributeName;
 PRINT CONVERT(VARCHAR(200), @AttributeValue);

Usage Example 10 – Deleting attributes

This example shows how to delete attributes so that you are not piling up!


EXEC Logging.SetAttribute @AttributeName='TEST', @AttributeValue='Test value', @AttributeType='VARCHAR', @AttributeFormat=NULL;

EXEC Logging.DeleteAttribute @AttributeName='TEST'

EXEC Logging.ShowAllAttributes

Usage Example 11 – Displaying attributes

This example shows how to display all attributes via PRINT


---------------
--Example 1 - Show all the attributes of current connection
---------------

EXEC Logging.SetAttribute @AttributeName='TEST', @AttributeValue='Test value', @AttributeType='VARCHAR', @AttributeFormat=NULL;

EXEC Logging.ShowAllAttributes

---------------
--Example 2 - Show all the attributes of all connections
---------------

EXEC Logging.SetAttribute @AttributeName='TEST', @AttributeValue='Test value', @AttributeType='VARCHAR', @AttributeFormat=NULL;

EXEC Logging.ShowAllAttributes @ShowGlobal = 1

Usage Example 12 – Deleting attributes

This example show how to delete all recorded attributes


---------------
--Example 1 - Delete all the attributes of current connection
---------------

EXEC Logging.SetAttribute @AttributeName='TEST', @AttributeValue='Test value', @AttributeType='VARCHAR', @AttributeFormat=NULL;

EXEC Logging.DeleteAllAttributes

EXEC Logging.ShowAllAttributes

Some sample output from the real-world!


SELECT * FROM Logging.vwLogSummaryByLogType

DatabaseName LogType AppContextInfo DistinctCount Executions OldestLog NewestLog TotalExecutionMilliSecs FastestExecutionMilliSecs SlowestExecutionMilliSecs AvgExecutionMilliSecs
--------------------------------------------------------------------------------------------------------------------------------------------- ------------- ----------- --------------------------- --------------------------- ----------------------- ------------------------- ------------------------- ---------------------
VaultDM FUNCTION Probe - Load Backup Data 7 553 2016-11-10 09:02:54.1330000 2017-01-07 22:28:43.0570000 640168074 50 42263176 1172469
VaultDM LOOP Probe - Load Backup Data 3 13859 2016-11-10 09:41:38.1130000 2017-01-07 22:28:43.0630000 96721448 20 36383810 7071
VaultDM STEP Probe - Load Backup Data 6 2385 2016-11-10 09:02:54.1370000 2017-01-07 22:29:07.2230000 623011833 0 37643397 261989

(3 row(s) affected)

Please improve!

Oracle has what is called an “autonomous transaction“. In plain English, it means, one can log the “logging” without affecting the overall transaction. I hope SQL Server has it soon! Today, this means that if you log to a table, you will lose the logging if you rolled back the transaction. You have the save off the message, then rollback the overall transaction and only then record the logging related details.

When it comes to logging, nothing is perfect! Please improve and make it as complex as you see fit! There are no licenses. Please attribute the source (if you can) as I did to Aaron Bertrand. If you do put it on GitHub with your improvements, please let me know so that I can participate. Happy logging!

Update (Jan 18, 2017):

I was able to add “autonomous transaction” type support to the logger using the means available in SQL Server (a loopback linked server). The new and updated code is available on GitHub.

https://github.com/SQLJana/TSQL_Logger

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s