Re-throw Errors with Logging

  • Comments posted to this topic are about the item Re-throw Errors with Logging

  • Hi, thank you for this article. What would be the best technique to have exception logging beyond a begin tran...rollback scenario, the problem being that any error logged to a table is also rolled back when you rollback a transaction, so again no trace of the exception...

    thanks

    Dirk.

  • Exactly my thoughts, Dirk. This solution doesn't work with rolled back transactions. The only way we have found is to use cmdshell to log errors in local txt file on the server.

    Additionally you can have some job which would upload that file back to the database, but we didn't go that far.

    You can get fancy and save errors not just as plain txt, but as csv or even xml form, depending on your needs.

    Does anybody have better idea?

  • If you are using transactions, you can put the rollback statement at the beginning of the catch as follows:

    BEGIN CATCH;

    ROLLBACK;

    SET @Result = 0;

    -- re-raise the error to be caught in the calling process

    EXECUTE @Result = dbo.pReThrowErrorwithlogging @ProcedureName = @SPName, @logError = 1, @Debug = 1;

    END CATCH;

    That will allow the procedure to log the error.

  • A couple of suggestions.

    Incorporate Granularity: Log4Net and nLog and others have the concept of logging levels viz Trace / Debug / Info / Warn / Severe / Fatal.

    Any exception should have a granularity IMHO and be handled accordingly.

    This leads to:

    Standardize Exception Objects: Every exception ought to be in a registry of some sort with an ID, Severity, Message, etc. and possibly redress actions. THose are independent of the application(s) themselves, so they can be reused across a suite of apps.

    Finally:

    as far as I can see, this does not capture anything about the server instance(in cluster). thread or session that generated the problem which may be critical. A function should be incorporated that does that and records it along with the exception. This might be done by some sort of 'Job ID' but those may not be unique....

  • Hi William, In a single stored procedure this will indeed allow you to have a trace of the exception, in real world you often have nested stored procedures, triggers called within the transaction-scope, and all log-records to assist you in trying to analyse the problem/flow are gone too once you've rolled back (but I realize i'm now mixing logging in general and Exception logging).

    But your solution is already much better than having no logging at all, and imho also much better that having to fall back to external logfiles. It would be nice to have a statement/keyword to enable you to do DML beyond the scope of the current transaction, however dangerous that may sound 🙂

  • You can log the error to the SQL Server system log by specifying "WITH LOG" on your call to RAISERROR. These log entries survive the transaction rollback:

    BEGIN TRAN

    BEGIN TRY

    RAISERROR('Sample Error for Testing', 16, 1) WITH LOG

    COMMIT TRAN

    END TRY

    BEGIN CATCH

    PRINT 'Error message was logged to the SQL Server log even though the transaction has been rolled back.'

    ROLLBACK TRAN

    END CATCH

    (See the log in SSMS under Management / SQL Server Logs / Current)

    This doesn't help you log to a normal table...but it may be cleaner than writing to a flat file from xp_cmdshell.

  • Team,

    I have an answer for retaining logging errors during a rollback situation.

    I have an associated reply to another post that you can read at this link

    http://social.msdn.microsoft.com/Forums/en-US/vstsdb/thread/2ab351c2-00cc-4500-841b-35c3271e040b/.

    I use a similiar approach of implementing TRY/CATCH statements in my stored

    procedures and submitting the errors to a database table via an error logging

    stored procedure. However, I use a CLR stored procedure to handle the logging

    to deal with the transaction issue. Here are the details...

    Often times you can run stored procedures from many processes, like other stored

    procedures, where there are different levels of transactions. The problem is that if you

    write to your log table and a rollback occurs, you lose that error record. Even if you write

    the log record after a rollback statement, you could lose your record if that stored proc.

    itself is running with in inner transaction context and the out transaction rolled back.

    This is simply handled by creating a CLR Stored Procedure, because with a CLR Stored

    Proc. you can create a seperate transaction context, within which to write the record to

    the logging table, and that context is not affected any transaction contexts of the T-SQL

    stored procs that were running, not matter how deep your levels of transactions.

    From within the CLR stored proc. I get the pertainent information about the database

    and server and dynamically construct my connection string, which points back to the

    database the stored proc. is on. I then create a seperate connection, in a seperate

    transaction context, and write a record to the logging table. You should be able to

    infer the schema of the table from the code.

    In the CATCH section that calls this CLR stored proc., I write an error to the system

    event log if an exception is throw by this stored procedure. The stored proc. is generic

    enough that I could use it, as is, on any database as long as it has a consistently structure

    error logging table.

    CODE SAMPLE BELOW

    using System;

    using System.Data;

    using System.Data.SqlClient;

    using System.Data.SqlTypes;

    using System.Security;

    using System.Security.Principal;

    using System.Transactions;

    using Microsoft.SqlServer.Server;

    public partial class LogDatabaseError

    {

    [Microsoft.SqlServer.Server.SqlProcedure]

    public static void usp_clrLogDatabaseError(SqlDateTime ErrorEventDateTime

    ,SqlInt32 ErrorNumber

    ,SqlInt32 ErrorSeverity

    ,SqlInt32 ErrorState

    ,SqlString ErrorProcedure

    ,SqlInt32 ErrorLine

    ,SqlString ErrorMessage)

    {

    try

    {

    const string DATASOURCE = "Data Source=";

    const string INITIALCATALOG = ";Initial Catalog=";

    const string INTEGRATEDSECURITY = ";Integrated Security=True;Enlist=false;";

    string dynamicConnString;

    string SQL_InstanceName;

    string SQL_DatabaseName;

    //Establish a connection in the current context to dynamically get the current

    //Server and Database Name.

    using (SqlConnection sysconn = new SqlConnection("context connection=true"))

    {

    SqlCommand GetSQLSystemProperties = new SqlCommand();

    GetSQLSystemProperties.Connection = sysconn;

    sysconn.Open();

    //Get the current SQL Server instance name

    GetSQLSystemProperties.CommandText = "SELECT @@Servername";

    SQL_InstanceName = (string)GetSQLSystemProperties.ExecuteScalar();

    //Get the current Database Name

    GetSQLSystemProperties.CommandText = "SELECT DB_NAME()";

    SQL_DatabaseName = (string)GetSQLSystemProperties.ExecuteScalar();

    sysconn.Close();

    }

    //Dynamically construct the connection string to establish a connection outside

    //of the current context, so that any error written to the error table won't be

    //rolled back.

    dynamicConnString = DATASOURCE + SQL_InstanceName + INITIALCATALOG + SQL_DatabaseName + INTEGRATEDSECURITY;

    using (SqlConnection conn = new SqlConnection(dynamicConnString))

    {

    SqlCommand InsertDatabaseErrorRecord = new SqlCommand();

    SqlParameter ErrorEventDateTimeParam = new SqlParameter("@errorEventDateTime", SqlDbType.DateTime);

    SqlParameter ErrorNumberParam = new SqlParameter("@errorNumber", SqlDbType.Int);

    SqlParameter ErrorSeverityParam = new SqlParameter("@errorSeverity", SqlDbType.Int);

    SqlParameter ErrorStateParam = new SqlParameter("@errorState", SqlDbType.Int);

    SqlParameter ErrorProcedureParam = new SqlParameter("@errorProcedure", SqlDbType.NVarChar, 200);

    SqlParameter ErrorLineParam = new SqlParameter("@errorLine", SqlDbType.Int);

    SqlParameter ErrorMessageParam = new SqlParameter("@errorMessage", SqlDbType.NVarChar, 4000);

    ErrorEventDateTimeParam.Value = ErrorEventDateTime;

    ErrorNumberParam.Value = ErrorNumber;

    ErrorSeverityParam.Value = ErrorSeverity;

    ErrorStateParam.Value = ErrorState;

    ErrorProcedureParam.Value = ErrorProcedure;

    ErrorLineParam.Value = ErrorLine;

    ErrorMessageParam.Value = ErrorMessage;

    InsertDatabaseErrorRecord.Parameters.Add(ErrorEventDateTimeParam);

    InsertDatabaseErrorRecord.Parameters.Add(ErrorNumberParam);

    InsertDatabaseErrorRecord.Parameters.Add(ErrorSeverityParam);

    InsertDatabaseErrorRecord.Parameters.Add(ErrorStateParam);

    InsertDatabaseErrorRecord.Parameters.Add(ErrorProcedureParam);

    InsertDatabaseErrorRecord.Parameters.Add(ErrorLineParam);

    InsertDatabaseErrorRecord.Parameters.Add(ErrorMessageParam);

    InsertDatabaseErrorRecord.CommandText =

    " INSERT INTO CLIENT.ErrorLog " +

    " (ErrorEventDateTime " +

    " ,ErrorNumber " +

    " ,ErrorSeverity " +

    " ,ErrorState " +

    " ,ErrorProcedure " +

    " ,ErrorLine " +

    " ,ErrorMessage) " +

    " VALUES " +

    " (@errorEventDateTime " +

    " ,@errorNumber " +

    " ,@errorSeverity " +

    " ,@errorState " +

    " ,@errorProcedure " +

    " ,@errorLine " +

    " ,@errorMessage) ";

    InsertDatabaseErrorRecord.Connection = conn;

    conn.Open();

    InsertDatabaseErrorRecord.ExecuteNonQuery();

    conn.Close();

    }

    }

    catch (Exception LogException)

    {

    throw new Exception("The usp_LogDatabaseError error logging routine experienced a problem while attempting to write an error the logging table.", LogException);

    }

    }

    };

    I hope this is helpful and happy logging!! :smooooth:

  • steven.bingham (3/28/2013)


    Team,

    ...

    Often times you can run stored procedures from many processes, like other stored

    procedures, where there are different levels of transactions. The problem is that if you

    write to your log table and a rollback occurs, you lose that error record. Even if you write

    the log record after a rollback statement, you could lose your record if that stored proc.

    itself is running with in inner transaction context and the out transaction rolled back.

    ...

    This is a common misconception with TSQL. A COMMIT statement commits the innermost transaction, but a ROLLBACK statement rolls back to the outermost transaction. So if you do a rollback, you're no longer inside any nested transactions. (You can explicitly rollback to a savepoint, but when using ROLLBACK by itself or even ROLLBACK @transaction_name, you're always rolling back ALL active transactions.)

    Another technique I've seen used is taking advantage of table variables to store errors and relevant details inside of transactions. If you insert data into a table variable and then rollback the transaction, the table variable isn't affected and will still contain the same data as before the rollback. This can be useful for inline debugging, but for logging you still need to make sure the transaction has committed or rolled back before logging from the table var back to a table.

  • NBSteve,

    I'm not exactly sure what you were referring too was a misconception, but my intent

    wasn't to explain all the nuances of transaction commits and rollbacks.

    I'm familiar with people trying to use savepoints and the like and using variables is

    one approach and I've heard of several other approachs people have suggested to

    handle the error logging issue where transactions are concerned.

    However, my experience has been that using the CLR stored proc. approach is simple, extensible and really, for me at least, has made the transaction issue a non issue.

    Transactions can be invoked outside the stored procedure, such as with a C# application or an SSIS package. This is what I meant when I said 'you can run stored procs from many different processes'. Still, the CLR approach has made the transaction issue for logging irrelavent.

    Steve

  • The fundamental problem with writing an error to a log within a transaction that is subsequently rolled back is that everything written by the connection within the transaction is rolled back--including the error message.

    So the only solution is to either wait until after the end of the transaction (i.e. perform the ROLLBACK and then log the error), or to use a different connection that is not part of the transaction.

    One way to use a different transaction is to use CLR (as steven.bingham posted).

    Another is to use ADO, called from within a T-SQL procedure.

    Here is an example of this approach being used:

    BEGIN TRAN

    BEGIN TRY

    RAISERROR('Sample Error for Testing', 16, 1)

    COMMIT TRAN

    END TRY

    BEGIN CATCH

    DECLARE @ThisMsg varchar(MAX)

    SET @ThisMsg = 'We had an error: ' + ERROR_MESSAGE()

    EXEC dbo.spLogErrorCommitted @Msg = @ThisMsg

    ROLLBACK TRAN

    END CATCH

    SELECT * FROM dbo.tblErrorLog

    The message will remain in dbo.tblErrorLog even though the transaction was rolled back.

    I'm happy to provide the declaration of dbo.spLogErrorCommitted if anyone is interested. But the basic idea is that it uses ADO (via sp_OACreate) to establish a new database connection and to perform the insert into the log table.

    In this way the inserted error log row is not removed when the transaction is rolled back.

  • David, I'm certainly intrested to see the declaration of that SP.

    Has anyone measured the performance cost of either of these techniques (Steve's CLR using a seperate transaction context and David's approach to use ADO) ?

    This probably won't be that critical if they are restricted to pure exception handling, but it's another situation if this would be used for more general logging purposes.

  • I haven't measured performance for this specific routine, but I have compared performance between CLR and COM calls in the past (i.e. for retrieving HTML from a remote server).

    CLR is faster--and is the preferred approach suggested by Microsoft and most developers.

    COM is simpler to deploy, and performs adequately for many things. With COM you can use pure T-SQL code, and don't need to register any assemblies on the server.

    To illustrate the performance difference: a certain procedure using COM can execute 200 times in 22 seconds. The same procedure written using CLR can execute 200 times in 13 seconds.

    So CLR is definitely faster and "better"...once it is written and deployed. Using COM is simpler to write and deploy if you prefer working in T-SQL and are not in the business of writing C# code and deploying .NET assemblies and CLR stored procedures.

  • As the saying goes "There's more than one way to skin a cat".

    I too would like to see the declaration of dbo.spLogErrorCommitted. The nice thing about

    the ADO approach is it's relative simplicity. Although, there are the execute permission considerations in leveraging the sp_OACreate, which if memory serves me correctly is an extended stored proc.

    There are also some configuration considerations with the CLR stored proc. approach. Some functionality in this CLR stored proc. requires it to have an assembly permission option of 'EXTERNAL_ACCESS'. With this permission option you will also either have to sign your assembly with a key OR set the database 'Trustworthy' setting to true. Either way you'll want

    your DBA's blessing. 🙂

    The best approach is the one that works best for you! 🙂

    As for the performance issue, CLR objects often aren't that bad for performance. In this case given the nature of exceptions you likely won't be running this often or frequent enough for performance to be an issue.

  • Here is a script that demonstrates an ADO-based approach for logging within a transaction that may later be rolled back.

    This script creates dbo.spLogErrorCommitted and other needed objects, and prints out some instructions.

    /*

    Script to create an error logging procedure that can record errors

    that will retain the error messages even when they were written within

    a transaction that is subsequently rolled back.

    Written by David Rueter (drueter@assyst.com) 3/28/2013

    Not copyrighted / Public domain / Use at your own risk.

    */

    SET ANSI_NULLS ON

    GO

    SET QUOTED_IDENTIFIER ON

    GO

    /*

    To remove objects created by this script:

    DROP PROCEDURE dbo.spLogErrorCommitted

    DROP PROCEDURE dbo.spLogError

    DROP TABLE dbo.tblErrorLog

    DROP USER errorWriter

    DROP LOGIN errorWriter

    */

    /*

    Create a table to hold error log messages.

    */

    CREATE TABLE tblErrorLog (

    ErrorLogID int IDENTITY PRIMARY KEY,

    DateLogged datetime DEFAULT (GETDATE()),

    Msg varchar(MAX)

    )

    GO

    /*

    Create a procedure to insert errror messages into the log table

    */

    CREATE PROCEDURE dbo.spLogError

    @Msg varchar(MAX)

    AS

    BEGIN

    SET NOCOUNT ON

    INSERT INTO tblErrorLog (Msg) VALUES (@Msg)

    END

    GO

    /*

    Create a new SQL login for ADO to use to call back into the database. This user will ONLY have rights to execute the dbo.spLogError procedure.'

    */

    DECLARE @SQL varchar(MAX)

    SET @SQL = 'CREATE LOGIN errorWriter WITH PASSWORD=N''errorWriterPW'', DEFAULT_DATABASE=[' + DB_NAME() + '], DEFAULT_LANGUAGE=[us_english], CHECK_EXPIRATION=OFF, CHECK_POLICY=OFF'

    EXEC(@SQL)

    /*

    Create a new SQL user in the current database linked to the new login created above.

    */

    CREATE USER [errorWriter] FOR LOGIN [errorWriter] WITH DEFAULT_SCHEMA=[dbo]

    GO

    /*

    Grant rights to the new errorWriter user to execute the dbo.spLogError procedure

    */

    GRANT EXEC ON dbo.spLogError TO errorWriter

    GO

    /*

    Create the procedure that will be called to log and commit an error message even inside

    a transaction that will be rolled back.

    */

    CREATE PROCEDURE dbo.spLogErrorCommitted

    @Msg varchar(MAX),

    @SuppressInternalErrors bit = 0

    AS

    BEGIN

    /*

    This procedure is designed to allow a caller to provide a message that will be written to an error log table,

    and allow the caller to call it within a transaction. The provided message will be persisted to the

    error log table even if the transaction is rolled back.

    To accomplish this, this procedure utilizes ADO to establish a second database connection (outside

    the transaction context) back into the database to call the dbo.spLogError procedure.

    */

    SET NOCOUNT ON

    DECLARE @ConnStr varchar(MAX)

    --connection string for ADO to use to access the database

    SET @ConnStr = 'Provider=SQLNCLI10; DataTypeCompatibility=80; Server=localhost; Database=' + DB_NAME() + '; Uid=errorWriter; Pwd=errorWriterPW;'

    DECLARE @SQLCommand varchar(MAX)

    SET @SQLCommand = 'EXEC dbo.spLogError @Msg=''' + REPLACE(@Msg, CHAR(39), CHAR(39) + CHAR(39)) + ''''

    DECLARE @ObjCn int

    --ADO Connection object

    DECLARE @ObjRS int

    --ADO Recordset object returned

    DECLARE @RecordCount int

    --Maximum records to be returned

    SET @RecordCount = 0

    DECLARE @ExecOptions int

    --Execute options: 0x80 means to return no records (adExecuteNoRecords) + 0x01 means CommandText is to be evaluted as text

    SET @ExecOptions = 0x81

    DECLARE @LastResultCode int = NULL

    --Last result code returned by an sp_OAxxx procedure. Will be 0 unless an error code was encountered.

    DECLARE @ErrSource varchar(512)

    --Returned if a COM error is encounterd

    DECLARE @ErrMsg varchar(512)

    --Returned if a COM error is encountered

    DECLARE @ErrorMessage varchar(MAX) = NULL

    --our formatted error message

    SET @ErrorMessage = NULL

    SET @LastResultCode = 0

    BEGIN TRY

    EXEC @LastResultCode = sp_OACreate 'ADODB.Connection', @ObjCn OUT

    IF @LastResultCode <> 0 BEGIN

    EXEC sp_OAGetErrorInfo @ObjCn, @ErrSource OUTPUT, @ErrMsg OUTPUT

    END

    END TRY

    BEGIN CATCH

    SET @ErrorMessage = ERROR_MESSAGE()

    END CATCH

    BEGIN TRY

    IF @LastResultCode = 0 BEGIN

    EXEC @LastResultCode = sp_OAMethod @ObjCn, 'Open', NULL, @ConnStr

    IF @LastResultCode <> 0 BEGIN

    EXEC sp_OAGetErrorInfo @ObjCn, @ErrSource OUTPUT, @ErrMsg OUTPUT

    END

    END

    END TRY

    BEGIN CATCH

    SET @ErrorMessage = ERROR_MESSAGE()

    END CATCH

    IF @LastResultCode = 0 BEGIN

    EXEC @LastResultCode = sp_OAMethod @ObjCn, 'Execute', @ObjRS OUTPUT, @SQLCommand, @RecordCount, @ExecOptions

    IF @LastResultCode <> 0 BEGIN

    EXEC sp_OAGetErrorInfo @ObjCn, @ErrSource OUTPUT, @ErrMsg OUTPUT

    END

    END

    IF @ObjRS IS NOT NULL BEGIN

    BEGIN TRY

    EXEC sp_OADestroy @ObjCn

    END TRY

    BEGIN CATCH

    --not much we can do...

    SET @LastResultCode = 0

    END CATCH

    END

    IF @ObjCn= 1 BEGIN

    BEGIN TRY

    EXEC sp_OADestroy @ObjCn

    END TRY

    BEGIN CATCH

    --not much we can do...

    SET @LastResultCode = 0

    END CATCH

    END

    IF (@SuppressInternalErrors = 1) AND ((@LastResultCode <> 0) OR (@ErrorMessage IS NOT NULL)) BEGIN

    SET @ErrorMessage = 'Error in spLogErrorCommitted' + ISNULL(': ' + @ErrMsg, '')

    RAISERROR(@ErrorMessage, 16, 1)

    --We are in an error-logging routine. If the we encounter an error here, there's not a lot we can do.

    --Don't raise an error or try to log this internal error.

    END

    END

    GO

    DECLARE @CRLF varchar(5)

    SET @CRLF = CHAR(13) + CHAR(10)

    DECLARE @Instructions varchar(MAX)

    SET @Instructions =

    'You can now call dbo.spLogErrorCommitted to write error messages to dbo.tblErrorLog.' + @CRLF +

    'Messages written via this procedure will be retained even if written within a transaction' + @CRLF +

    'that is rolled back.' + @CRLF +

    @CRLF +

    'To demonstrate that this works, try executing the following:' + @CRLF +

    '

    BEGIN TRAN

    BEGIN TRY

    RAISERROR(''Sample Error for Testing'', 16, 1)

    COMMIT TRAN

    END TRY

    BEGIN CATCH

    DECLARE @ThisMsg varchar(MAX)

    SET @ThisMsg = ''We had an error: '' + ERROR_MESSAGE()

    EXEC dbo.spLogErrorCommitted @Msg = @ThisMsg

    ROLLBACK TRAN

    END CATCH

    SELECT * FROM dbo.tblErrorLog' + @CRLF +

    @CRLF +

    'Note that the row still exists in dbo.tblErrorLog, even though ROLLBACK TRAN was called' + @CRLF +

    'after the message was inserted into a row in the table.' + @CRLF +

    @CRLF +

    'Remember that this stored procedure uses OLE. To work properly you may need to configure ' +

    'your database to allow OLE, as follows: ' + @CRLF +

    ' EXEC sp_configure ''show advanced options'', 1;' + @CRLF +

    ' RECONFIGURE;' + @CRLF +

    ' EXEC sp_configure ''Ole Automation Procedures'', 1;' + @CRLF +

    ' RECONFIGURE;' + @CRLF +

    'Also, your SQL user must have execute rights to the following stored procedures in master:' + @CRLF +

    ' sp_OACreate' + @CRLF +

    ' sp_OAGetProperty' + @CRLF +

    ' sp_OASetProperty' + @CRLF +

    ' sp_OAMethod' + @CRLF +

    ' sp_OAGetErrorInfo' + @CRLF +

    ' sp_OADestroy' + @CRLF +

    'You can grant rights for each of these as follows:' + @CRLF +

    ' USE master' + @CRLF +

    ' GRANT EXEC ON sp_OACreate TO myuser' + @CRLF +

    ' GRANT EXEC etc. ...' + @CRLF

    PRINT @Instructions

Viewing 15 posts - 1 through 15 (of 15 total)

You must be logged in to reply to this topic. Login to reply