I’ve been playing with a simple logging framework that I’ve had lying around for ages and thought I’d add an NLog implementation just for kicks and giggles. It also gave me an opportunity to play with the ApprovalTests framework by Llewellyn Falco.
Very briefly ApprovalTests lets you compare output generated during a test with a predefined example. If they differ the test fails. In this case I wanted to verify that a log file generated during a the execution of a unit test matched an example log file. I could then be sure that the log file had been generated and that the contents were correctly formatted.
I’m not going in to a great deal of detail about the basics of unit testing here. Suffice is to say that I’m using NUnit.
In Visual Studio I created a test project, added a reference to the project containing my logger implementation and added a few NuGet packages to the test project:
Note that I’ve added ApprovalTests and NLog as well as NUnit.
I added an App.config file to the test project and put some basic NLog configuration in it. NLog is very helpful and attempts to automatically configure itself on start-up by looking for configuration files in some standard locations. One of those is – you guessed it – the standard App.config file.
<?xml version="1.0" encoding="utf-8" ?>
<configuration>
<configSections>
<section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog"/>
</configSections>
<nlog throwExceptions="true">
<targets>
<target name="file" type="File" fileName="log.txt" layout="${level:uppercase=true}|${logger}|${message}|${exception}" />
</targets>
<rules>
<logger name="*" minlevel="Debug" writeTo="file" />
</rules>
</nlog>
</configuration>
Note the target on line 8. That defines the layout for a log message and therefore what we expect to see for each entry in the log file. The macros (prefixed with $) will be replaced with appropriate values when the log entry is written. Also note that the generated log file will be called log.txt and will appear in the same directory as the compiled dlls.
The next step is to create a test fixture. Here’s some code:
namespace Andy.French.Logging.NLog.Tests
{
using System;
using System.IO;
using ApprovalTests;
using ApprovalTests.Reporters;
using NUnit.Framework;
/// <summary>
/// Tests for the <see cref="Andy.French.Logging.NLog.Logger"/>.
/// </summary>
[TestFixture]
public class LoggerTests
{
/// <summary>The logger to test.</summary>
private ILogger logger;
/// <summary>
/// Sets up a unit test.
/// </summary>
[SetUp]
public void SetUp()
{
this.logger = new Logger("This.Is.A.Test.Logger");
}
/// <summary>
/// Tests that the information method the with a string argument writes a message in correct format.
/// </summary>
[Test]
[UseReporter(typeof(DiffReporter))]
public void Information_WithStringArgument_WritesInfoMessageInCorrectFormat()
{
// Arrange
// Act
this.logger.Information("This is a test message.");
// Assert
Approvals.Verify(new FileInfo("log.txt"));
}
/// <summary>
/// Tears down a unit test.
/// </summary>
[TearDown]
public void TearDown()
{
if (File.Exists("log.txt"))
{
File.Delete("log.txt");
}
}
}
}
So what’s going on here?
Firstly, we have a setup method that instantiates a new instance of my Logger class prior to execution of each unit test. We also have a teardown method that checks for the log file at the end of each unit test and if it’s there it deletes it. This way we guarantee that each unit test starts with a clean slate.
Update: The teardown method isn’t strictly required because ApprovalTests cleans up after each unit test run. In this case it deletes the log file.
There are a couple of interesting lines in the test. On line 33 there’s a UseReporter attribute. This is part of the ApprovalTests framework and does some interesting things. More on that later.
On line 42 we make a call to Approvals.Verify. Note we aren’t using standard NUnit assertions here but are using the ApprovalTests API instead. This call is going to check that the log file matches the predefined example. If it doesn’t, the test fails.
So where is the example log file and how do we generate it? That’s where the UseReporter attribute comes in.
The first time you run the test in Visual Studio (I use the ReSharper unit test runner) the test will fail because we haven’t got an example for ApprovalTests to use to make a comparison with. Because we’ve added the UseReporter attribute ApprovalTests steps in and reports what’s going on. It actually creates an example file for us, shows us what’s in the generated file and allows us to edit the example.
Here’s the test failure in the ReSharper test runner:
And this is what we’ve got in the Visual Studio editor:
The output in the actual log file is correct so we can safely copy the text from the log file (on the left) into the example (on the right) and save it.
Note that ApprovalTests has created the example file in the project folder and has used a naming convention based on the name of the test class and the name of the test method. ApprovalTests uses this naming convention to matchup an example file with a specific unit test. In this case the name is:
LoggerTests.Information_WithStringArgument_WritesInfoMessageInCorrectFormat.approved.txt
To see this file click the ‘Show All Files’ icon in the Solution Explorer. Right-click on it and select ‘Include In Project’. The example files need to be saved with the project and added to version control.
Next time the test is run we get a pass!
By the way, if you’re wondering about the test method naming convention it’s the one I’ve used for years and was first suggested by Roy Osherove.
Update: I forgot to mention that ApprovalTests doesn’t just work with text-based files like the log file we were testing here. It can work with a variety of file formats including images. You can find the source code here if you are interested in poking around.
