Tuesday, May 31, 2022

Log T-SQL processing events

I frequently see questions about the best way to log events in T-SQL processing, including success and failure messages.  This method has the following advantages:

  • Minimal code needs to be added to your procedures.
  • Can log both informational status messages and error messages.
  • Events go into a log table, and are displayed in the SSMS messages pane, and if it has an error it “throws” the error to the calling program with error detail info.
  • Error messages include the following:
    • Date and time
    • Application that is running the procedure
    • User that is running the procedure
    • Server name
    • Database name
    • Schema name
    • Procedure name (this is the calling procedure where the even happened)
    • Message to record, e.g. “Start of MyProc”, “Insert sales”
    • Line number of the error
    • Error Message
    • Error number
    • Error severity
    • Error state
    • (optionally) the SQL command causing the error

Start by creating the following table to log events:

CREATE TABLE DW.EventLog (
id            int IDENTITY(1,1) NOT NULL,
DateLogged    datetime NOT NULL DEFAULT (GETDATE()),
AppName       nvarchar(240),
UserName      nvarchar(128) DEFAULT (USER_NAME()),
ServerName    nvarchar(240),
DBName        nvarchar(240),
SchemaName    nvarchar(128),
ProcName      nvarchar(128),
[Message]     varchar(240),
ErrorLine     int,
ErrorMessage  nvarchar(4000),
ErrorNumber   int,
ErrorSeverity int,
ErrorState    int
)

Create the following procedure to log the event:

--Procedure to log error and success information.
--Call this using: EXEC DW.LogEvent 'Description of next step', @@PROCID
ALTER PROCEDURE [DW].[LogEvent] @Message VARCHAR(240) = '', @ProcID int = NULL
AS  
BEGIN

DECLARE 
  @AppName  		NVARCHAR(128)
, @UserName 		NVARCHAR(128)
, @ServerName		NVARCHAR(128)
, @DBName   		NVARCHAR(128)
, @SchemaName		NVARCHAR(128)
, @ProcName 		NVARCHAR(128)
, @ErrorLine		INT
, @ErrorMessage		NVARCHAR(4000)
, @ErrorNumber		INT
, @ErrorSeverity	INT
, @ErrorState		INT
, @FullMessage		NVARCHAR(max);

SET @AppName		= APP_NAME()
SET @UserName		= USER_NAME()
SET @ServerName		= @@SERVERNAME
SET @DBName 		= DB_NAME()
SET @SchemaName		= COALESCE(LEFT(ERROR_PROCEDURE(),CHARINDEX('.',ERROR_PROCEDURE())-1), OBJECT_SCHEMA_NAME(@ProcID), OBJECT_SCHEMA_NAME(@@PROCID))
SET @ProcName		= COALESCE(SUBSTRING(ERROR_PROCEDURE(),CHARINDEX('.',ERROR_PROCEDURE())+1,128), OBJECT_NAME(@ProcID), OBJECT_NAME(@@PROCID))
SET @ErrorLine		= ERROR_LINE()
SET @ErrorMessage	= ERROR_MESSAGE()
SET @ErrorNumber	= ERROR_NUMBER()
SET @ErrorSeverity	= ERROR_SEVERITY()
SET @ErrorState		= ERROR_STATE()

--Log the error.
INSERT INTO [DW].[EventLog](
AppName,
ServerName,
DBName,
SchemaName,
ProcName,
[Message],
ErrorLine, 
ErrorMessage, 
ErrorNumber,  
ErrorSeverity, 
ErrorState
) 
SELECT
@AppName,
@ServerName,
@DBName,
@SchemaName,
@ProcName,
@Message,
@ErrorLine,  
@ErrorMessage,  
@ErrorNumber,
@ErrorSeverity,  
@ErrorState;

SET @FullMessage = CONCAT
( '['	, @ServerName
, '].['	, @DBName
, '].['	, @SchemaName
, '].['	, @ProcName
, ']: '	, @Message
);

IF @ErrorNumber IS NOT NULL
SET @FullMessage = LEFT(CONCAT
( @FullMessage
, '. ErrorLine: '      , TRIM(STR(@ErrorLine))
, '. ErrorMessage: '   , @ErrorMessage
, '. ErrorNumber: '    , TRIM(STR(@ErrorNumber))
, '. ErrorSeverity: '  , TRIM(STR(@ErrorSeverity))
, '. ErrorState: '     , TRIM(STR(@ErrorState))
, '. Application: '    , @AppName
, '. User: '           , @UserName
), 2048);

--Display the message.
PRINT @FullMessage;

--If this is an error then throw the error to the calling application, otherwise return to calling application.
IF @ErrorNumber IS NOT NULL
	THROW 50000, @FullMessage, @ErrorState;
ELSE
	RETURN

END

Here is an example of a procedure that is modified to log these events.  The changes you need to make to your code are:

  • Add “DECLARE @step VARCHAR(240);
  • Add the TRY/CATCH.  Note: the @@PROCID is needed to accurately record the name of the current procedure.
  • Add the “EXEC DW.LogEvent…” lines to announce information that you want recorded.
  • Add “SET @step = 'what is next'” prior to each SQL command to describe where it failed.

CREATE PROCEDURE [DW].[test_error]
AS
BEGIN TRY
	DECLARE @step VARCHAR(240);

	EXEC DW.LogEvent 'Starting error test', @@PROCID;	--announce start of run


	--Body of the procedure follows
	SET @step = 'second step'	--describe each coming step
	SELECT 1/0


	EXEC DW.LogEvent 'Error test completed', @@PROCID;	--announce end of run

	RETURN

END TRY
BEGIN CATCH
	EXEC DW.LogEvent @step, @@PROCID;
END CATCH

The only thing missing is the actual text of the SQL command that caused the error. If that is needed you can execute your commands using the following procedure:

CREATE PROCEDURE [DW].[ExecuteSQL] @SQL NVARCHAR(max), @ProcID int = NULL
AS
--Procedure to execute a sql command and log the error and the offending sql text.
--Call this using: EXEC DW.ExecuteSQL 'SQL Command here', @@PROCID
BEGIN
	BEGIN TRY  
		DECLARE @SqlCommand	NVARCHAR(240)
		SET @SqlCommand = LEFT(CONCAT('SQL: ', @SQL), 240)
		--execute the sql command
		EXECUTE sp_executesql @SQL
	END TRY  
	BEGIN CATCH  
		PRINT 'ERROR WITH THE FOLLOWING COMMAND:'
		PRINT @SQL
		-- Log the error.  
		EXECUTE DW.LogEvent @SqlCommand, @ProcID;
	END CATCH;
END;

No comments:

Post a Comment