jimmy keen

on .NET, C# and unit testing

Logging test results with NUnit

February 28, 2015 | tags: unit-testing nunit extensions logging design

Recently, a question popped at StackOverflow asking what needed to be done in order to custom-log unit test failures. Not many people know that, but NUnit offers extensions API which could be utilized to solve this very problem. In this post, we’ll see how.

NUnit Addins API

To extend NUnit we need to implement an addin listening to events NUnit triggers during different stages of tests execution. Our response to such events (preferably test finished event) will be logging some data to a file. As simple as that. Let’s see what do we got:

All the components we need are available as NUnit.AddinsDependencies package, available on NuGet.

NUnitFileLoggerAddin

1. Detection

In order for NUnit to detect our addin we need to mark class implementing it with NUnitAddinAttribute and implement IAddin interface:

[NUnitAddin(
  Name = "File Logger",
  Description = "Writes test result to file",
  Type = ExtensionType.Core)]
public partial class NUnitFileLoggerAddin : IAddin

We’ll also kick off unit tests project with the very first test verifying whether our addin is discoverable. With FluentAssertions, it is as easy as:

[Test]
public void NUnitFileLoggingAddin_IsDiscoverable()
{
    var addin = new NUnitFileLoggingAddin();

    addin.Should().BeAssignableTo<IAddin>();
    addin.GetType().Should().BeDecoratedWith<NUnitAddinAttribute>(
        a => a.Type == ExtensionType.Core);
}

2. Installation

Next, the addin must hook itself to NUnit’s extensions system via IAddin.Install method:

public bool Install(IExtensionHost host)
{
  var listeners = host.GetExtensionPoint("EventListeners");
  if (listeners == null)
    return false;

  listeners.Install(this);
  return true;
}

This is to make sure we receive notifications when test-related event occurs.

3. EventListener interface

This interface offers notifications for various stages of test suite execution. The one that we want to hook to is TestFinished method. We’ll simply log time, result and test name. If a test fails, we also save an error message:

public void TestFinished(TestResult result)
{
    using (var file = File.Open("Log.txt", FileMode.Append))
    using (var writer = new StreamWriter(file))
    {
        var message = string.Format("[{0:s}] [{1}] {2}", DateTime.Now,
            result.ResultState, result.Name);
        writer.WriteLine(message);
        var isFailure =
            result.ResultState == ResultState.Error ||
            result.ResultState == ResultState.Failure;
        if (isFailure)
        {
            writer.WriteLine(result.Message);
        }
    }
}

That’s all you need to log test results to custom file. Simply copy NUnitFileLoggingAddin class files to your test project and your tests will be logged to Log.txt file. However, we are far from done.

Design considerations

In its current form our addin is rather poor piece of software. We lack proper unit tests (File.Open and DateTime.Now sort of get in the way) and even changing log file name would require recompilation. This is no good.

Before we jump straight to refactoring let’s take a moment to think about possible improvements and extension points of our addin.

1. Code quality improvements

2. Extensibility

Refactoring for testability and extensibility

Our first step would be to introduce abstractions over file system and time, IFileStreamFactory and ITimeProvider, respectively. Now, we also need to solve the problem with providing those abstractions. Since NUnit will create addin instance using reflection, there should be working parameterless constructor for our addin. Yet we also need constructor with parameters to pass mocked dependencies in unit test. What do we do? We use an anti-pattern – poor man’s DI:

public NUnitFileLoggingAddin()
    : this(new FileStreamFactory(), new TimeProvider())
{
}

public NUnitFileLoggingAddin(
    IFileStreamFactory fileStreamFactory,
    ITimeProvider timeProvider)
{
    this.fileStreamFactory = fileStreamFactory;
    this.timeProvider = timeProvider;
}

We’re good to write few tests for the logging part. As you might know from my previous posts, unit testing, IDisposable and Stream don’t play along very well. To test I/O interactions we will be using StreamRecorder class:

[Test]
public void TestFinished_LogsSuccessfulTestNameAndTimestampToFile()
{
    var testResult = CreateTestResult("DummyTestName",
        ResultState.Success);
    var streamRecorder = new StreamRecorder();
    A.CallTo(() => fileStreamFactory.Create(A<string>._, A<FileMode>._))
        .Returns(streamRecorder.UnderlyingStream);
    A.CallTo(() => timeProvider.Now())
        .Returns(10.May(2015).At(17, 35, 20));

    addin.TestFinished(testResult);

    streamRecorder.WrittenContent.Should()
        .StartWith("[2015-05-10T17:35:20] [Success] DummyTestName")
}

Test above simply verifies whether correct message is written to log file. We should add couple more tests for logging functionality before we proceed to extensibility refactoring. All unit tests written for NUnitFileLoggerAddin can be viewed at my GitHub repository.

Extension points

At this point our addin is fully usable. We might even use it to record its own tests - all we need is a local type inheriting from our base NUnitFileLoggerAddin class:

[NUnitAddin] public class LoggerAddin : NUnitFileLoggerAddin { }

This is a minor nuance given how we want to have our addin reusable, but luckily majority of the features can remain in base class.

Back to extension points. As I mentioned, we want to have control over the output formatting and log file path. To achieve this, our base NUnitFileLoggerAddin will expose several protected virtual members:

protected virtual string LogFilePath { get { return "Log.txt"; } }
protected virtual string CreatePassedTestMessage(TestResult result,
    DateTime currentTime)
protected virtual string CreateFailedTestMessage(TestResult result,
    DateTime currentTime)

Now, our LoggerAddin can for example change the way failed tests are reported:

[NUnitAddin]
public class LoggerAddin : NUnitFileLoggerAddin
{
    protected override string CreateFailedTestMessage(TestResult result,
        DateTime currentTime)
    {
        return string.Format("{0} failed. Investigate!", result.Name);
    }
}

Conclusion

Although we only did simple logging, available API offers much more in terms of extensibility. For example, similar mechanism can be used to write database integration testing API where NUnit will gather all tests marked with special database attribute, and before any of them is run, it will execute some code, for example creating database and inserting test data. We’ll explore these options in the next blog post.

It is also worth noting that upcoming NUnit 3.0 will replace the way how addins are implemented. Read about it at NUnit Addins wiki page and Addins replacement in (NUnit) Framework.