One of the biggest hurdles I’ve had to overcome in applications that do file logging is the the ability to write to a log file from one process or thread and be *read* from another process or thread in near real time. Its all about timing. If the timing is a little off, a failure is going to occur due to file locking problems. Even when both processes or threads are accessing the file with as little locking as possible.
Sooner or later you’re going to get an exception (usually System.IO.IOexception). I solved this using a transactional method that incorporates the use of a ReaderWriterLock and a specialized type of collection called a Queue. A ReaderWriterLock (System.Threading.ReaderWriterLock) is a special type of lock that supports single writers and multiple readers. What this means is: You can acquire a lock for single thread doing writes, but still allow multiple concurrent threads to read.
A Queue (System.Collections.Generic.Queue<T>) is a type-safe collection of First In, Last Out objects. Yes, this is essentially a FIFO buffer. For our purposes, we’ll use this to queue a message string which we will retrieve when we are ready to actually write the message to a file. The idea is to use a class that starts a queue processor, of sorts, that will take messages out of the queue in a first come, first serve manner and write each message to the file immediately. What this means is the write buffers created by System.IO.StreamWriter and System.IO.FileStream will be immediately flushed to disk instead of hanging out in the buffer until a later time. The only buffering we will be using is the Queue itself. In doing so, we help to ensure that messages are stored before some condition such as a catastrophic error or unexpected shutdown occurs. So with the queue running on a separate thread, we can submit messages to the queue and then the queue processor will process them as they come in. In this way, we avoid collisions because only one thread is writing to the file at a time.
This scheme would allow for a thread in a Windows Service or daemon (for example) to write to the file while allowing another program using a sentinel (such as a FileSystemWatcher) to monitor changes to the file and then load the file changes into a viewer of sorts. You could have multiple viewers reading the file while the service is writing to it. This is particularly handy if you have some kind of monitoring or management application or maybe even an active log viewer monitoring the file being used on multiple computers across a network keeping an eye on that log.
Now because the queue processor is going to run on its own thread but will be given data by another thread, the best way to handle errors in the processor thread is to raise errors in the form of an event. So when our queue processor encounters a corrupted state or a fatal error, we will catch the exceptions and then pass the exception object via an event that fires. Then in the application that implements this logger can handle the events and react accordingly. The logger also has a flag to indicate whether or not it is initialized.
The processor will do the following:
1.) Acquire a ReaderWriterLock.
2.) Open the log file for read/write access.
3.) Acquire a thread lock.
4.) Dequeue the message.
5.) Release the thread lock.
6.) Write the message to file and flush buffers.
7.) Release ReaderWriterLock
8.) Repeat for next message in queue.
This essentially makes up a transaction. You submit the message to queue using a method call, then a subroutine running on another thread (message processor) processes all the messages currently in the queue and starts over. I’m not going to go into all the details of a how ReaderWriterLock or Queue works here….. you can read the MSDN articles that I linked above. I’m going to demonstrate my implementation of it. Lets start with the processor routine (some code omitted for brevity):
// The namespaces we need to import:
using System;
using System.Collections.Generic;
using System.IO;
using System.Security;
using System.Threading;
//Here's some variables that we'll need
private static String _logFilePath = String.Empty;
private static Boolean _initialized = false;
private static Boolean _enableTimestamp = false;
private static Thread _writerThread = null;
private static Int32 _writes = 0;
private static Int32 _writerTimeouts = 0;
private static ReaderWriterLock _rwl = new ReaderWriterLock();
private static Queue _msgQueue = new Queue();
private static Mutex _logMutex = new Mutex();
private static readonly Object _writeLock = new Object();
// We raise this event if an error occurs.
public static event LoggerEventHandler Failed;
// ...and here's the queue processor method.
private static void LogLoop()
{
FileInfo logFile = new FileInfo(_logFilePath);
// .... code to create log file if it does not exist goes here.
// The outer loop. We continue until we are no longer initialized.
Boolean succeeded = false;
String message = String.Empty;
while (_initialized)
{
try
{
// Acquire the lock (timeout in 100ms)
_rwl.AcquireReaderWriterLock(100);
try
{
// Process the messages in the queue until empty.
while(_msgQueue.Count > 0)
{
// Create a FileStream in append mode. Append mode can only be used with FileAccess.Write access.
// We use FileShare.ReadWrite so other processes or threads can read from it even if we are currently
// writing to it.
using (FileStream saveStream = new FileStream(logFile.FullName, FileMode.Append, FileAccess.Write, FileShare.ReadWrite)
{
// Make sure we can write to the stream.
if (saveStream.CanWrite)
{
// Create the actual writer, dequeue the message, then write
// it to the file immediately.
using (StreamWriter writer = new StreamWriter(saveStream))
{
// Automatically flush the buffer when done.
writer.AutoFlush = true;
// Clear the message string of any previous contents
message = String.Empy;
// Acquire the thread lock.
lock (_writeLock)
{
try
{
// Double-check both inner and outter loop conditions to make sure
// they haven't changed since the last time we checked, then
// dequeue the next message.
if ((_initialized) && (_msgQueue.Count > 0))
{
message = _msgQueue.Dequeue();
}
}
catch (InvalidOperationException)
{
// The queue has been emptied since we last checked _msgQueue.Count.
// This is a rare but possible condition. This could, for example, happen if
// Stop() was called since we last checked the _initialized flag (outter loop),
// since the Stop() method clears the message queue. Since we double-check the
// loop conditions right before dequeue, this should almost never happen.
}
}
// If the message is not null or empty, write it to disk.
if (!String.IsNullOrEmpty(message))
{
writer.WriteLine(message);
saveStream.Flush();
succeeded = true;
}
}
}
}
// Getting here, we had a successful write operation.
if (succeeded)
{
Interlocked.Increment(ref _writes);
}
}
Thread.Sleep(20);
}
catch (Exception ex)
{
// We actually want catch as many possible exceptions, but we'll use 'Exception' as an example.
Failed(null, new LoggerEventArgs(ex));
}
finally
{
// Release the writer lock.
_rwl.ReleaseWriterLock();
}
}
catch (ApplicationException)
{
// The lock request timed out.
Interlocked.Increment(ref _writerTimeouts);
}
}
}As you can see, we created our queue to hold the messages with the statement:
private static Queue _msgQueue = new Queue();
Now since the queue processor runs in its own thread, we’ll need a method for initializing it before we can actually submit any messages to it. The initializer’s primary goal will be to perform any necessary checks prior to lift off, and will then create the thread and start it. Like so:
public static void Start()
{
// If we've already been initialized once before, then
// we do nothing here. This also eliminates the need to
// catch a ThreadStateException when calling the Thread's
// Start() method because the _initialized flag should
// only get altered by the Start() and Stop() methods
// of this class. If _intialized is false, then the
// the state of IsAlive on the thread should also be
// false and/or the Thread object should be null.
if (_initialized)
{
return;
}
// Create the logger thread and start it.
_writerThread = new Thread(new ThreadStart(LogLoop));
_writerThread.IsBackground = true;
_writerThread.Name = "msgLogger";
try
{
_writerThread.Start();
_initialized = true;
}
catch (OutOfMemoryException)
{
// We could not allocate memory for the new thread.
// Just re-throw the exception, preserving the stacktrace.
throw;
}
}Since we have a start method, we will also need a stop method. The stop method should empty the message queue and then abort the thread we create in the start method:
public static void Stop()
{
// Do nothing if we are not currently initialized.
if (!_initialized)
{
return;
}
// Try to stop gracefully first. We use a mutex to help
// ensure that we can alter the state flag and empty the
// queue. In doing so, the queue processor should abort
// quietly on its own.
// Note: The handler for the 'Failed' event should call this
// this method so that it does not continue on in a
// corrupted state.
_logMutex.WaitOne();
_initialized = false;
Thread.Sleep(100);
_msgQueue.Clear();
_logMutex.ReleaseMutex();
// If we're still initialized, then force the thread to abort.
if (_initialized)
{
if (_writerThread != null)
{
try
{
if (_writerThread.IsAlive)
{
_writerThread.Abort();
}
}
catch (ThreadAbortException)
{
// By virtue of calling the Thread.Abort() method,
// a ThreadAbortException will occur. Since we
// expect this to happen and do not intend to
// reset the thread, we just swallow this and
// and move on.
}
finallly
{
// Get to the choppa!
_writerThread = null;
}
}
}
// If we were still initialized before, then we aren't now.
_initialized = false;
}Now that we have all that in place, we’ll need a method for getting messages into the queue so that they can be processed.
public static void WriteEntry(String message)
{
// Stop right there! If we haven't been initialized yet, then we are
// in a bad state to be trying to write to the log.
if (!_initialized)
{
throw new InvalidOperationException("Logger not initialized. You must start the logger before attempting to write.");
}
// .... code for validating log file path here.
// Convert null strings to empty strings.
if (message == null)
{
message = String.Empty;
}
// If timestamping is enabled, the we prepend the
// message with a YMDHMS timestamp.
if (_enableTimestamp)
{
message = String.Format("[{0}] - {1}", DateTime.Now.ToString("yyyy:MM:dd:hh:mm:ss"), message);
}
// Queue the message for writing.
// We ensure the commit occurs by locking the thread until
// we are done.
lock(_writeLock)
{
_msgQueue.Enqueue(message);
}
}That’s it! So to use this thing, you call the Start() method first, then call the WriteEntry() method and when you’re done logging or if the Failed event fires, you call Stop(). You’ll obviously want to put the above code into your own static class (it is very important that this class be static) and include some public accessors for reading the _initialized flag and setting/getting the _enableTimestamp and _logFilePath values. You probably noticed that we passed a custom event arguments object to the Failed event. The LoggerEventArgs class is just used to pass the exception and/or message containing the details of the failure. The following is the code for the LoggerEventArgs class:
using System;
public class LoggerEventArgs : EventArgs
{
private String _message = String.Empty;
private Exception _exception = null;
// Constructors.
public LoggerEventArgs()
: base()
{
}
public LoggerEventArgs(Exception ex)
: base()
{
this._exception = ex;
}
public LoggerEventArgs(String message, Exception ex)
: base()
{
this._message = message;
this._exception = ex;
}
// Properties.
public String Message
{
return this._message;
}
public Exception EventException
{
return this._exception;
}
}We can’t fire the event without the delegate to marshal it to the handler, so here is the necessary delegate:
public delegate void LoggerEventHandler(Object sender, LoggerEventArgs e);
Sweet, right? ”But Cyrus, how do we actually use this thing?” Well, assuming you named your class something like “MessageLogger”, then you would do the following:
void Main(String[] args)
{
MessageLogger.EnableTimeStamp = true;
MessageLogger.LogFilePath = "c:\test.log";
MessageLogger.Failed += new LoggerEventHandler(MessageLogger_Failed);
MessageLogger.Start();
MessageLogger.WriteEntry("Hello World!");
MessageLogger.Stop();
}
void MessageLogger_Failed(Object sender, LoggerEventArgs e)
{
Console.WriteLine("Oh no! The logger crashed!");
Console.WriteLine(String.Format("Error message: {0}", e.EventException.Message));
MessageLogger.Stop();
}Tada! Good stuff. I am sure this can be improved, but it works great for every application I’ve implemented it in so far. It has good performance and has been quite reliable. Even if something bad happens I can restart the logger (I use a timer for this) by calling Stop() and then Start() again. There is a good possibility that the condition that caused the failure in the first place can be caught in the next call to Start(), assuming you’ve put all the necessary checking in there. Happy code-slingin’!
