Capturing Log Output in Tests with XUnit 2

02 Jun 2015

xunit 2.x now enables parallel testing by default. According to the docs, using console to output messages is no longer viable:

When xUnit.net v2 shipped with parallelization turned on by default, this output capture mechanism was no longer appropriate; it is impossible to know which of the many tests that could be running in parallel were responsible for writing to those shared resources.

The recommend approach is now to take a dependency on ITestOutputHelper on your test class.

But what if you are using a library with logging support, perhaps a 3rd party one, and you want to capture it's log output that is related to your test?

Because logging is considered a cross-cutting concern, the typical usage is to declare a logger as a static shared resource in a class:

public class Foo
{
    private static readonly ILog s_logger = LogProvider.For<Foo>();

    public void Bar(string message)
    {
        s_logger.Info(message);
    }
}

The issue here is that if this class is used in a concurrent way, it's log output will be interleaved, just in the same way as using console in tests.

Solution

The typical approach to message correlation with logging is to use diagnostic contexts. That is, for each xunit 2.x test collection, we attach a correlation id to each log message and filter + pipe the messages we're interested in to the collection's ITestOutputHelper instance.

In this sample solution:

  1. Using serilog, we capture all log output to an IObservable<LogEvent>. Note we must .Enrich.FromLogContext() for the correlation id to be attached.
  2. When each test class is instantiated, we open a unique diagnostic context, subscribe and filter log messages for that context and pipe them to the test classes' ITestOutputHelper instance.
  3. When the test class is disposed, the subscription and the context is disposed.

A test class will look like this:

public class TestClass1 : IDisposable
{
    private readonly IDisposable _logCapture;

    public TestClass1(ITestOutputHelper outputHelper)
    {
        _logCapture = LoggingHelper.Capture(outputHelper);
    }

    [Fact]
    public void Test1()
    {
        //...
    }

    public void Dispose()
    {
        _logCapture.Dispose();
    }
}

Notes:

  1. While we used LibLog in the sample library, the same approach applies to any library that defines it's own logging abstraction or has a dependency on a logging framework.
  2. While we used Serilog to wire up the observable sink, we could do similar with another logging framework (NLog, Log4Net etc).