Re-throw Errors with Logging

Question

Re-throw Errors with Logging

harsha.majety

SSCommitted

Points: 1537
More actions
March 27, 2013 at 10:15 pm

#272618

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

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

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

Dirk Naudts SSC Enthusiast Points: 125 More actions · Answer 1

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.

roman.asadovsky SSC Enthusiast Points: 140 More actions · Answer 2

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?

William Vach SSCertifiable Points: 5538 More actions · Answer 3

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.

armarshall SSC Enthusiast Points: 155 More actions · Answer 4

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....

Dirk Naudts SSC Enthusiast Points: 125 More actions · Answer 5

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 🙂

David Rueter SSCrazy Points: 2661 More actions · Answer 6

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.

steven.bingham SSC Rookie Points: 34 More actions · Answer 7

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:

NBSteve SSCarpal Tunnel Points: 4055 More actions · Answer 8

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.

steven.bingham SSC Rookie Points: 34 More actions · Answer 9

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

David Rueter SSCrazy Points: 2661 More actions · Answer 10

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.

Dirk Naudts SSC Enthusiast Points: 125 More actions · Answer 11

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.

David Rueter SSCrazy Points: 2661 More actions · Answer 12

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.

steven.bingham SSC Rookie Points: 34 More actions · Answer 13

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.

David Rueter SSCrazy Points: 2661 More actions · Answer 14

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 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

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

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