How to check that an error is logged in a unit test for ASP.NET Core 3.0?

Question

I want to create a unit test to ensure that a method is logging an error using xUnit and Moq. This code worked in ASP.NET Core 2.1:

//Arrange
var logger = new Mock<ILogger<MyMiddleware>>();
var httpContext = new DefaultHttpContext();

var middleware = new MyMiddleware(request => Task.FromResult(httpContext), logger.Object);

//Act
await middleware.InvokeAsync(httpContext);

//Assert
logger.Verify(x => x.Log(LogLevel.Error, It.IsAny<EventId>(), It.IsAny<FormattedLogValues>(), It.IsAny<Exception>(), It.IsAny<Func<object, Exception, string>>()), Times.Once);

To validate that _logger.LogError("Error message"); was called in middleware.InvokeAsync.

However, in ASP.NET Core 3.0, I am unable to verify that the logger is being called. Microsoft.Extensions.Logging.Internal can no longer be referenced, so FormattedLogValues is unavailable.

I tried changing the Assert() to use object instead of FormattedLogValues, and also IReadOnlyList<KeyValuePair<string, object>> since that is what FormattedLogValues is based on (FormattedLogValues.cs).

This is the error message I am getting in the Visual Studio test runner:

Message: 
    Moq.MockException : 
    Expected invocation on the mock once, but was 0 times: x => x.Log<object>(LogLevel.Error, It.IsAny<EventId>(), It.IsAny<object>(), It.IsAny<Exception>(), It.IsAny<Func<object, Exception, string>>())

  Performed invocations:

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

  Stack Trace: 
    Mock.Verify(Mock mock, LambdaExpression expression, Times times, String failMessage)
    Mock`1.Verify(Expression`1 expression, Times times)
    Mock`1.Verify(Expression`1 expression, Func`1 times)
    MyMiddlewareTests.InvokeAsync_ErrorIsLogged() line 35
    --- End of stack trace from previous location where exception was thrown ---

How can I validate the error is being logged in ASP.NET Core 3.0?

Infante

Add a setup for the Log method. – Euphemiah

Answer 1

There is an issue on the aspnet github page about this. It seems the problem is with Moq and they have made changes to fix it.

You will need to upgrade to Moq 4.13 to get the fix.

They have introduced an It.IsAnyType to resolve the problem with internal objects so you should be able to change the object reference to It.IsAnyType and write your test like this:

logger.Verify(x => x.Log(LogLevel.Error, It.IsAny<EventId>(), It.IsAny<It.IsAnyType>(), It.IsAny<Exception>(), (Func<It.IsAnyType, Exception, string>)It.IsAny<object>()), Times.Once);

Note: The last parameter needs to be type cast as Moq doesn't currently support nested type matchers.

More details from Moq can be found here

Decolorize

How can you verify the message that was passed to the Log method? – Signorelli

Answer 2

This is a bit late, but I just want to add that if you are asserting for specific messages being logged, you can create a custom matcher that inspects the message:

 logger.Verify(x => x.Log(LogLevel.Error,
      It.IsAny<EventId>(),
      It.Is<It.IsAnyType>((x, _) => LogMessageMatcher(x, "Expected error message")),
     It.IsAny<Exception>(),
     It.IsAny<Func<It.IsAnyType, Exception, string>>()), Times.Once);

The MatcherMethod would be a static method like so:

     public static bool LogMessageMatcher(object formattedLogValueObject, string message)
    {
        var logValues = formattedLogValueObject as IReadOnlyList<KeyValuePair<string, object>>;
        return logValues.FirstOrDefault(logValue => logValue.Key == "{OriginalFormat}")
                         .Value.ToString() == message;
    }

Suzetta

Answer 3

I use SGA (Setup, Grab, Assert) approach.

//In the setup part
var mockLog = new Mock<ILogger>(MockBehavior.Strict);
string error = null;
mockLog.Setup(l => l
    .Error(It.IsAny<Exception>(), It.IsAny<string>()))
    .Callback((Exception b, string c) =>
    {
        error = c + " " + b.GetBaseException().Message;
        // This would keep only the last error, but it's OK, since there should be zero
        // Sometimes I use a collection and append the error info.
    });


//In the assert part
Assert.IsNull(error, $"Error detected: {error}");

Mundane