Click here to Skip to main content
15,867,568 members
Articles / Database Development / SQL Server

Logging from inside a transaction

Rate me:
Please Sign up or sign in to vote.
4.94/5 (30 votes)
21 Feb 2015CPOL8 min read 52.6K   263   39   13
How to log information into a table from inside a transaction, even if the transaction is rolled back.

Before going to the actual problem and solutions,
few questions

There are few things I want to point out or actually answers:

  • Why the logging is done in the database, why not on the client side?
  • Why not use table variables?
  • Do we need another database where the logging data is stored?

Let's consider each question separately

Why not client side?

A lot can happend during the execution and in many situtations the client isn't able to see what actually happens in the database. So we would need a mechanism to transfer the log data to the client and the store it the database. What if the connection is suddenly broken, what if the application runs into an unhandled exception and so on. You have a big chance of loosing logged data.

Then why not table variables?

The data stored in a table variable is not bound to a transaction so why not use a table variable and store the data from this variable after the transacation. Well, there are a few reasons why I didn't do it this way. Again, a lot can happen during the execution. What if the database call is suddenly terminated for some reason like broken connection, error, and so on. You would have to be sure that the execution is run into the point where the data from table variable is stored but actually there's no way of ensuring this. This means that the log data would be lost in erroneous situations wher, in my opinion, the gathering of the data is most crucial.

Another point is, this approach does not apply if the transaction scope is outside the database boundaries. Consider for example propagated transactions, distributed systems or even just client initiated transacions. In all of these situations you don't have an exact point outside the transaction where the data in the table variable would be persisted.

What about the log database, is it separate?

Well actually that's your choice. The examples I have made connect to the same database where the operation is executed so the are kind of loopback connections. In other words the log data remains in the same database. However, if you like, you can point the connections to another database.

Introduction, the problem

It's nice to log information to a table from stored procedures, triggers, functions and so on. This information helps to understand what has happened during the execution. But if the operation fails, typically the transaction is rolled back so everything written into the database inside this transaction will not be persisted. Let's see this in detail.

First we need a table where to store the log data

SQL
-- Table for logging information
CREATE TABLE LogTable (
   Id       INT      Identity (1,1)    NOT NULL,
   Recorded DATETIME DEFAULT GETDATE() NOT NULL,
   Info     VARCHAR(4000)
);
ALTER TABLE LogTable ADD PRIMARY KEY (Id);

Now in a successful transaction everything written into the log table safe after the transaction commits. Like this

SQL
-- Commit situation
BEGIN TRANSACTION
  -- Make some modifications etc. in the database

  -- Insert log data
  INSERT INTO LogTable (Info) VALUES ('Text from committing transaction');

  -- Select the log data
  SELECT * FROM LogTable;
COMMIT;

-- Select the log data
SELECT * FROM LogTable;

After executing the block above you should see results like this

Resultset 1, from inside the transaction
----------------------------------------

Id   Recorded                  Info
--   -----------------------   ------------------
15   2015-01-17 21:22:47.730   Text from committing transaction



Resultset 2, after the transaction has ended
--------------------------------------------

Id   Recorded                  Info
--   -----------------------   -----------------
15   2015-01-17 21:22:47.730   Text from committing transaction

So far so good but what if the transaction is rolled back, let's test

SQL
-- Rolling back
BEGIN TRANSACTION
  -- Make some modifications

  -- Insert log data
  INSERT INTO LogTable (Info) VALUES ('Text from transaction which is going to be rolled back');

  -- Select the log data
  SELECT * FROM LogTable;
ROLLBACK;

-- Select the log data
SELECT * FROM LogTable;

Now the results from the two SELECT statements look like this

Resultset 1, from inside the transaction
----------------------------------------

Id    Recorded                 Info
--   -----------------------   ------------------
15   2015-01-17 21:22:47.730   Text from committing transaction
16   2015-01-17 21:29:48.930   Text from transaction which is going to be rolled back



Resultset 2, after the transaction has ended
--------------------------------------------

Id   Recorded                  Info
--   -----------------------   -----------------
15   2015-01-17 21:22:47.730   Text from committing transaction

As expected after the transaction has rolled back no evidence of the second row remains.

It's also important to notice that the data from within the transaction was visible only to the session which started the transaction. Other sessions can't see the data until it's committed.

So the problem is how to ensure that the log data remains in the log table even after a rollback. For example Oracle has a mechanism called autonomous transaction. This means that completely independent DML operations can be executed and commited within another transaction. Unfortunately SQL Server doesn't have this capability so we need to make a workaround,

Using linked server

One option is to use a linked server. Linked server is a named connection to another database, the same one or different database. Typically operations performed against a linked server are using a distributed transaction but a linked server can also be configured not to participate in the originating transaction. This feature is what we're going to use. This implementation is much like Peter Scharlock's in How to create an autonomous transaction in SQL Server 2008 but in a bit more detail.

First we create the linked server

SQL
-- Create linked server 
DECLARE @database VARCHAR(200) = DB_NAME();
EXECUTE sp_addlinkedserver @server = 'Logging',  
                           @srvproduct = ' ',
                           @provider = 'SQLNCLI', 
                           @datasrc = @@SERVERNAME, 
                           @catalog = @database

Server is the name we are calling the linked server. Server product is SQL Server so an empty string is sufficient. We use native client as the data provider. Data source is the current server and the default catalog (database) is our current database. This means that we create a linked server that points back to the exact same database.

The next step is to create a procedure for writing to log table. The procedure is simple

SQL
CREATE PROCEDURE AddLogEntry(@info VARCHAR(4000)) AS
BEGIN
   INSERT INTO LogTable (Info) VALUES (@info);
END;

All in place so let's try. I'll use the following batch in the rest of the examples to test the insertion to the log table

SQL
-- Rolling back
BEGIN TRANSACTION
  -- Make some modifications etc. in the database

  -- Insert log data
  EXECUTE Logging...AddLogEntry 'Text from transaction which is going to be rolled back';

  -- Select the log data
  SELECT * FROM LogTable;
ROLLBACK;

Note the syntax when calling the stored procedure. Instead of the standard three part notation there's now a fourth part in the beginning, the name of the linked server. I have omitted the database name and the owner since the linked server is configured to connect to correct database by default. Also the owner of the procedure is dbo so no need to specify that.

Now when the block above is executed an error is generated

Msg 7411, Level 16, State 1, Line 71
Server 'Logging' is not configured for RPC.

Okay, remote procedure calls are not enabled by default. Let's change that

SQL
-- Enable RPC calls
EXEC sp_serveroption Logging, 'RPC OUT', 'TRUE'

When run again we'll encounter a different error

SQL
Msg 8501, Level 16, State 3, Line 71
MSDTC on server 'MyServerName' is unavailable.

This error happens because the insertion through the linked server is trying to utilize a distributed transaction. MSDTC (Microsoft Distributed Transaction Coordinator) is the service responsible for coordinating commit and rollback operations between multiple databases. If the service would have been present, the operation would have been executed but it would have been tied to the original transaction.

To ensure that a separate transaction is used we need to reconfigure the linked server

SQL
-- disable distributed transaction
EXEC sp_serveroption Logging, 'remote proc transaction promotion', 'FALSE'

This prevents the target server from participating in the originating transaction. Now when the same test block is run the result is

Resultset 1, from inside the transaction
----------------------------------------

Id    Recorded                 Info
--   -----------------------   ------------------
15   2015-01-17 21:22:47.730   Text from committing transaction
19   2015-01-17 23:59:43.070   Text from transaction which is going to be rolled back



Resultset 2, after the transaction has ended
--------------------------------------------

Id    Recorded                 Info
--   -----------------------   -----------------
15   2015-01-17 21:22:47.730   Text from committing transaction
19   2015-01-17 23:59:43.070   Text from transaction which is going to be rolled back

As you see, even though the original transaction was rolled back the log table contains the data inserted using the AddLogEntry procedure.

Using a CLR assembly

A completely different approach is to use a CLR assembly to do the job. The idea is that a CLR procedure will connect to the database using a different transaction scope. This transaction is independent from the transaction the call originated from so the modifications made in this procedure will remain even if the original transaction is rolled back.

This is what the CLR procedure looks like

C#
using System.Data.SqlClient;
using System.Transactions;

namespace SqlServerLogging {
   /// <summary>
   /// Class to handle logging inside an autonomous transaction
   /// </summary>
   public static class AutonomousTransaction {
      /// <summary>
      /// Writes a log entry within an autonomous transaction to the LogTable
      /// </summary>
      /// <param name="info">Text to write to log</param>
      [Microsoft.SqlServer.Server.SqlProcedure()]
      public static void WriteLog(string info) {
         SqlConnectionStringBuilder connectionBuilder = new SqlConnectionStringBuilder();

         // Define properties for the connection string
         // TODO: Change the server and instance names
         connectionBuilder.DataSource = "ServerName\\InstanceName";
         connectionBuilder.IntegratedSecurity = true;
         // TODO: Change the database name
         connectionBuilder.InitialCatalog = "DatabaseName";
         
         // Define a new transaction scope
         using (TransactionScope scope = new TransactionScope(TransactionScopeOption.RequiresNew)) {
            // prepare the connection
            using (SqlConnection connection = new SqlConnection(connectionBuilder.ConnectionString)) {
               // Define and execute the command 
               using (SqlCommand command = new SqlCommand()) {
                  command.CommandText = "INSERT INTO LogTable (Info) VALUES (@info)";
                  command.Parameters.AddWithValue("@info", info);
                  command.Connection = connection;
                  connection.Open();
                  command.ExecuteNonQuery();
               }
               connection.Close();
            }
            // Commit the changes
            scope.Complete();
         }
      }
   }
}

First of all, there are few parameters that need to be tweaked before using this:

  • ServerName, use the name of the server where the SQL Server resides
  • InstanceName, if you use named instances replace this with the name of the instance. If the database is located in the default instance, remove this from connection string
  • DatabaseName, replace with the name of the database where the log table is located

As described earlier this takes a new connection inside a separate transaction, commits changes and returns. From the database registration point of view the method is decorated with SqlProcedure attribute so that this method can be registered in the database.

To register this procedure to the database we need to take few steps. First of all we need to define the database trustworthy, like this

SQL
-- Make the database trustworthy
ALTER DATABASE DatabaseName SET TRUSTWORTHY ON;

This needs to be done so that we can define external access for the CLR assembly when we register it. Otherwise the execution of the CLR procedure would cause a security exception.

The next thing is to enable CLR components

SQL
-- Enable CLR components
sp_configure 'clr enabled', 1;
RECONFIGURE;

The next step isn't mandatory but I like to separate things into different schemas so I decided to create a schema for logging operations, like this

SQL
-- Create a new schema for the logging
CREATE SCHEMA CSLogging;

This schema is used when the procedure is registered and used. Now everything should be ready for the assembly registration

SQL
CREATE ASSEMBLY SqlServerLogging
   AUTHORIZATION dbo
   FROM 'C:\???\???\SqlServerLogging.dll'
   WITH PERMISSION_SET = EXTERNAL_ACCESS;

To successfully run the statement above you need to change the path so that it points to the location where you have compiled the assembly.

The last step is to create a procedure to SQL Server which actually uses the procedure inside the assembly. To do this, run the following statement

SQL
CREATE PROCEDURE CSLogging.WriteLog (@info nvarchar(4000))
   AS EXTERNAL NAME SqlServerLogging.[SqlServerLogging.AutonomousTransaction].WriteLog;

That's it. Now the environment to log data using a CLR procedure should be complete. Let's have a test and run the following block

-- Rolling back
BEGIN TRANSACTION
  -- Make some modifications

  -- Insert log data
  EXECUTE CSLogging.WriteLog 'Text from transaction which is going to be rolled back';

  -- Select the log data
  SELECT * FROM LogTable;
ROLLBACK;
-- Select the log data
SELECT * FROM LogTable;

The result of the block is something like the following

Resultset 1, from inside the transaction
----------------------------------------

Id   Recorded                  Info
--   -----------------------   ------------------
26   2015-01-18 21:43:04.070   Text from transaction which is going to be rolled back


Resultset 2, after the transaction has ended
--------------------------------------------

Id   Recorded                  Info
--   -----------------------   -----------------
26   2015-01-18 21:43:04.070   Text from transaction which is going to be rolled back

Don't mind about the missing rows from previous samples. I deleted them from the database in order to keep the sample data small.

Anyhow, this worked as a charm. So now we can also use a CLR procedure to log any interesting data.

Conclusion

By using either of these mechanisms you can ensure that the information logged during a transaction is persisted even when the transaction is rolled back. This is an enormous benefit from problem solving point of view. By utilizing proper logging inside the database it's much easier to understand what has happenned, even when things go wrong.

References

The following references may be useful to you:

History

  • 19th January 2014: Created.

License

This article, along with any associated source code and files, is licensed under The Code Project Open License (CPOL)


Written By
Architect
Europe Europe
Biography provided

Comments and Discussions

 
QuestionCan you write a article to show how we can pass friendly message to frond end Pin
Mou_kol11-Oct-17 23:13
Mou_kol11-Oct-17 23:13 
GeneralMy vote of 5 Pin
Paw Jershauge9-Nov-16 23:15
Paw Jershauge9-Nov-16 23:15 
GeneralRe: My vote of 5 Pin
Wendelius23-Nov-16 7:01
mentorWendelius23-Nov-16 7:01 
GeneralMy vote of 5 Pin
D V L12-Sep-15 1:32
professionalD V L12-Sep-15 1:32 
GeneralRe: My vote of 5 Pin
Wendelius19-Sep-15 21:54
mentorWendelius19-Sep-15 21:54 
GeneralMy vote of 5 Pin
Alex Galisteo4-Mar-15 2:35
Alex Galisteo4-Mar-15 2:35 
GeneralRe: My vote of 5 Pin
Wendelius4-Mar-15 8:37
mentorWendelius4-Mar-15 8:37 
SuggestionUse a table variable Pin
John B Oliver16-Feb-15 10:28
John B Oliver16-Feb-15 10:28 
GeneralRe: Use a table variable Pin
Wendelius16-Feb-15 17:39
mentorWendelius16-Feb-15 17:39 
Thanks for your comments. Table variables are one way to store the logging information outside the transaction. But as I wrote here[^] the main idea was to have the data in place and safe as soon as the log info is written.

With table variables we need to wait until the transaction has been finished until we can write to the table. Also if the transaction is initiated on the calling side the database operations are always inside the transaction.
QuestionAlternative solution (keeps the logging table in same DB) Pin
djmarcus20-Jan-15 10:56
djmarcus20-Jan-15 10:56 
AnswerRe: Alternative solution (keeps the logging table in same DB) Pin
Wendelius20-Jan-15 17:39
mentorWendelius20-Jan-15 17:39 
QuestionToo complex? Pin
daveynogoodboyo20-Jan-15 9:36
daveynogoodboyo20-Jan-15 9:36 
AnswerRe: Too complex? Pin
Wendelius20-Jan-15 17:44
mentorWendelius20-Jan-15 17:44 

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Praise Praise    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.