Cannot test ILogger Received with NSubstitute

Question

I have a .Net Core 3 application and am trying to test calls to ILogger in my method:

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

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

    public void MyMethod(string message)
    {
        _logger.LogError(message);
    }
}

Having found answers here on SO and on blogs, I know that I have to test against the interface method, not the extension method, so I have this test:

[TestMethod]
public void MyMethodTest()
{
    // Arrange
    var logger = Substitute.For<ILogger<MyClass>>();

    var myClass = new MyClass(logger);

    var message = "a message";

    // Act
    myClass.MyMethod(message);

    // Assert
    logger.Received(1).Log(
        LogLevel.Error,
        Arg.Any<EventId>(),
        Arg.Is<object>(o => o.ToString() == message),
        null,
        Arg.Any<Func<object, Exception, string>>());
}

However, this isn't working and I get this error:

Test method MyLibrary.Tests.MyClassTests.MyMethodTest threw exception: 
NSubstitute.Exceptions.ReceivedCallsException: Expected to receive exactly 1 call matching:
    Log<Object>(Error, any EventId, o => (o.ToString() == value(MyLibrary.Tests.MyClassTests+<>c__DisplayClass0_0).message), <null>, any Func<Object, Exception, String>)
Actually received no matching calls.

    at NSubstitute.Core.ReceivedCallsExceptionThrower.Throw(ICallSpecification callSpecification, IEnumerable`1 matchingCalls, IEnumerable`1 nonMatchingCalls, Quantity requiredQuantity)
   at NSubstitute.Routing.Handlers.CheckReceivedCallsHandler.Handle(ICall call)
   at NSubstitute.Routing.Route.Handle(ICall call)
   at NSubstitute.Core.CallRouter.Route(ICall call)
   at NSubstitute.Proxies.CastleDynamicProxy.CastleForwardingInterceptor.Intercept(IInvocation invocation)
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at NSubstitute.Proxies.CastleDynamicProxy.ProxyIdInterceptor.Intercept(IInvocation invocation)
   at Castle.DynamicProxy.AbstractInvocation.Proceed()
   at Castle.Proxies.ObjectProxy.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at MyLibrary.Tests.MyClassTests.MyMethodTest() in D:\Source\Scratch\MyLibrary\MyLibrary.Tests\MyClassTests.cs:line 25

What am I doing wrong?

netcoreapp3.0 / Microsoft.Extensions.Logging 3.1.2 / NSubstitute 4.2.1

UPDATE: I have tried the match with Arg.Any<>() and get the same result:

logger.Received(1).Log(
    Arg.Any<LogLevel>(),
    Arg.Any<EventId>(),
    Arg.Any<object>(),
    Arg.Any<Exception>(),
    Arg.Any<Func<object, Exception, string>>());

UPDATE 2: I have tried the same test using Moq and get the same result:

logger.Verify(l => l.Log(
        LogLevel.Error,
        It.IsAny<EventId>(),
        It.Is<object>(o => o.ToString() == message),
        null,
        It.IsAny<Func<object, Exception, string>>()),
    Times.Once);

Result:

Test method MyLibrary.Tests.Moq.MyClassTests.MyMethodTest threw exception: 
Moq.MockException: 
Expected invocation on the mock once, but was 0 times: l => l.Log<object>(LogLevel.Error, It.IsAny<EventId>(), It.Is<object>(o => o.ToString() == "a message"), null, It.IsAny<Func<object, Exception, string>>())

Performed invocations:

   Mock<ILogger<MyClass>:1> (l):

      ILogger.Log<FormattedLogValues>(LogLevel.Error, 0, a message, null, Func<FormattedLogValues, Exception, string>)

    at Moq.Mock.Verify(Mock mock, LambdaExpression expression, Times times, String failMessage)
   at Moq.Mock`1.Verify(Expression`1 expression, Times times)
   at Moq.Mock`1.Verify(Expression`1 expression, Func`1 times)
   at MyLibrary.Tests.Moq.MyClassTests.MyMethodTest() in D:\Source\Scratch\MyLibrary\MyLibrary.Tests.Moq\MyClassTests.cs:line 25

Answer 1

The main issue unit testing ILogger invocations with .NET Core 3.* is that FormattedLogValues was changed to internal, it complicates things.

The Moq workaround is to use It.IsAnyType:

public class TestsUsingMoq
{
    [Test]
    public void MyMethod_String_LogsError()
    {
        // Arrange
        var logger = Mock.Of<ILogger<MyClass>>();

        var myClass = new MyClass(logger);

        var message = "a message";

        // Act
        myClass.MyMethod(message);

        //Assert
        Mock.Get(logger)
            .Verify(l => l.Log(LogLevel.Error,
                    It.IsAny<EventId>(),
                    It.Is<It.IsAnyType>((o, t) => ((IReadOnlyList<KeyValuePair<string, object>>) o).Last().Value.ToString().Equals(message)),
                    It.IsAny<Exception>(),
                    (Func<It.IsAnyType, Exception, string>) It.IsAny<object>()),
                Times.Once);
    }
}

NSubstitute doesn't have an It.IsAnyType equivalent at the moment as far as I am aware, which presents an issue when trying to use the Received method. There is a workaround however as it does provide a ReceivedCalls method which you can iterate over and do you own invocation check.

public class TestsUsingNSubstitute
{
    [Test]
    public void MyMethod_String_LogsError()
    {
        // Arrange
        var logger = Substitute.For<ILogger<MyClass>>();

        var myClass = new MyClass(logger);

        var message = "a message";

        // Act
        myClass.MyMethod(message);

        //Assert
        Assert.That(logger.ReceivedCalls()
                .Select(call => call.GetArguments())
                .Count(callArguments => ((LogLevel) callArguments[0]).Equals(LogLevel.Error) &&
                                        ((IReadOnlyList<KeyValuePair<string, object>>) callArguments[2]).Last().Value.ToString().Equals(message)),
            Is.EqualTo(1));
    }
}

As a workaround, it's not a bad one, and could be easily bundled up into an extension method.

FormattedLogValues implements IReadOnlyList<KeyValuePair<string, object>>. The last item in this list is the original message that you specified.

Working sample

Answer 2

I tried wrapping the Logger around an adapter, more like a proxy class. You can mock the adapter interface and that would return what log function has been called.

 public class LoggerAdapter<TType> : ILoggerAdapter<TType>
    {
        private readonly ILogger<TType> _logger;

        public LoggerAdapter(ILogger<TType> logger)
        {
            _logger = logger;
        }
        public void LogInformation(string message, params object[] args)
        {
            _logger.LogInformation(message,args);
        }

        public void LogError(string message, params object[] args)
        {
            _logger.LogError(message, args);
        }
    }

 private readonly ILoggerAdapter<PosUpdateService> _logger = Substitute.For<ILoggerAdapter<PosUpdateService>>();

_logger.Received(1).LogInformation("User with Id {id} was fetched in {0} milliseconds", 
               Arg.Is(Id),
               Arg.Any<long>());