How to log errors with T-SQL try/catch

Today a co-worker of mine (Brad) asked a question regarding the usage of T-SQL’s Try-Catch block. Brad wanted to write to a table every time a stored procedure failed so that it was easy to recover the error messages and track issues. His Try-Catch block looked something like this.

BEGIN TRY

BEGIN TRANSACTION

PRINT 'do work'

COMMIT

END TRY
BEGIN CATCH

DECLARE @errMsg VARCHAR(500) = ERROR_MESSAGE()
, @errState INT = ERROR_STATE()
, @errSeverity int = ERROR_SEVERITY()

INSERT INTO dbo.Failures (errorMsg)
VALUES (@errMsg)

RAISERROR(@errMsg, @errSeverity, @errState);

END CATCH

The intention was that the RAISERROR command would be similar to a re-throw and roll back the transaction after writing to the table. Quick tangent, SQL Server 2012’s new THROW command is preferred, in my opinion, over RAISERROR. Check out more on THROW here. But I digress. The problem with the above code was that we knew deadlocks were occurring but there was never a single insert into the dbo.Failures table.

Before announcing the solution, let’s set up a test for demonstration purposes.

The test

Setup

This quick script will create our table with data and our table which will be used to log errors.

CREATE TABLE dbo.ToBeBlocked (id TINYINT NOT NULL)
CREATE TABLE dbo.Failures (id TINYINT IDENTITY(1,1) NOT NULL
, errorMsg VARCHAR(500) NOT NULL)
GO
INSERT INTO dbo.ToBeBlocked (id) VALUES (1);
INSERT INTO dbo.ToBeBlocked (id) VALUES (2);
GO 10

Script 1

In this script we have the Try-Catch block seen above. I’ve added a select and an update to help us setup a deadlock condition. The DEADLOCK_PRIORITY and REPEATABLE READ isolation level ensures that we take a lock on all rows in the table and try to update them after another script has stepped in the way. The WAITFOR DELAY is used to give time for you to run Script 2 in another query window before the update fires. Finally, it will query the Failures table to see if we inserted any rows.

SET DEADLOCK_PRIORITY LOW

SET TRANSACTION ISOLATION LEVEL REPEATABLE READ

BEGIN TRY

BEGIN TRANSACTION

SELECT id FROM dbo.ToBeBlocked;

-- Give us a chance to run the other script
-- to cause a deadlock
WAITFOR DELAY '00:00:05';

UPDATE dbo.ToBeBlocked
SET id = 3
WHERE id = 2

COMMIT

END TRY
BEGIN CATCH

DECLARE @errMsg VARCHAR(500) = ERROR_MESSAGE()
, @errState INT = ERROR_STATE()
, @errSeverity int = ERROR_SEVERITY()

INSERT INTO dbo.Failures (errorMsg)
VALUES (@errMsg)

RAISERROR(@errMsg, @errSeverity, @errState);

END CATCH

SELECT * FROM dbo.Failures

Script 2

This script will be executed during the 5 sec delay from running Script 1. This will cause our deadlock and become the victor because Script 1’s DEADLOCK_PRIORITY is set to LOW, making it the victim.

BEGIN TRANSACTION

UPDATE dbo.ToBeBlocked
SET id = 2
WHERE id = 2;

COMMIT

The results

By executing Script 1 and causing a deadlock with Script 2, we receive these messages.

(20 row(s) affected)

(0 row(s) affected)
Msg 3930, Level 16, State 1, Line 28
The current transaction cannot be committed and cannot support operations that write to the log file. Roll back the transaction.
Msg 50000, Level 13, State 45, Line 31
Transaction (Process ID 52) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.

(0 row(s) affected)
Msg 3998, Level 16, State 1, Line 1
Uncommittable transaction is detected at the end of the batch. The transaction is rolled back.

We can also see that no records were inserted into the Failures table.

try-catch-result-1

The solution

The reason that Brad was left without any log records was because the INSERT INTO dbo.Failures was still part of the first, uncommitted, transaction. Since that transaction was deadlocked and could not be committed the, “Uncommittable transaction is detected,” error was thrown and everything was rolled back, including the Failures record. The solution to this problem is to add a ROLLBACK statement before the INSERT. This will rollback the transaction which is in an uncommittable state and then allow the Failures record to be INSERTed as a separate transaction.

BEGIN CATCH

DECLARE @errMsg VARCHAR(500) = ERROR_MESSAGE()
, @errState INT = ERROR_STATE()
, @errSeverity int = ERROR_SEVERITY()

ROLLBACK --Solution

INSERT INTO dbo.Failures (errorMsg)
VALUES (@errMsg)

RAISERROR(@errMsg, @errSeverity, @errState);

END CATCH

New results

(20 row(s) affected)

(0 row(s) affected)

(1 row(s) affected)
Msg 50000, Level 13, State 45, Line 33
Transaction (Process ID 52) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.

(1 row(s) affected)

try-catch-result-2


Microsoft SQL Server resourceWritten by Derik Hammer of SQL Hammer

Derik is a data professional focusing on Microsoft SQL Server. His passion focuses around high-availability, disaster recovery, continuous integration, and automated maintenance. his experience has spanned long-term database administration, consulting, and entrepreneurial ventures.

Derik gives the SQL community credit for plugging the gaps in his knowledge when he was a junior DBA and, now that his skills have matured, started SQLHammer.com as one small way to give back and continue the cycle of shared learning.

Derik is the owner and lead author of SQL Hammer, a Microsoft SQL Server resource.

For more information, visit http://sqlhammer.com/. Follow Derik on Twitter for SQL tips and chat

Leave a Reply

%d bloggers like this: