I’ve been meaning to write this post for a few weeks now and a post by Anthony Giretti prompted me to get moving! Thanks @anthonygiretti!

In Anthony’s blog he looks at how to mock the ILogger extension methods using a library called NSubstitute (more info). My mocking library of choice is Moq and bizzarely I also had the same issue as Anthony a few weeks ago.

In this post I’m going to show how you can verify calls to ILogger using Moq and how to make it reusable through extension methods.

ILogger Extension Methods

If you have used logging and ILogger in your dotnet code you will most likely have come across the ILoggerExtensions. These give handy extension methods for logging at various log levels (Information, Warning, Debug etc.) without you, the developer, having to deal with all the possible values to the underlying base method call.

Now the issue is that you can’t mock an extension method as by definition it is just syntatic sugar for a static method. So what you have to do is mock the underlying call on the “thing” the extension method is extending.

In the case of ILoggerExtensions (link) all the extension methods end up calling …

/// <summary>
/// Formats and writes a log message at the specified log level.
/// </summary>
/// <param name="logger">The <see cref="ILogger"/> to write to.</param>
/// <param name="logLevel">Entry will be written on this level.</param>
/// <param name="eventId">The event id associated with the log.</param>
/// <param name="exception">The exception to log.</param>
/// <param name="message">Format string of the log message.</param>
/// <param name="args">An object array that contains zero or more objects to format.</param>
public static void Log(this ILogger logger, LogLevel logLevel, EventId eventId, Exception exception, string message, params object[] args)
{
    if (logger == null)
    {
        throw new ArgumentNullException(nameof(logger));
    }

    logger.Log(logLevel, eventId, new FormattedLogValues(message, args), exception, _messageFormatter);
}

… so you have to look to mock the call to logger.Log above.

Now the interface defines a TState which can be anything, however the underlying “state” which the ILogger uses is the FormattedLogValues (see above). Personlly this is not ideal for a couple of reasons including it has static state internally which caches log message templates and that it is internal so can’t be mocked easily!

What Do You Need To Moq?

Looking at the signature of the main Log method there are a few items which need to be sorted out.

/// <summary>Writes a log entry.</summary>
/// <param name="logLevel">Entry will be written on this level.</param>
/// <param name="eventId">Id of the event.</param>
/// <param name="state">The entry to be written. Can be also an object.</param>
/// <param name="exception">The exception related to this entry.</param>
/// <param name="formatter">Function to create a <see cref="T:System.String" /> message of the <paramref name="state" /> and <paramref name="exception" />.</param>
/// <typeparam name="TState">The type of the object to be written.</typeparam>
void Log<TState>(
    LogLevel logLevel,
    EventId eventId,
    TState state,
    Exception exception,
    Func<TState, Exception, string> formatter);

They all look relatively straight forward except it keeps coming back to this TState and how do we mock that?

While a collegue and I were trying to resolve this issue and we found a comment on a Moq github issue which used a Moq construct I had not seen before It.IsAnyType. Now I’ve been using Moq for a number of years but not noticed that this was added in 4.13, so pretty new! This allows for matching generic argument types.

I have only started to scratch the surface of this construct but what I’ve found so far is pretty cool.

Sample Test Class

First we need a class to test, insert very basic example class …

public class PleaseTestMe
{
    private readonly ILogger<PleaseTestMe> _logger;

    public PleaseTestMe(ILogger<PleaseTestMe> logger)
    {
        _logger = logger;
    }

    public void RunMe()
    {
        _logger.LogDebug("Logging this ...");
    }
}

Very simple class. It has a logger dependency in the constructor and then the LogDebug method is called in the RunMe method. Simple and straight forward. Having an ILogger passed into the constructor is a popular pattern when using dependency injection.

All the code for this post can be found on my github repository.

So how do we test it?

Testing Attempt No. 1

[Fact]
public void VerifyWasCalled()
{
    // Arrange
    var loggerMock = new Mock<ILogger<PleaseTestMe>>();
    var sut = new PleaseTestMe(loggerMock.Object);

    // Act
    sut.RunMe();

    // Assert
    loggerMock.Verify(
        x => x.Log(
            It.IsAny<LogLevel>(),
            It.IsAny<EventId>(),
            It.Is<It.IsAnyType>((v, t) => true),
            It.IsAny<Exception>(),
            It.Is<Func<It.IsAnyType, Exception, string>>((v, t) => true)));
}

So using the initial comment code as a base we have said verify a call to Log is called, but any value for any of the parameters is passed through. As we are using the It.Is<It.IsAnyType>() construct and passing in a func style predicate which always returns true it doesn’t do much.

This works, but if you change the call in PleaseTestMe.RunMe to ..

public void RunMe()
{
    _logger.LogWarning("Logging this ...");
}

… the test still passes, not good!

Testing Attempt No. 2

[Fact]
public void VerifyWasCalledWithExpectedValues()
{
    // Arrange
    var loggerMock = new Mock<ILogger<PleaseTestMe>>();
    var sut = new PleaseTestMe(loggerMock.Object);

    // Act
    sut.RunMe();

    // Assert
    loggerMock.Verify(
        x => x.Log(
            It.Is<LogLevel>(l => l == LogLevel.Debug),
            It.IsAny<EventId>(),
            It.Is<It.IsAnyType>((v, t) => true),
            It.IsAny<Exception>(),
            It.Is<Func<It.IsAnyType, Exception, string>>((v, t) => true)));
}

Now we need to change the verify call to check for a specific LogLevel by using the It.Is<T> construct. We can see from the above we are now wanting to check the parameter which is passed through to make sure the level we want, Debug in this case, is the actual value passed through.

But what happens if we want to check what the message parameter is?

Testing Attempt No. 3

[Fact]
public void VerifyWasCalledWithMessage()
{
    // Arrange
    var loggerMock = new Mock<ILogger<PleaseTestMe>>();
    var sut = new PleaseTestMe(loggerMock.Object);

    // Act
    sut.RunMe();

    // Assert
    loggerMock.Verify(
        x => x.Log(
            It.Is<LogLevel>(l => l == LogLevel.Debug),
            It.IsAny<EventId>(),
            It.Is<It.IsAnyType>((v, t) => v.ToString() == "Logging this ..."),
            It.IsAny<Exception>(),
            It.Is<Func<It.IsAnyType, Exception, string>>((v, t) => true)));
}

The It.Is<T> construct has 2 method signatures. One which takes the T and returns a bool …

public static TValue Is<TValue>(Expression<Func<TValue, bool>> match)

… but the whole point is we don’t know what TValue is at this point, so the second …

public static TValue Is<TValue>(Expression<Func<object, Type, bool>> match)

… which gives you more access to what is going on.

The object is the “thing” which is passed in, in this case it will be the Microsoft.Extensions.Logging.FormattedLogValues instance. The Type is the type of the parameter, again in this case it will be Microsoft.Extensions.Logging.FormattedLogValues and it needs to return whether it was successful or not.

To check that the message being passed in was equal to a string we can call ToString() on the FormattedLogValues instance and it will resolve the formatted string. This is enough for our testing.

But this is quite a lot of code to write to check one Debug message, so how can we refactor this into something which is reusable in other tests?

Testing Attempt No. 4

[Fact]
public void VerifyWasCalledWithReusableExtension()
{
    // Arrange
    var loggerMock = new Mock<ILogger<PleaseTestMe>>();
    var sut = new PleaseTestMe(loggerMock.Object);

    // Act
    sut.RunMe();

    // Assert
    loggerMock.VerifyDebugWasCalled();
}

We want to make the unit test as clean and descriptive as possible without adding a lot of boiler plate code which can just get in the way. A technique I’ve been using recently has been an adaptation on Matthew Jones’ Fluent Test Classes where I write extension methods on top of Mock<T> to abstract this noise away.

public static Mock<ILogger<T>> VerifyDebugWasCalled<T>(this Mock<ILogger<T>> logger)
{
    logger.Verify(
        x => x.Log(
            It.Is<LogLevel>(l => l == LogLevel.Debug),
            It.IsAny<EventId>(),
            It.Is<It.IsAnyType>((v, t) => true),
            It.IsAny<Exception>(),
            It.Is<Func<It.IsAnyType, Exception, string>>((v, t) => true)));

    return logger;
}

I return the Mock<ILogger<T>> from the method so various items can be chained together. I recommend reading his post.

But we’ve lost the message checking!

Testing Attempt No. 5

[Fact]
public void VerifyWasCalledWithReusableExtensionWithMessage()
{
    // Arrange
    var loggerMock = new Mock<ILogger<PleaseTestMe>>();
    var sut = new PleaseTestMe(loggerMock.Object);

    // Act
    sut.RunMe();

    // Assert
    loggerMock.VerifyDebugWasCalled("Logging this ...");
}

With this version of the extension method (below) it keeps it clean and it allows for checking the message.

public static Mock<ILogger<T>> VerifyDebugWasCalled<T>(this Mock<ILogger<T>> logger, string expectedMessage)
{
    Func<object, Type, bool> state = (v, t) => v.ToString().CompareTo(expectedMessage) == 0;
    
    logger.Verify(
        x => x.Log(
            It.Is<LogLevel>(l => l == LogLevel.Debug),
            It.IsAny<EventId>(),
            It.Is<It.IsAnyType>((v, t) => state(v, t)),
            It.IsAny<Exception>(),
            It.Is<Func<It.IsAnyType, Exception, string>>((v, t) => true)));

    return logger;
}

To check that the message value is what we want to test we can call ToString, as before, on the instance value being passed through. To make it easier to read I define a local Func<object, Type, bool> definition which checks the ToString value of the instance and then call that inside the It.Is<T> call. This allows for readability of what we are checking as well as helps with debugging when initially setting it up.

Advanced Scenarios

So what more could we want to do with this?

Run multiple of the same calls in a loop
Run many different debug messages in the method
Check different log message levels during the same test.

To address the additional scenarios you can combine techniques we’ve discussed and create an extension method which can handle different levels, different times it’s called and different messages.

public static Mock<ILogger<T>> VerifyLogging<T>(this Mock<ILogger<T>> logger, string expectedMessage, LogLevel expectedLogLevel = LogLevel.Debug, Times? times = null)
{
    times ??= Times.Once();

    Func<object, Type, bool> state = (v, t) => v.ToString().CompareTo(expectedMessage) == 0;

    logger.Verify(
        x => x.Log(
            It.Is<LogLevel>(l => l == expectedLogLevel),
            It.IsAny<EventId>(),
            It.Is<It.IsAnyType>((v, t) => state(v, t)),
            It.IsAny<Exception>(),
            It.Is<Func<It.IsAnyType, Exception, string>>((v, t) => true)), (Times)times);

    return logger;
}

With the fluent nature of the extension method it keeps the tests clean and readable. I have also designed it so it can have some default values so for one call debug testing there is only the expected message required for the invocation.

[Fact]
public void VerifyMultiDebug()
{
    // Arrange
    var loggerMock = new Mock<ILogger<PleaseTestMe>>();
    var sut = new PleaseTestMe(loggerMock.Object);

    // Act
    sut.RunMeMultiDebug();

    loggerMock.VerifyLogging("Message one.")
        .VerifyLogging("Message two.")
        .VerifyLogging("Message three.");
}

Check out my github repo for these scenarios in full.

Conclusion

In this post we have reviewed how we can verify specific log level calls are called via the ILoggerExtensions extension methods. This has been done by mocking the underlying Log method call. We have also looked at how we can refactor the code into a reusable extension method which can then allow us to make additional verify calls in a fluent style while keeping things DRY.

Any questions/comments then please contact me on Twitter @WestDiscGolf

ILogger Extension Methods#

What Do You Need To Moq?#

Sample Test Class#

Testing Attempt No. 1#

Testing Attempt No. 2#

Testing Attempt No. 3#

Testing Attempt No. 4#

Testing Attempt No. 5#

Advanced Scenarios#

Conclusion#