CODEWITHSUNDEEP
sql-serversql-server-2008error-handlingtry-catcherror-logging
David
David

Reputation:

Logging SQL Errors

SQL Server 2008 has a new try/catch structure. If I encounter an error in a sequence of nested stored procedures, I like to log the call stack in an error table. The problem is that if I have started a transaction (which will be true for operations that update the db), an records written to the error table will be removed when the code in the catch part of the try/catch statement rolls back the transaction.

Any hints as to how I can get around this are welcome.

Upvotes: 3

Views: 946

Answers (2)

KM.
KM.

Reputation: 103579

this creates two test tables and three nested procedures, with transactions:

if exists (select * from sysobjects where id = object_id(N'[dbo].ProcedureA') and OBJECTPROPERTY(id, N'IsProcedure') = 1) drop procedure [dbo].ProcedureA
if exists (select * from sysobjects where id = object_id(N'[dbo].ProcedureB') and OBJECTPROPERTY(id, N'IsProcedure') = 1) drop procedure [dbo].ProcedureB
if exists (select * from sysobjects where id = object_id(N'[dbo].ProcedureC') and OBJECTPROPERTY(id, N'IsProcedure') = 1) drop procedure [dbo].ProcedureC
if exists (select * from sysobjects where id = object_id(N'YourLogTable') and OBJECTPROPERTY(id, N'IsTable') = 1) drop table YourLogTable
if exists (select * from sysobjects where id = object_id(N'YourTestTable') and OBJECTPROPERTY(id, N'IsTable') = 1) drop table YourTestTable

go
CREATE TABLE YourLogTable
(
     LogID    int               not null primary key identity(1,1)
    ,LogDate  datetime          not null default GETDATE()
    ,ProcedureName varchar(50)  null default OBJECT_NAME(@@PROCID)
    ,LogText varchar(8000)      not null
)
go
CREATE TABLE YourTestTable
(
     TestID    int not null primary key identity(1,1)
    ,TestData  varchar(100) not null
)

go
-----------------------------------------------------------------------
-----------------------------------------------------------------------
CREATE PROCEDURE ProcedureA
(
    @ParamA1     int
   ,@ParamA2     varchar(10)
   ,@ErrorMsg    varchar(1000) OUTPUT
)
AS

DECLARE @LogValue      varchar(8000)
DECLARE @ReturnValueX  int
DECLARE @ErrorMsgX     varchar(1000)

DECLARE @TempValue     int

BEGIN TRY

    SET @LogValue=ISNULL(OBJECT_NAME(@@PROCID), 'unknown')
        +': @ParamA1='+COALESCE(''''+CONVERT(varchar(10),@ParamA1)+'''','null')
        +', @ParamA2='+COALESCE(''''+@ParamA2+'''','null')


    BEGIN TRANSACTION --<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<,

    INSERT INTO YourTestTable (TestData) VALUES ('I was in top of ProdecureA')



    --your logic logic here---
    IF @ParamA1=1
    BEGIN
        RAISERROR('testing, bad parameter',16,1) --send control to the BEGIN CATCH block
    END

    SET @TempValue=@ParamA1/@ParamA1

    EXEC @ReturnValueX=ProcedureB @ParamA1,@ParamA2,@ErrorMsgX OUTPUT
    IF @ReturnValueX!=0
    BEGIN
        SET @ErrorMsg='Call to ProcedureB failed, ReturnValueX='+COALESCE(''''+CONVERT(varchar(10),@ReturnValueX)+'''','null')+', @ErrorMsgX='+COALESCE(''''+CONVERT(varchar(10),@ErrorMsgX)+'''','null')
        RAISERROR(@ErrorMsg,16,1) --send control to the BEGIN CATCH block
    END

    --your logic logic here---
    INSERT INTO YourTestTable (TestData) VALUES ('I was in bottom of ProdecureA')


END TRY
BEGIN CATCH

    IF XACT_STATE()!=0
    BEGIN
        ROLLBACK TRANSACTION
    END

    SET @ErrorMsg=@LogValue+'; '
                   +CASE WHEN ERROR_NUMBER()     IS NOT NULL THEN 'Msg '         +CONVERT(varchar(30),   ERROR_NUMBER()     ) ELSE '' END
                   +CASE WHEN ERROR_SEVERITY()   IS NOT NULL THEN ', Level '     +CONVERT(varchar(30),   ERROR_SEVERITY()   ) ELSE '' END
                   +CASE WHEN ERROR_STATE()      IS NOT NULL THEN ', State '     +CONVERT(varchar(30),   ERROR_STATE()      ) ELSE '' END
                   +CASE WHEN ERROR_PROCEDURE()  IS NOT NULL THEN ', Procedure ' +                       ERROR_PROCEDURE()    ELSE '' END
                   +CASE WHEN ERROR_LINE()       IS NOT NULL THEN ', Line '      +CONVERT(varchar(30),   ERROR_LINE()       ) ELSE '' END
                   +CASE WHEN ERROR_MESSAGE()    IS NOT NULL THEN ', '           +                       ERROR_MESSAGE()      ELSE '' END
    INSERT INTO YourLogTable (LogText) VALUES (@ErrorMsg)
    RETURN 999

END CATCH

IF XACT_STATE()!=0
BEGIN
    COMMIT
END

--PRINT ISNULL(OBJECT_NAME(@@PROCID), 'unknown')+' OK'
RETURN 0
GO

-----------------------------------------------------------------------
-----------------------------------------------------------------------
CREATE PROCEDURE ProcedureB
(
    @ParamB1     int
   ,@ParamB2     varchar(10)
   ,@ErrorMsg    varchar(1000) OUTPUT
)
AS

DECLARE @LogValue      varchar(8000)
DECLARE @ReturnValueX  int
DECLARE @ErrorMsgX     varchar(1000)

DECLARE @TempValue     int

BEGIN TRY

    SET @LogValue=ISNULL(OBJECT_NAME(@@PROCID), 'unknown')
        +': @ParamB1='+COALESCE(''''+CONVERT(varchar(10),@ParamB1)+'''','null')
        +', @ParamB2='+COALESCE(''''+@ParamB2+'''','null')

    BEGIN TRANSACTION --<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<,

    INSERT INTO YourTestTable (TestData) VALUES ('I was in top of ProdecureB')

    --your logic logic here---
    IF @ParamB1=10
    BEGIN
        RAISERROR('testing, bad parameter',16,1) --send control to the BEGIN CATCH block
    END

    SET @TempValue=@ParamB1/@ParamB1

    EXEC @ReturnValueX=ProcedureC @ParamB1,@ErrorMsgX OUTPUT
    IF @ReturnValueX!=0
    BEGIN
        SET @ErrorMsg='Call to ProcedureC failed, ReturnValueX='+COALESCE(''''+CONVERT(varchar(10),@ReturnValueX)+'''','null')+', @ErrorMsgX='+COALESCE(''''+CONVERT(varchar(10),@ErrorMsgX)+'''','null')
        RAISERROR(@ErrorMsg,16,1) --send control to the BEGIN CATCH block
    END

    --your logic logic here---
    INSERT INTO YourTestTable (TestData) VALUES ('I was in bottom of ProdecureB')


END TRY
BEGIN CATCH

    IF XACT_STATE()!=0
    BEGIN
        ROLLBACK TRANSACTION
    END

    SET @ErrorMsg=@LogValue+'; '
                   +CASE WHEN ERROR_NUMBER()     IS NOT NULL THEN 'Msg '         +CONVERT(varchar(30),   ERROR_NUMBER()     ) ELSE '' END
                   +CASE WHEN ERROR_SEVERITY()   IS NOT NULL THEN ', Level '     +CONVERT(varchar(30),   ERROR_SEVERITY()   ) ELSE '' END
                   +CASE WHEN ERROR_STATE()      IS NOT NULL THEN ', State '     +CONVERT(varchar(30),   ERROR_STATE()      ) ELSE '' END
                   +CASE WHEN ERROR_PROCEDURE()  IS NOT NULL THEN ', Procedure ' +                       ERROR_PROCEDURE()    ELSE '' END
                   +CASE WHEN ERROR_LINE()       IS NOT NULL THEN ', Line '      +CONVERT(varchar(30),   ERROR_LINE()       ) ELSE '' END
                   +CASE WHEN ERROR_MESSAGE()    IS NOT NULL THEN ', '           +                       ERROR_MESSAGE()      ELSE '' END
    INSERT INTO YourLogTable (LogText) VALUES (@ErrorMsg)

    RETURN 999

END CATCH

IF XACT_STATE()!=0
BEGIN
    COMMIT
END
--PRINT ISNULL(OBJECT_NAME(@@PROCID), 'unknown')+' OK'
RETURN 0
GO

-----------------------------------------------------------------------
-----------------------------------------------------------------------
CREATE PROCEDURE ProcedureC
(
    @ParamC1     int
   ,@ErrorMsg    varchar(1000) OUTPUT
)
AS

DECLARE @LogValue      varchar(8000)
DECLARE @ReturnValueX  int
DECLARE @ErrorMsgX     varchar(1000)

DECLARE @TempValue     int


BEGIN TRY

    BEGIN TRANSACTION --<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<,

    SET @LogValue=ISNULL(OBJECT_NAME(@@PROCID), 'unknown')
        +': @ParamC1='+COALESCE(''''+CONVERT(varchar(10),@ParamC1)+'''','null')

    --your logic logic here---
    INSERT INTO YourTestTable (TestData) VALUES ('I was in top of ProdecureC')

    IF @ParamC1=100
    BEGIN
        RAISERROR('testing, bad parameter',16,1) --send control to the BEGIN CATCH block
    END

    SET @TempValue=@ParamC1/@ParamC1


    --your logic logic here---
    INSERT INTO YourTestTable (TestData) VALUES ('I was in bottom of ProdecureC')


END TRY
BEGIN CATCH

    IF XACT_STATE()!=0
    BEGIN
        ROLLBACK TRANSACTION
    END

    SET @ErrorMsg=@LogValue+'; '
                   +CASE WHEN ERROR_NUMBER()     IS NOT NULL THEN 'Msg '         +CONVERT(varchar(30),   ERROR_NUMBER()     ) ELSE '' END
                   +CASE WHEN ERROR_SEVERITY()   IS NOT NULL THEN ', Level '     +CONVERT(varchar(30),   ERROR_SEVERITY()   ) ELSE '' END
                   +CASE WHEN ERROR_STATE()      IS NOT NULL THEN ', State '     +CONVERT(varchar(30),   ERROR_STATE()      ) ELSE '' END
                   +CASE WHEN ERROR_PROCEDURE()  IS NOT NULL THEN ', Procedure ' +                       ERROR_PROCEDURE()    ELSE '' END
                   +CASE WHEN ERROR_LINE()       IS NOT NULL THEN ', Line '      +CONVERT(varchar(30),   ERROR_LINE()       ) ELSE '' END
                   +CASE WHEN ERROR_MESSAGE()    IS NOT NULL THEN ', '           +                       ERROR_MESSAGE()      ELSE '' END
    INSERT INTO YourLogTable (LogText) VALUES (@ErrorMsg)

    RETURN 999

END CATCH

IF XACT_STATE()!=0
BEGIN
    COMMIT
END
--PRINT ISNULL(OBJECT_NAME(@@PROCID), 'unknown')+' OK'
RETURN 0
GO

this will run the above procedures for four test cases:

  • fail in A, YourTestTable has no data in it, YourLogTable shows log info for A
  • fail in B, YourTestTable has no data in it, YourLogTable shows log info for B and A
  • fail in C, YourTestTable has no data in it, YourLogTable shows log info for C, B and A
  • all work, YourTestTable has data in it, YourLogTable has no data in it

code here:

DECLARE @ReturnValue  int
DECLARE @ErrorMsg     varchar(1000)

print '###########################################################################'
print 'will error out in A - should log A>>> EXEC ProcedureA 1,''abcd'''
delete from YourTestTable; delete from YourLogTable;
EXEC @ReturnValue=ProcedureA 1,'abcd',@ErrorMsg OUTPUT; SELECT @ReturnValue AS '@ReturnValue' ,@ErrorMsg AS '@ErrorMsg'; select 'YourTestTable' AS 'YourTestTable',* from YourTestTable; select 'YourLogTable' AS 'YourLogTable',* from YourLogTable;
print '###########################################################################'
print 'will error out in B - should log B and A>>> EXEC ProcedureA 10,''abcd'''
delete from YourTestTable; delete from YourLogTable;
EXEC @ReturnValue=ProcedureA 10,'abcd',@ErrorMsg OUTPUT; SELECT @ReturnValue AS '@ReturnValue' ,@ErrorMsg AS '@ErrorMsg'; select 'YourTestTable' AS 'YourTestTable',* from YourTestTable; select 'YourLogTable' AS 'YourLogTable',* from YourLogTable;
print '###########################################################################'
print 'will error out in C - should log C, B and A>>>> EXEC ProcedureA 100,''123'''
delete from YourTestTable; delete from YourLogTable;
EXEC @ReturnValue=ProcedureA 100,'123',@ErrorMsg OUTPUT; SELECT @ReturnValue AS '@ReturnValue' ,@ErrorMsg AS '@ErrorMsg'; select 'YourTestTable' AS 'YourTestTable',* from YourTestTable; select 'YourLogTable' AS 'YourLogTable',* from YourLogTable;
print '###########################################################################'
print 'will complete, YourTestTable will contain data >>>> EXEC ProcedureA 2,''123'''
delete from YourTestTable; delete from YourLogTable;
EXEC @ReturnValue=ProcedureA 2,'123',@ErrorMsg OUTPUT; SELECT @ReturnValue AS '@ReturnValue' ,@ErrorMsg AS '@ErrorMsg'; select 'YourTestTable' AS 'YourTestTable',* from YourTestTable; select 'YourLogTable' AS 'YourLogTable',* from YourLogTable;
print '###########################################################################'

here is the output, which shows a stack in the log, despite the rollbacks:

###########################################################################
will error out in A - should log A>>> EXEC ProcedureA 1,'abcd'

(6 row(s) affected)

(0 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)
@ReturnValue @ErrorMsg
------------ ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
999          ProcedureA: @ParamA1='1', @ParamA2='abcd'; Msg 50000, Level 16, State 1, Procedure ProcedureA, Line 33, testing, bad parameter

(1 row(s) affected)

YourTestTable TestID      TestData
------------- ----------- ----------------------------------------------------------------------------------------------------

(0 row(s) affected)

YourLogTable LogID       LogDate                 ProcedureName                                      LogText
------------ ----------- ----------------------- -------------------------------------------------- --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
YourLogTable 37          2009-09-08 15:04:39.663 ProcedureA                                         ProcedureA: @ParamA1='1', @ParamA2='abcd'; Msg 50000, Level 16, State 1, Procedure ProcedureA, Line 33, testing, bad parameter

(1 row(s) affected)

###########################################################################
will error out in B - should log B and A>>> EXEC ProcedureA 10,'abcd'

(0 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)
@ReturnValue @ErrorMsg
------------ ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
999          ProcedureA: @ParamA1='10', @ParamA2='abcd'; Msg 266, Level 16, State 2, Procedure ProcedureB, Line 0, Transaction count after EXECUTE indicates that a COMMIT or ROLLBACK TRANSACTION statement is missing. Previous count = 1, current count = 0.

(1 row(s) affected)

YourTestTable TestID      TestData
------------- ----------- ----------------------------------------------------------------------------------------------------

(0 row(s) affected)

YourLogTable LogID       LogDate                 ProcedureName                                      LogText
------------ ----------- ----------------------- -------------------------------------------------- --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
YourLogTable 38          2009-09-08 15:04:39.680 ProcedureB                                         ProcedureB: @ParamB1='10', @ParamB2='abcd'; Msg 50000, Level 16, State 1, Procedure ProcedureB, Line 31, testing, bad parameter
YourLogTable 39          2009-09-08 15:04:39.680 ProcedureA                                         ProcedureA: @ParamA1='10', @ParamA2='abcd'; Msg 266, Level 16, State 2, Procedure ProcedureB, Line 0, Transaction count after EXECUTE indicates that a COMMIT or ROLLBACK TRANSACTION statement is missing. Previous count = 1, current count = 0.

(2 row(s) affected)

###########################################################################
will error out in C - should log C, B and A>>>> EXEC ProcedureA 100,'123'

(0 row(s) affected)

(2 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)

(1 row(s) affected)
@ReturnValue @ErrorMsg
------------ ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
999          ProcedureA: @ParamA1='100', @ParamA2='123'; Msg 266, Level 16, State 2, Procedure ProcedureB, Line 0, Transaction count after EXECUTE indicates that a COMMIT or ROLLBACK TRANSACTION statement is missing. Previous count = 1, current count = 0.

(1 row(s) affected)

YourTestTable TestID      TestData
------------- ----------- ----------------------------------------------------------------------------------------------------

(0 row(s) affected)

YourLogTable LogID       LogDate                 ProcedureName                                      LogText
------------ ----------- ----------------------- -------------------------------------------------- -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

Upvotes: 0

gbn
gbn

Reputation: 432200

Some options:

  • Test for @@TRANCOUNT = 0 in the logging code
  • Use SET XACT_ABORT ON: this always rolls back. This is what I'd do.

SO Questions about SET XACT_ABORT ON (with some error handling)

Upvotes: 1

Related Questions