Unit Testing Logging

As part of the upgrade we’re planning on making to CruiseControl.NET we are using NLog for logging messages. We are also aiming to increase the unit test coverage of the code. So the question arises – how can we test that logging is actually working as it should be?

There’s actually two parts to this question:

1. Are the logs being generated correctly?
2. Are we putting the right stuff in the logs?

Question #1 is really outside our scope – considering the number of different ways the logging can be configured we’d have to duplicate all the tests in NLog itself. So rather than doing this we’re just going to assume that the tests in NLog will pick up any errors with log generation.

That leaves the second question – how can we know we are putting the right stuff into the logs? The short answer is we can’t – but then there is no way that we can guarantee that any code we write is 100% correct!

Instead what I’m interested in doing is checking that we are logging some expected stuff. In other words how can we intercept the logging to ensure that we are logging the expected messages?

To answer this question we need a little bit of background. Logging in NLog can be configured either via a configuration file or via code. Now the recommended way is the config file so it can be changed without forcing a re-compile. But for us the way that we will use is via code.

NLog also has the concept of Targets: where the output is written to. There is a wide variety of different targets for different scenarios (console, file, e-mail, database, etc.) Of interest in unit testing is the Memory target. This will write the log messages to an array in memory.

So all we need is some way to wire up the logging to a memory target and then check the messages that are being written. It would also be nice if the unit tests reset the logging after they’ve finished just in case there has been some configuration in the unit test config file.

To make this easy I have added a helper class to our unit tests that simplifies this whole process. This is a disposable class with a static method for initialising the whole process. To use this class looks something like:

using (var intercept = LogHelper.InterceptLogging(typeof(TypeBeingTested)))
{
    // Tests go here
    var expected = new[]
                        {
                            // Expected messages go here
                            "LogLevel|TypeBeingTested|Message"
                        };
    CollectionAssert.AreEqual(expected, intercept.Messages);
}

Since the class implements IDisposable it can be used in a using statement. This will ensure that the configuration is reset after the tests have finished.

The static method takes in an array of types. These types are the loggers that should be intercepted – after all there can be other messages occurring that we don’t want to intercept.

To actually check the results we need to compare the Messages property on the class with the expected messages. This is just a facade property that exposes the messages from the underlying memory target. As in the example above the messages consist of three parts: loglevel (e.g. debug, info, error, etc.), the loggger (this will be one of the types in the array) and the actual message.

Nice and simple, without adding too much overhead to the testing process.

Let me know if anyone is interested in the actual code behind LogHelper and I will post it. Otherwise it is in the Subversion repository for CruiseControl.NET.

About these ads