Sql-server – Impossible to log errors after dooming a transaction within an INSERT-EXEC statement

error handlingsql server

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 INSERT-EXEC statement:

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.

Best Answer

There is a way to first write a 'custom' log entry by using raiserror with LOG. It is going to raise the error before the throw, and afterwards we will read from the log using xp_readerrorlog.

It is for sure not going to be pretty, and not really suited for production.

But here it goes:

  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
 -- Create a custom error message with an identifier for reading from the log (WrapperIssue)
 DECLARE @ErrorMessage NVARCHAR(4000)
 DECLARE @ErrorSeverity INT
 SELECT
  @ErrorMessage = (cast(ERROR_MESSAGE() as nvarchar(2000)) + N' WrapperIssue'),
  @ErrorSeverity = ERROR_SEVERITY()

 -- RaisError with logging to the SQL Server LOG
 RAISERROR(@ErrorMessage, @ErrorSeverity, 1) WITH LOG
        ;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

-- Read from the rror log using a text filter + only for the last minute
-- Credits for query: https://sqlserver-help.com/2014/12/10/sql-internals-useful-parameters-for-xp_readerrorlog/
Declare @InstanceName nvarchar(4000),
        @LogType int,
        @ArchiveID int,
        @Filter1Text nvarchar(4000),
        @Filter2Text nvarchar(4000),
        @FirstEntry datetime,
        @LastEntry datetime

Select  @InstanceName=NULL,    -- Don't know ?
        @LogType = 1,          -- 2 = SQL SERVER
        @Filter1Text='WrapperIssue',     -- First Text Filter
        @Filter2Text=NULL,     -- Second Text Filter
        @FirstEntry=dateadd(minute,-1,getdate()) ,      -- Start Date
        @LastEntry=NULL        -- End Date
Create table #readerrorlog(LogDate datetime2, 
                           Processinfo nvarchar(2000),
                           text nvarchar(4000))
-- Get the data from the error log
insert into #readerrorlog
EXEC master.dbo.xp_readerrorlog @ArchiveID, @LogType, @Filter1Text, @Filter2Text, @FirstEntry, @LastEntry, N'DESC', @InstanceName


-- Finally insert into the TempLog table
INSERT INTO TempLog(LogMessage) 
select Text from #readerrorlog


select * From TempLog


drop table #readerrorlog
Related Question