Logging with SQL Server

By Ed Swiedler, 2010/01/06

Total article views: 1765 | Views in the last 30 days: 1765

 Rate this |   Join the discussion |  Briefcase |   Print

Applications running in production frequently, at least more so than we are prone to admit, have problems. Diagnosing these problems can be a nightmare when we do not have access to information regarding the error. I have seen several solutions, but none that would allow me to log all activity in a central location. The one that comes most quickly to mind, is to use a table in a database to contain all of the messages.

The problem for me was that the table would grow very quickly to a point at which it was unmanageable. I could partition the table to increase the speed of both insert and query operations, but I would still have to manage the database (backup, etc.). I did like the idea of inserting a row into a table, however, as this made it simple to log activity by merely inserting the information into a table.

I also wanted to write the log messages to text files that would exist in a location that was readily available to me to be able to research problems. Typically, there are no shares defined on database servers that are available to developers

I finally hit on what I believe is a rather elegant solution: to overcome the growth of the table, I decided to use Service Broker.

Service Broker is a delivery system for routing messages from a Queue to a Service. This routing begins by what is known as the Initiator beginning a conversation with Service Broker and specifying the Target Service with which it wants to communicate. The Target Service can then send a response to the Initiator by sending a message back to the Initiator Service. By defining a Target Queue associated with the Target Service, the effect is that the Message is placed in the Target Queue. The processing of the messages in the Target Queue can be handled directly by SQL Server by specifying a stored procedure to call whenever a message appears on the queue.

The problem I had with using a stored procedure to process the messages was that I wanted to be able to specify a location for the log files and have flexibility in the format of the written messages. After a little reading, I decided that I could create a Windows Service that would query the Target Queue and process the messages. This meant that I would have control over the location of the log files and the format of the messages.

The tasks I needed to complete in order to make this solution work were:

• Define a table in the database of your choice. If you will be logging messages from multiple servers, creating a linked server in each of the other servers can simplify the insertion from these servers into the table.
• Define an INSTEAD trigger for the table that would handle the conversation with the Service Broker service.
• Define a Windows Service that would RECEIVE those messages and write them to a log file.

The sequence of events is:

1. The application senses a condition that requires logging information.
2. The application inserts the pertinent information into the log table.
3. The trigger for the table fires and begins the conversation with the Service Broker Target Service.
4. The Service Broker service adds the message to the Target Queue.
5. The Windows Service receives the message and writes the formatted information to the appropriate log file.

That's the guts of it. The details follow.

Message Type

This defines what kind of messages will be handled. The only specification here is that they will all be XML and verified by Service Broker as valid.

CREATE MESSAGE TYPE [LogRequest] 
 AUTHORIZATION [dbo] 
 VALIDATION = WELL_FORMED_XML

Message Contract

This defines what type of message will be handled and who will send it. We are only interested in sending messages from the client, so we specify the initiator as the sender.

CREATE CONTRACT [LogContract] 
 AUTHORIZATION [dbo] 
 (
 [LogRequest] SENT BY INITIATOR
 )

Queues

Initiator Queue

This defines the queue for the initiator. It is only used to send messages back to the sender, which we are not doing, but it is good practice to define one in case you ever decide to do so.

CREATE QUEUE [dbo].[LogInitiatorQueue]

Target Queue

This defines the queue into which the sender will put the messages.

CREATE QUEUE [dbo].[LogTargetQueue] 
 WITH 
 STATUS = ON , 
 RETENTION = OFF 
 ON [PRIMARY]

Services

Initiator Service

This defines the service for retrieving the messages from the initiator queue.

CREATE SERVICE [LogInitiatorService] 
 AUTHORIZATION [dbo] 
 ON QUEUE [dbo].[LogInitiatorQueue]

Target Service

This defines the service that will handle the messages from the target queue.

CREATE SERVICE [LogTargetService] 
 AUTHORIZATION [dbo] 
 ON QUEUE [dbo].[LogTargetQueue] 
 (
 [LogContract]
 )

Log Table

This table is where the client will insert the messages.

CREATE TABLE [dbo].[LogData]( 
 [MachineName] [varchar(50)] NOT NULL,
 [ProcessName] [varchar](50) NOT NULL,
 [ProcessMessage] [varchar](max) NOT NULL,
 [LogTime] [datetime] NULL
) ON [PRIMARY]

The messages will never actually be inserted into the table. Rather, they will be re-routed to the target service by the use of a trigger that is executed instead of allowing the data to be inserted.

CREATE TRIGGER [dbo].[LogData_Insert] 
 ON [dbo].[LogData] 
 INSTEAD OF INSERT
AS 
BEGIN
 SET NOCOUNT ON;
DECLARE 
 @MessageBody XML, 
 @Handle UNIQUEIDENTIFIER,
 @RequestMsg XML SELECT 

 @RequestMsg = 
 (
  SELECT 
   *
  FROM 
   Inserted 
  FOR XML PATH ('Row'), ROOT('LOG'), TYPE
 );
BEGIN TRANSACTION 
BEGIN DIALOG @Handle
 FROM SERVICE
 [LogInitiatorService]
 TO SERVICE
 N'LogTargetService'
 ON CONTRACT
 [LogContract]
 WITH
 ENCRYPTION = OFF;SEND ON CONVERSATION @Handle
 MESSAGE TYPE 
 [LogRequest](@RequestMsg);
COMMIT TRANSACTION
END

Windows Service

The service will be a Windows Service that will constantly be trying to receive messages from the Target Queue. The standard plumbing for a Windows Service will not be discussed here. The central code that performs the function of receiving the messages from the queue is as follows:

1. Create a connection to the database containing the Service Broker Target Queue.
2. Create a command for the connection that will receive the next message on the Target Queue. This command will wait forever for a message to be available.
3. Create an XML document from the character string received from the execution of the command. This allows us to retrieve the information within the message. Remember that the messages on the Target Queue are XML.
4. Format the information in the message.
5. Determine the log file to which you want to write the message. In my case, I am writing all log files by each computer in its own folder. Each log file will be named using the ProcessName within the message.
6. If log files are being created for each day, or some other period, check to se if the current file needs to be moved o an archive location.
7. Write the formatted message to the log file.

Connection

using ( SqlConnection Conn = new SqlConnection ( this.LogConnectionString ) )
{
Conn.Open ();

Command

using ( SqlCommand Cmd = Conn.CreateCommand () )
{
Cmd.CommandText = "ProcessLogQueue";

The contents of the stored procedure follow:

BEGIN TRANSACTION 

WAITFOR (RECEIVE TOP(1) 
 CONVERT (XML, CONVERT (VARCHAR(MAX), message_body) ) 
FROM 
 LogTargetQueue 

COMMIT TRANSACTION

Cmd.CommandType = System.Data.CommandType.StoredProcedure;
Cmd.CommandTimeout = 0; // no timeout

while ( !this.m_Terminate ) // looping until the service is stopped
{
string Response = Cmd.ExecuteScalar ().ToString (); // execute the command

if ( Response.Length > 0 )
{
XmlDocument Doc = new XmlDocument ();
Doc.LoadXml ( Response );
XmlNode RootNode = Doc.SelectSingleNode ( "LOG" );
XmlNode RowNode = RootNode.SelectSingleNode ( "Row" );
string ProcessName = RowNode.SelectSingleNode ( "ProcessName" ).InnerText;
string MachineName = RowNode.SelectSingleNode ( "MachineName" ).InnerText; string MachineFolder = Path.Combine ( this.LogFolder, MachineName );

if ( !Directory.Exists ( MachineFolder ) )
{
try
{
Directory.CreateDirectory ( MachineFolder );
}
catch ( Exception Ex )
{
// log the failure to a logfile for the Windows Service
return;
}
}

// create the name of the log file

string FileName = Path.Combine ( MachineFolder, ProcessName + ".log" );

try
{
this.CheckLog ( MachineName, FileName ); // does the log file nee to be archived?
}
catch ( Exception Ex )
{
// log the failure to a logfile for the Windows Service
return;
}

using ( StreamWriter SW = new StreamWriter ( FileName, true ) )
{
SW.WriteLine ( string.Format ( "{0} {1}", RowNode.SelectSingleNode ( "LogTime" ).InnerText, RowNode.SelectSingleNode ( "ProcessMessage" ).InnerText ) );
}
}
}
}
}
}
catch ( SqlException Ex )
{
// log the failure to a logfile for the Windows Service and quit
}
catch ( System.Threading.ThreadAbortException )
{
// we have been ordered to quit
}
catch ( Exception Ex )
{
// log the failure to a logfile for the Windows Service and quit
}
}

private void CheckLog ( string MachineName, string FileName )
{
FileInfo FI = new FileInfo ( FileName );

if ( FI.Exists )
{
DateTime Today = Convert.ToDateTime ( DateTime.Now.ToShortDateString () );

if ( FI.LastWriteTime < Today )
{
string ArchiveFileName = Path.GetFileName ( FileName ).Replace ( ".log", FI.LastWriteTime.ToString ( "yyyyMMdd" ) + ".log" );
string MachineFolder = Path.Combine ( this.ArchiveFolder, MachineName );

if ( !Directory.Exists ( MachineFolder ) )
{
Directory.CreateDirectory ( MachineFolder );
}

FI.MoveTo ( Path.Combine ( MachineFolder, ArchiveFileName ) );
}
}
}

An example of the XML produced by the trigger on the log table follows:

<LOG>
 <Row>
  <ProcessName>MyProcess</ProcessName>
  <ProcessMessage>This is the message</ProcessMessage>
  <LogTime>2009-12-20T11:47:47.677</LogTime>
  <MachineName>MyMachine</MachineName>
 </Row>
</LOG>

The essentials here are that we are requesting the next entry from the queue and will wait forever for it. Once we have a message, we extract the Machine Name and Process Name and build a file name from them, using the Machine Name as the folder name. If the file exists, we check to see when a message was last written. If it was not today, we rename it and move it to the archive folder.

Client

As was indicated earlier, the Client, either a stored procedure or any Win32 application, will quite simply insert the message into the database table and move on. As an example, suppose you have an order processing system and, at the end of the process you want to log the number of orders processed by each customer in a batch. You would collect the summary information in a temporary table and run the following code. By doing this, you have started the process described at the beginning of this document.

Note that, if the ProcessMessage is NULL, the Service Broker conversation will fail.

 INSERT INTO Logging.dbo.LogData
 (
  MachineName,
  ProcessName,
  ProcessMessage
 )
 SELECT
   CAST(SERVERPROPERTY('MachineName') AS varchar),
   'ProcessCustomerOrders',
   'Customer: ' + CAST(CutomerID AS varchar) + ' Orders: '+ CAST(OrderCount AS varchar)
  FROM
   @CustomerOrders

Conclusion

In the end, everyone will have their own preferences for this. Being an old main-frame nut, I am very used to scanning logs. The accumulation of logging information into text files makes it very easy for me to locate problems or trace activity without a lot of effort. As an aside, if you find yourself frequently looking at file content, I advise you to take a look at V (available at http://www.fileviewer.com/). It is hands-down the best utility I have ever seen. It includes the ability to tail a file to watch as it changes.

By Ed Swiedler, 2010/01/06

Total article views: 1765 | Views in the last 30 days: 1765