Writing tests for logging messages

I originally posted this post on my blog a couple of weeks ago. It's part of an ongoing series I've been publishing, called Unit Testing 101.

---

As code reviewer, these days I had to take a look at a controller that logs the exceptions thrown by a service. This is how that controller looked and what I learned about testing logging messages.

When writing unit tests for logging, assert that actual log messages contain keywords like identifiers or requested values. Don't assert that actual and expected log messages are exactly the same.

1. Don't expect identical log messages

The controller I reviewed looked like this,

using Microsoft.AspNetCore.Mvc;
using OnTestingLogMessages.Services;

namespace OnTestingLogMessages.Controllers;

[ApiController]
[Route("[controller]")]
public class SomethingController : ControllerBase
{
    private readonly IClientService _clientService;
    private readonly ILogger<SomethingController> _logger;

    public SomethingController(IClientService clientService,
                               ILogger<SomethingController> logger)
    {
        _clientService = clientService;
        _logger = logger;
    }

    [HttpPost]
    public async Task<IActionResult> PostAsync(AnyPostRequest request)
    {
        try
        {
            // Imagine that this service does something interesting...
            await _clientService.DoSomethingAsync(request.ClientId);

            return Ok();
        }
        catch (Exception exception)
        {
            _logger.LogError(exception, "Something horribly wrong happened. ClientId: [{clientId}]", request.ClientId);
            //      👆👆👆
            // Logging things like good citizens of the world...

            return BadRequest();
        }
    }
}

Nothing fancy. This is an API controller that called an IClientService service and logged the exception thrown by it. I wrote a funny log message here just to prove a point. Yes, exception filters are a better idea, but bear with me.

To test if the controller logs exceptions, we could write a unit test like this,

using Microsoft.Extensions.Logging;
using Moq;
using OnTestingLogMessages.Controllers;
using OnTestingLogMessages.Services;

namespace OnTestingLogMessages.Tests;

[TestClass]
public class SomethingControllerTests
{
    [TestMethod]
    public async Task PostAsync_Exception_LogsThatException()
    {
        var clientId = 123456;

        var fakeClientService = new Mock<IClientService>();
        fakeClientService
            .Setup(t => t.DoSomethingAsync(clientId))
            .ThrowsAsync(new Exception("Expected exception..."));
            //           👆👆👆
            // 3...2...1...💣...
        var fakeLogger = new Mock<ILogger<SomethingController>>();
        var controller = new SomethingController(fakeClientService.Object, fakeLogger.Object);
        //                                       ^^^^^

        var request = new AnyPostRequest(clientId);
        await controller.PostAsync(request);

        var expected = $"Something horribly wrong happened. ClientId: [{clientId}]";
        //  👆👆👆
        // We expect exactly the same log message from the PostAsync
        fakeLogger.VerifyWasCalled(LogLevel.Error, expected);
    }
}

In that test, we used Moq to create fakes for our dependencies. I prefer to call it fakes. There's a difference between stubs and mocks.

Notice we're expecting the actual log message to be exactly the same as the one inside the SomethingController. Can you already spot the duplication? In fact, we're rebuilding the log message inside our tests. We're duplicating the logic under test.

Also, notice we used a custom assertion method to make our assertions less verbose. VerifyWasCalled() is an extension method that inspects the Moq instance to check if the actual and expected messages are equal. Here it is,

public static class MoqExtensions
{
    public static void VerifyWasCalled<T>(
        this Mock<ILogger<T>> fakeLogger,
        LogLevel logLevel,
        string message)
    {
        fakeLogger.Verify(
            x => x.Log(
                logLevel,
                It.IsAny<EventId>(),
                It.Is<It.IsAnyType>((o, t) =>
                    string.Equals(message, o.ToString(), StringComparison.InvariantCultureIgnoreCase)),
                    //     👆👆👆
                It.IsAny<Exception>(),
                It.IsAny<Func<It.IsAnyType, Exception?, string>>()),
            Times.Once);
    }
}

Don't expect identical log...messages. Photo by Chandler Cruttenden on Unsplash

2. Instead, expect log messages to contain keywords

To make our unit tests more maintainable, let's check that log messages contain keywords or relevant substrings, like identifiers and values from input requests. Let's not check if they're identical to the expected log messages. Any change in casing, punctuation, spelling or any other minor change in the message structure will make our tests break.

Let's rewrite our test,

using Microsoft.Extensions.Logging;
using Moq;
using OnTestingLogMessages.Controllers;
using OnTestingLogMessages.Services;

namespace OnTestingLogMessages.Tests;

[TestClass]
public class SomethingControllerTests
{
    [TestMethod]
    public async Task PostAsync_Exception_LogsException()
    {
        var clientId = 123456;

        var fakeClientService = new Mock<IClientService>();
        fakeClientService
            .Setup(t => t.DoSomethingAsync(clientId))
            .ThrowsAsync(new Exception("Expected exception..."));
            //           👆👆👆
            // 3...2...1...💣...
        var fakeLogger = new Mock<ILogger<SomethingController>>();
        var controller = new SomethingController(fakeClientService.Object, fakeLogger.Object);

        var request = new AnyPostRequest(clientId);
        await controller.PostAsync(request);

        // var expected = $"Something horribly wrong happened. ClientId: [{clientId}]";
        // We don't need to rebuild the logging message here
        fakeLogger.VerifyMessageContains(LogLevel.Error, clientId.ToString());
        //         👆👆👆
        // We expect the same log message to only contain the clientId
    }
}

This time, we rolled another extension method, VerifyMessageContains(), removed the expected log message and asserted that the log message only contained only relevant subtrings: the clientId.

Here it is the new VerifyMessageContains(),

public static class MoqExtensions
{
    public static void VerifyMessageContains<T>(
        this Mock<ILogger<T>> fakeLogger,
        LogLevel logLevel,
        params string[] expected)
    {
        fakeLogger.Verify(
            x => x.Log(
                logLevel,
                It.IsAny<EventId>(),
                It.Is<It.IsAnyType>((o, t) =>
                    expected.All(s => o.ToString().Contains(s, StringComparison.OrdinalIgnoreCase))),
                    // 👆👆👆
                    // Checking if the log message contains some keywords, instead
                It.IsAny<Exception>(),
                It.IsAny<Func<It.IsAnyType, Exception?, string>>()),
            Times.Once);
    }
}

Voilà! That's how to make our test that checks logging messages more maintainable. By not rebuilding log messages inside tests and asserting that they contain keywords instead of expecting to be exact matches.

Here we dealt with logging for diagnostic purposes (logging to make troubleshooting easier for developers). But if logging were a business requirement, we should have to make it a separate "concept" in our code. Not in logging statements scatter all over the place.

I first found this concept on the book Unit Testing Principles, Practices, and Patterns. I had the chance of sharing my takeaways during a code review session.

---

If you want to upgrade your unit testing skills, check my course: Mastering C# Unit Testing with Real-world Examples on Udemy. Write readable and maintainable unit tests in 1 hour by refactoring real-world tests — Yes, real tests. No boring tests for a Calculator class.

Happy coding!