Sometimes when we develop unit tests it’s convenient to check if the tested code wrote something to the log.
Is it a good practice to assert that some particular message appeared in the logs? I think there are pros and cons. On the pros side, we can make general assertions like “no errors were written to the log”. Testing for error messages can also assure us that a specific edge case was handled. On the con side, it usually feels flaky. This is because log messages tend to change over time. This might require us to update tests every time a log message was improved a bit.
But if we decide to write assertions based on logs, then it’s time to code 🙂 Since the release of .NET Core, the standard logging mechanism is ILogger
which comes with the platform. And the most popular library for mocking I encountered in projects is Moq.
When we try to mock ILogger
, however, we might find ourselves dealing with an error like:
System.NotSupportedException : Unsupported expression: x => x.LogError(It.IsAny<string>(), new[] { })
Extension methods (here: LoggerExtensions.LogError) may not be used in setup / verification expressions.
at Moq.Guard.IsOverridable(MethodInfo method, Expression expression)
(...)
at Moq.Mock`1.Verify(Expression`1 expression, Func`1 times)
at MyProject.UnitTests.When_Something_Expect_Something()
Code language: JavaScript (javascript)
This is because logging implemented in .NET heavily relies on extension methods.
Solution and a working example
Since we cannot mock extension methods, I’d accept the tradeoff where we execute the real extension methods, but mock the object they are operating on. Here’s a working example:
using Microsoft.Extensions.Logging;
using Moq;
namespace MyTestProject;
public class SystemUnderTest
{
public SystemUnderTest(ILogger logger)
{
logger.LogError("Some log message");
}
}
public class Tests // assuming NUnit is used for unit testing
{
// Use with most recent version of Moq! With older versions, you might see unexpected behaviors.
[Test]
public void When_ObjectIsConstructed_Expect_NoErrorsLogged()
{
// Arrange
var loggerMock = new Mock<ILogger>(MockBehavior.Strict);
loggerMock.Setup(x => x.Log(
LogLevel.Error,
It.IsAny<EventId>(),
It.IsAny<It.IsAnyType>(),
It.IsAny<Exception>(),
It.IsAny<Func<It.IsAnyType, Exception?, string>>()
)
);
// Act
var sut = new SystemUnderTest(loggerMock.Object);
// Assert
// We can inspect invocations and get logged messages
var loggedErrorMessages = loggerMock.Invocations
.Where(x => (LogLevel)x.Arguments[0] == LogLevel.Error)
.Select(x => x.Arguments[2].ToString());
// ... or verify that a method was/was not called
loggerMock.Verify(
m => m.Log(
LogLevel.Error,
It.IsAny<EventId>(),
It.IsAny<It.IsAnyType>(),
It.IsAny<Exception>(),
It.IsAny<Func<It.IsAnyType, Exception?, string>>()),
Times.Never,
"Expected no errors would be written to ILogger, but found some"
);
}
}
Code language: C# (cs)
If you want to look for alternative solutions, here’s a good blogpost that shows more options on how to unit test ILogger<T>
.
Have fun 🙂