Writing tests for logging messages
Tags: csharp, beginners, dotnet, testing
Published: 2023-04-03 05:00:00

_I originally posted this post [on my blog](https://canro91.github.io/2022/12/04/TestingLoggingAndLogMessages/) a couple of weeks ago. It's part of an ongoing series I've been publishing, called [Unit Testing 101](https://canro91.github.io/UnitTesting)._

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,

```csharp
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,

```csharp
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](https://canro91.github.io/2020/08/11/HowToCreateFakesWithMoq/) for our dependencies. I prefer to call it fakes. There's a [difference between stubs and mocks](https://canro91.github.io/2021/05/24/WhatAreFakesInTesting/).

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](https://canro91.github.io/2021/10/11/DontRepeatLogicInAssertions/).

Also, notice we used a [custom assertion method](https://canro91.github.io/2021/08/16/WriteCustomAssertions/) 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,

```csharp
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);
    }
}
```

<figure>
<img src="https://source.unsplash.com/w2UPekNZFAA/600x400" alt="Pile of tree logs" />

<figcaption>Don't expect identical log...messages. Photo by <a href="https://unsplash.com/es/@chanphoto?utm_source=unsplash&utm_medium=referral&utm_content=creditCopyText">Chandler Cruttenden</a> on <a href="https://unsplash.com/s/photos/log?utm_source=unsplash&utm_medium=referral&utm_content=creditCopyText">Unsplash</a></figcaption>
</figure>

## 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,

```csharp
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()`,

```csharp
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](https://canro91.github.io/2022/10/17/UnitTestingPrinciplesPracticesTakeaways/). I had the chance of sharing my takeaways during a code review session.

***

_Hey! I'm Cesar, a software engineer and lifelong learner. If you want to upgrade your unit testing skills, check my course [Mastering C# Unit Testing with Real-world Examples](https://www.udemy.com/course/mastering-csharp-unit-testing-with-real-world-examples/?referralCode=8456B1B78E2EDE923174) on Udemy. Practice with hands-on exercises and learn best practices by refactoring real-world unit tests._

_Happy coding!_