We have a stored procedure that does some work within a transaction, wrapped within a stored procedure that returns some result data using the
INSERT-EXEC method of sharing data.
After observing the generic error message "the transaction has been rolled back" floating back up to the UI, we went to check the log tables but found nothing. We ended up having to track down the error through the SQL Server Profiler (which is made excessively difficult by omitting things like line number in the
Exception event class). I tracked down our logging failure as the reason in the first paragraph.
How can a failure in such a circumstance possibly be logged?
Here is some sample code demonstrating how it is impossible to write to a table after dooming a transaction while within an
IF OBJECT_ID('TempLog') IS NULL CREATE TABLE TempLog ( RowNumber INT NOT NULL IDENTITY(1, 1) ,LogMessage VARCHAR(MAX) NOT NULL ,TimestampUtc DATETIME NOT NULL DEFAULT(GETUTCDATE()) ) GO TRUNCATE TABLE TempLog GO IF OBJECT_ID('Failer') IS NOT NULL DROP PROCEDURE Failer GO CREATE PROCEDURE Failer AS BEGIN BEGIN TRANSACTION; SELECT 1 / 0 --unmatched COMMIT for fun END GO IF OBJECT_ID('Wrapper') IS NOT NULL DROP PROCEDURE Wrapper GO CREATE PROCEDURE Wrapper AS BEGIN BEGIN TRY EXEC Failer SELECT 'success' END TRY BEGIN CATCH BEGIN TRY INSERT INTO TempLog(LogMessage) VALUES ('test 1') END TRY BEGIN CATCH PRINT 'failed test 1: ' + ERROR_MESSAGE() END CATCH BEGIN TRY IF @@TRANCOUNT > 0 ROLLBACK TRANSACTION; INSERT INTO TempLog(LogMessage) VALUES ('test 2') END TRY BEGIN CATCH PRINT 'failed test 2: ' + ERROR_MESSAGE() END CATCH BEGIN TRY IF XACT_STATE() = -1 ROLLBACK TRANSACTION; IF XACT_STATE() = 1 COMMIT TRANSACTION; INSERT INTO TempLog(LogMessage) VALUES ('test 3') END TRY BEGIN CATCH PRINT 'failed test 3: ' + ERROR_MESSAGE() END CATCH ;THROW END CATCH END GO DECLARE @Result TABLE(RowNumber INT IDENTITY(1, 1), OtherStuff VARCHAR(MAX) NULL) INSERT INTO @Result(OtherStuff) EXEC Wrapper SELECT [@Result]='', * FROM @Result IF XACT_STATE() = -1 ROLLBACK TRANSACTION; IF XACT_STATE() = 1 COMMIT TRANSACTION; GO SELECT [Trancount] = @@TRANCOUNT SELECT * FROM TempLog
The final selection statements return
@@TRANCOUNT as 0 and nothing in
TempLog with these messages:
failed test 2: Cannot use the ROLLBACK statement within an INSERT-EXEC statement. failed test 3: Cannot use the ROLLBACK statement within an INSERT-EXEC statement. Msg 8134, Level 16, State 1, Procedure Failer, Line 60 Divide by zero error encountered.
(but somehow the first
INSERT statement to
TempLog is permitted even though it is within a doomed transaction)
How is it possible to write any sort of log data in such a case? Ideally it goes to the log table as we have an admin GUI which lets us inspect it without bugging anybody to get us direct backend access.
P.S. The management log doesn't include anything from my testing.
P.P.S. I dislike the
INSERT-EXEC method, but we have to deal with it sometimes.