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
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
BEGIN TRANSACTION
INSERT INTO LogTable (Info) VALUES ('Text from committing transaction');
SELECT * FROM LogTable;
COMMIT;
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
BEGIN TRANSACTION
INSERT INTO LogTable (Info) VALUES ('Text from transaction which is going to be rolled back');
SELECT * FROM LogTable;
ROLLBACK;
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
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
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
BEGIN TRANSACTION
EXECUTE Logging...AddLogEntry 'Text from transaction which is going to be rolled back';
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
EXEC sp_serveroption Logging, 'RPC OUT', 'TRUE'
When run again we'll encounter a different error
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
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
using System.Data.SqlClient;
using System.Transactions;
namespace SqlServerLogging {
public static class AutonomousTransaction {
[Microsoft.SqlServer.Server.SqlProcedure()]
public static void WriteLog(string info) {
SqlConnectionStringBuilder connectionBuilder = new SqlConnectionStringBuilder();
connectionBuilder.DataSource = "ServerName\\InstanceName";
connectionBuilder.IntegratedSecurity = true;
connectionBuilder.InitialCatalog = "DatabaseName";
using (TransactionScope scope = new TransactionScope(TransactionScopeOption.RequiresNew)) {
using (SqlConnection connection = new SqlConnection(connectionBuilder.ConnectionString)) {
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();
}
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 residesInstanceName, 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 stringDatabaseName, 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
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
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
CREATE SCHEMA CSLogging;
This schema is used when the procedure is registered and used. Now everything should be ready for the assembly registration
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
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.
