Testing logging code with Microsoft.Extensions.Logging and FakeLogger

Unit testing is most often used for testing business logic. But what if you want to ensure that your code logs important messages to your log store? In this post, I'll introduce you to FakeLogger and how it can be used to test logging code when using Microsoft.Extensions.Logging and the ILogger interface.

So, let's start by discussing why to even unit-test logging code. Adding good logging to your code is an often forgotten or down-prioritized practice. Until errors start happening in production and no one understands what's wrong. Making sure that logging is added and working as expected makes it a lot easier for you to figure out why a bug was introduced.

This post will use Microsoft.Extensions.Logging as the logging framework. Solutions similar to what is presented in this post also exist for other logging frameworks. If people are interested, I might write one or more posts for other frameworks.

Let's use a simple method as an example of testing logging. The complexity of the method under test is irrelevant to the purpose of the post, so I'll use something as simple as possible:

public class Math
{
    private readonly ILogger<Math> logger;

    public Math(ILogger<Math> logger)
    {
        this.logger = logger;
    }

    public int? Divide(int dividend, int divisor)
    {
        try
        {
            logger.LogInformation("Dividing {Dividend} with {Divisor}", dividend, divisor);
            return dividend / divisor;
        }
        catch (Exception ex)
        {
            logger.LogError(ex, "Error during divide");
            return null;
        }
    }
}

The code introduces a Math class with a Divide method. The Divide method is implemented using a try/catch which will log any errors happening and return null. In real life, you'd want to check input parameters and not create a control flow using exceptions. More information in this post: C# exception handling best practices. For now, let's accept this abomination of a class and start writing a unit test:

public class MathTest
{
    [Test]
    public void CanDivide()
    {
        // Arrange
        var math = new Math(NullLogger<Math>.Instance);

        // Act
        var result = math.Divide(10, 5);

        // Assert
        Assert.That(result, Is.EqualTo(2));
    }
}

The CanDivide method uses NUnit (the unit-test framework isn't really important here) to make sure that the Divide method works properly. In case you didn't know about NullLogger it's a great way to provide a not null object for code dependent of an ILogger. I have seen too many null checks for the injected logger in my time.

To test that the Divide method will log an error, let's look into the FakeLogger. Start by installing the Microsoft.Extensions.Diagnostics.Testing NuGet package in the test project:

dotnet add package Microsoft.Extensions.Diagnostics.Testing

Then we can use the FakeLogger class to create a logging instance in a new test method:

[Test]
public void CanLogError()
{
    // Arrange
    var logger = new FakeLogger<Math>();
    var math = new Math(logger);

    // Act
    var result = math.Divide(10, 0);

    // Assert
    Assert.That(result, Is.Null);
}

You will notice no checks for any logged messages when dividing with zero so let's fix that. The FakeLogger provide a property named Collector which will let us inspect the log messages sent to the FakeLogger object we created. There's a handy little property named LatestRecord which should be our error in this example:

// Assert
Assert.That(result, Is.Null);
Assert.That(logger.Collector.LatestRecord, Is.Not.Null);
Assert.That(logger.Collector.LatestRecord.Message, Is.EqualTo("Error during divide"));

We can also validate the count of messages logged:

Assert.That(logger.Collector.Count, Is.EqualTo(1));

The line above will fail the test since our code stores both a Information message and a Error message. Luckily, FakeLogger provide a way to specify options:

var options = new FakeLogCollectorOptions();
options.FilteredLevels.Add(LogLevel.Error);
var collection = FakeLogCollector.Create(options);
var logger = new FakeLogger<Math>(collection);

In the example, I'm using the FakeLogCollectorOptions class to specify which log levels I'm interested in for this test. The LogLevels added to the FilteredLevels property will be the only log levels saved by the FakeLogger born with these options.

FakeLogCollectorOptions also support a range of other ways of tweaking how and if the logged messages get logged. An interesting hook is the OutputSink action that can be used to output debug info or even collect a separate data structure of log messages for more advanced filtering than supported by options:

options.OutputSink = msg =>
{
    Console.WriteLine(msg);
};

Another benefit of using the FakeLogger is that you can instruct it to overrule disabled log levels to get ALL log messages even though the configuration is specified not to log a particular log level:

options.CollectRecordsForDisabledLogLevels = true;

I hope that you feel ready to start testing your log messages using the FakeLogger.