How to unit test structured logging calls using NSubstitute?

Question

I have a method which has a line as follows:

_logger.LogError(exception, $"Encountered {exception.GetType().Name}. Unable to verify user with id {user.UserId}");

This has a corresponding unit test with the following assertion:

var logger = Substitute.For<ILogger<SyncService>>();

// other Arrange, Act, Assert steps

logger.Received(1).LogError(exception, "Encountered NullReferenceException. Unable to verify user with id 1");

This test was running fine.

However, due to some issues we encountered, this log now needs to be converted into a structured log.

So now the line in the class looks as follows:

_logger.LogError(exception, "Encountered {exceptionType}. Unable to verify user with id {userId}", exception.GetType().Name, user.UserId);

But now when I changed the assertion to the following the test fails:

logger.Received(1).LogError(exception, "Encountered {exceptionType}. Unable to verify user with id {userId}", "NullReferenceException", 1);

The error message is as follows. I have removed the unwanted stack traces to highlight only the important parts:

NSubstitute.Exceptions.ReceivedCallsException : Expected to receive exactly 1 call matching:
    Log<FormattedLogValues>(Error, 0, Encountered NullReferenceException. Unable to verify user with id 1, System.NullReferenceException: Test Exception
   at NSubstitute.ExceptionExtensions.ExceptionExtensions.<>c__DisplayClass0_0.<Throws>b__0(CallInfo _)

   ...// complete stack trace ...

Actually received no matching calls.

Received 1 non-matching call (non-matching arguments indicated with '*' characters):
    Log<FormattedLogValues>(Error, 0, *Encountered NullReferenceException. Unable to verify user with id 1*, System.NullReferenceException: Test Exception
   at NSubstitute.ExceptionExtensions.ExceptionExtensions.<>c__DisplayClass0_0.<Throws>b__0(CallInfo _)

I was initially unable to figure out what I am doing incorrectly. From the 2 messages it seems like the correct method is being called with the correct parameters, but the message is still flagged as non-matching.

But after some digging I came to realize the flagged message is actually a ToString() call to FormattedLogValues which happens when the exception is thrown. Internally, it is trying to compare an instance of string to an instance of FormattedLogValues

I tried to directly assert on Log<FormattedLogValues> but it seems like the class FormattedLogValues is not available for external use.

This is how the issue was resolved earlier: https://github.com/nsubstitute/NSubstitute/issues/384

But now the struct FormattedLogValues is no longer available for public use. There is an open issue regarding this here: https://github.com/dotnet/runtime/issues/67577

But now the question is, how do I test this? I know Moq has a method called It.IsAnyType() which can be used to ignore the type of the message template, but does NSubstitute have anything similar?

I have seen some other posts in StackOverflow with similar issues but the answers do not seem to work when structured logs are used

Answer 1

Here is one thing you can do, which is something I've myself used in a few occasions.

First, create what we are going to call a "testable" logger abstraction:

public abstract class TestableLogger<T> : ILogger<T>
{
    public abstract IDisposable? BeginScope<TState>(TState state)
        where TState : notnull;

    public abstract bool IsEnabled(LogLevel logLevel);

    public void Log<TState>(
        LogLevel logLevel,
        EventId eventId,
        TState state,
        Exception? exception,
        Func<TState, Exception?, string> formatter)
    {
        this.Log(logLevel, eventId, state?.ToString(), exception);
    }

    public abstract void Log(
        LogLevel logLevel,
        EventId eventId,
        string? state,
        Exception? exception);
}

The purpose of this wrapper is to implement ILogger<T> as faithfully as possible, while allowing you to make assertions on a slight variation of the original Log<TState> method: we are "simplifying" the implementation by bypassing the internal formatter/TState class by just calling ToString on the TState argument.

We don't really care about the BeginScope and IsEnabled original members, so we just "pass those over" by implementing them abstractly.

Then, you can now substitute over this new abstract class instead of the original ILogger<T> and assert on it, like this:

[TestClass]
public class UnitTest1
{
    [TestMethod]
    public void TestMethod1()
    {
        // Arrange
        var user = new User { UserId = 1 };
        var exception = new NullReferenceException();
        var logger = Substitute.For<TestableLogger<Service>>();
        var verifier = Substitute.For<IUserVerifier>();
        verifier
            .When(v => v.Verify(user))
            .Throw(exception);

        var service = new Service(logger, verifier);

        // Act
        service.DoStuff(user);

        // Assert
        logger.Received(1).Log(
            LogLevel.Error,
            Arg.Any<EventId>(),
            "Encountered NullReferenceException. Unable to verify user with id 1",
            exception);
    }
}

I've made some assumptions about the rest of your scenario there but this seems sensible. Note I'm asserting using your original message there.

Here is the rest of the code I created to support this example:

public interface IUserVerifier
{
    void Verify(User user);
}

public class User
{
    public int UserId { get; set; }
}

public class Service
{
    private readonly ILogger<Service> logger;
    private readonly IUserVerifier userVerifier;

    public Service(ILogger<Service> logger, IUserVerifier userVerifier)
    {
        this.logger = logger;
        this.userVerifier = userVerifier;
    }

    public void DoStuff(User user)
    {
        try
        {
            this.userVerifier.Verify(user);
        }
        catch (Exception ex)
        {
            this.logger.LogError(
                ex, 
                "Encountered {exceptionType}. Unable to verify user with id {userId}",
                ex.GetType().Name,
                user.UserId);
        }
    }
}

The only caveat here is that you won't be able to assert the individual values passed as structured logging parameters individually, but it is still a somewhat valid assertion IMHO.

An interesting aspect of this approach is that you can actually customize that new abstract method to your liking. I removed just the parts that tend to be problematic, but you could completely change the shape of that method and still be able to assert on top of it, as long as you perform the same call redirection from the original Log method.

I'm currently not aware of a different approach that would allow you to specifically test each parameter.