Logging messages during a transaction

Ever tried to log a message to a table during a batch process which is then rolled back. You will have found that the message got rolled back as well.

How do you get round this?

Well you might think savepoints might be a solution. They aren’t, they just allow you to rollback to a specific point in your transaction. You might also think that nested transactions are the solution. Unfortunately thats not the case either. In SQL Server you only ever have one transaction, even if you use BEGIN TRANSACTION more than once.

One solution is to put your messages in a table variable. This works because table variables are not affected by transaction scope. However whilst this works it only really works when you have a single set of code/procedure doing the work, you log your messages in the table variable and then at the end after you have committed/rolled back your transaction you can store your messages.

So what is the solution.

When I was reviewing the profiler chapter of Professional SQL Server 2008 Internals and Troubleshooting with James Rowland Jones we were both looking at some of the edge case scenarios for some of the profiler functionality including the custom event mechanism. The thought then came that you might be able to use it for logging. Looking into it you can. What’s more there are some great features.

The key to this logging is the Custom Events that you can raise using the master..sp_trace_generateevent procedure.

You can capture these events in profiler but thats not very good. Whats really useful is that you can use Event Notifications to capture the events that you raise, further more with Event Notifications you can log to a remote source using the standard routing features in service broker.

You might think this all sounds very complex. Its not.

All you have to do is create 3 things, a queue, a service and an event notification.

The queue is the bucket your messages will be put in

The service is the address for you queue and says you are going to process event notification messages

And the Event notification tells SQL that you want your user event messages to go to your service.

create queue loggingQ

go

create service logging

on queue loggingQ ([http://schemas.microsoft.com/SQL/Notifications/PostEventNotification]);

go

create event notification logHandler0

on  server

for userconfigurable_0

to service 'logging', 'current database' ;

Note that userconfigurable_0 is the event and there are 9 more, so you can partition your messages.

To log a message you just call the stored proc specifying the event_class 82 corresponds to user event 0, event_class 83 for event 1 etc.

exec master..sp_trace_generateevent

   @event_class = 82, @userinfo = N'Inserted row into user_config_test'

To read messages you use the RECEIVE statement, i.e

receive  top (1000) message_body

from logDB..loggingQ

What’s nice is that the message contains lots of information that means you don’t have to pass that information in your message.

<EVENT_INSTANCE>

  <EventType>USERCONFIGURABLE_3</EventType>

  <PostTime>2010-10-17T22:08:39.677</PostTime>

  <SPID>52</SPID>

  <TextData>Inserted row into user_config_test</TextData>

  <BinaryData />

  <DatabaseID>1</DatabaseID>

  <TransactionID />

  <NTUserName>Simon</NTUserName>

  <NTDomainName>onarc-lap03</NTDomainName>

  <HostName>ONARC-LAP03</HostName>

  <ClientProcessID>5032</ClientProcessID>

  <ApplicationName>Microsoft SQL Server Management Studio - Query</ApplicationName>

  <LoginName>onarc-lap03\Simon</LoginName>

  <StartTime>2010-10-17T22:08:39.677</StartTime>

  <DatabaseName>master</DatabaseName>

  <LoginSid>AQUAAAAAAAUVAAAAvl392eyB2Zmm4Qb26AMAAA==</LoginSid>

  <RequestID>0</RequestID>

  <EventSequence>250</EventSequence>

  <IsSystem />

  <SessionLoginName>onarc-lap03\Simon</SessionLoginName>

  <GroupID>2</GroupID>

</EVENT_INSTANCE>

The complete script of what to do is here

create queue loggingQ

go

create service logging

on queue loggingQ ([http://schemas.microsoft.com/SQL/Notifications/PostEventNotification]);

go

create event notification logHandler0

on  server

for userconfigurable_0

to service 'logging', 'current database' ;

 

EXEC master..sp_trace_generateevent

   @event_class = 82, @userinfo = N'Inserted row into user_config_test'

 

create database logDB

go

alter database logDB set enable_broker

go

use logDB

go

create queue loggingQ

create service logging

on queue loggingQ ([http://schemas.microsoft.com/SQL/Notifications/PostEventNotification]);

go

create event notification logHandler0

on  server

for userconfigurable_0

to service 'logging', 'current database' ;

 

CREATE EVENT NOTIFICATION logHandler1

ON  SERVER

FOR USERCONFIGURABLE_1

TO SERVICE 'logging', 'current database' ;

go

 

CREATE EVENT NOTIFICATION logHandler2

ON  SERVER

FOR USERCONFIGURABLE_2

TO SERVICE 'logging', 'current database' ;

go

 

CREATE EVENT NOTIFICATION logHandler3

ON  SERVER

FOR USERCONFIGURABLE_3

TO SERVICE 'logging', 'current database' ;

go

begin transaction

 

EXEC master..sp_trace_generateevent

   @event_class = 82, @userinfo = N'Inserted row into user_config_test'

EXEC master..sp_trace_generateevent

   @event_class = 83, @userinfo = N'Inserted row into user_config_test'

EXEC master..sp_trace_generateevent

   @event_class = 84, @userinfo = N'Inserted row into user_config_test'

EXEC master..sp_trace_generateevent

   @event_class = 85, @userinfo = N'Inserted row into user_config_test'

 

rollback transaction

go

declare @message_body  xml;

declare @handle uniqueidentifier;

receive  @message_body = message_body

        ,@handle = conversation_handle

from logDB..loggingQ

end conversation @handle

select @message_body

Published Sunday, October 17, 2010 11:05 PM by simonsabin

Comments

Sunday, October 17, 2010 11:53 PM by SimonS Blog on SQL Server Stuff

# Logging messages during a transaction

Ever tried to log a message to a table during a batch process which is then rolled back. You will have

Friday, December 3, 2010 10:17 PM by Simons SQL Blog

# Restricting logons during certain hours for certain users

Following a an email in a DL I decided to look at implementing a logon restriction system to prevent