Windows Service Logging and the Debug Process

I'm a big proponent of log4net for system logging. The Apache log4net library is a tool to help the programmer output log statements to a variety of output targets. log4net is a port of the excellent Apache log4 framework to the Microsoft .NET runtime. I especially like it's integration with NHibernate. 

This blog post is focusing in on logging in Windows Service. This is not a post about the setting up of log4net but about extending it's capabilities. There's plenty of posts on the interwebs about the actual configuration.

To give the reader some background, I am currently working on a project which requires integration points for the system. In short the system being built using Dynamics CRM needs to on a scheduled basis push and pull data from different systems. To accomplish this I've developed a Windows Service that allows for multiple jobs to be executed from it. I decided to use log4net for the logging interface. 

The issue I came across was during the debugging process. I generally debug a Windows Services on my local machine by using a Windows Form as a UI to start (or stop) the underlying service. By using the following code in the program.cs file:

	static class Program
	{
	/// <summary>
	/// The main entry point for the application.
	/// </summary>
	static void Main(string[] args)
	{
	CommandArgumentCollection argumentCollection = new CommandArgumentCollection(args);
	if (argumentCollection.GetFirstArgument("console") != null)
	{
	Application.Run(new ServiceTest());
	}
	else
	{
	ServiceBase[] ServicesToRun;
	ServicesToRun = new ServiceBase[]
	{
	new Service1()
	};
	ServiceBase.Run(ServicesToRun);
	}
	}
	}

view raw Program.cs hosted with ❤ by GitHub

Then I set whether to run the Windows Form UI by setting the command line argument for the start up project to /console as shown in the image below.

Now when I press F5 the debug form is shown.

The problem was I was always finding myself continuously running SQL queries during the debugging process to look at the log messages, not entirely productive. I figured there had to be a better approach. Through a bit of research I was able to find a decent approach to the problem. The solution was to use a custom AppenderSkeleton. The code is as shown below:

	public class CustomMemoryAppender : AppenderSkeleton
	{
	private readonly StringBuilder logBuffer;
	readonly StringWriter stringWriter;
	private readonly object lockObject = new object();
	public CustomMemoryAppender()
	{
	logBuffer = new StringBuilder();
	stringWriter = new StringWriter(logBuffer);
	}
	protected override void Append(LoggingEvent loggingEvent)
	{
	lock (lockObject)
	{
	if (Layout == null)
	{
	logBuffer.AppendLine(string.Format("{0} - {1}", loggingEvent.Level, loggingEvent.RenderedMessage));
	}
	else
	{
	Layout.Format(stringWriter, loggingEvent);
	}
	}
	}
	public string ReadBuffer()
	{
	lock (lockObject)
	{
	string retVal = logBuffer.ToString();
	logBuffer.Clear();
	return retVal;
	}
	}
	}

view raw ServiceTest.cs hosted with ❤ by GitHub

The is two key parts to the new CustomMemoryAppender class. Firstly, the overridden Append method. This method takes the logging event information and appends it to a StringBuilder variable called logBuffer. Secondly the public method ReadBuffer() this allows a external caller to access the current log message buffer information.

To hook this up in the Windows Form I need to override the Form OnLoad event and add some code:

	protected override void OnLoad(EventArgs e)
	{
	base.OnLoad(e);
	XmlConfigurator.Configure();
	serviceRun.Start();
	appender = new CustomMemoryAppender();
	//Get the logger repository hierarchy.
	var logRepository = (Hierarchy)LogManager.GetRepository();
	//and add the appender to the root level
	//of the logging hierarchy
	logRepository.Root.AddAppender(appender);
	//configure the logging at the root.
	logRepository.Root.Level = Level.All;
	//mark repository as configured and
	//notify that is has changed.
	logRepository.Configured = true;
	logRepository.RaiseConfigurationChanged(EventArgs.Empty);
	}

view raw OnLoad.cs hosted with ❤ by GitHub

The above code informs log4net to include the CustomMemoryAppender in the list of appenders the log4net with log to. It all tells log4net to log all logging events to the new appender.

Now when I press F5 I get the Debug form as well as all the logging messages. 

I've created a sample solution available at GitHub that uses a timer event to create log messages.