Verify ILogger calls with Moq.ILogger

Moq is by far the most used mocking library for .NET.

It provides objects to either mimic real services implementations or to verify if they were called in a certain way by the Service Under Test.

Often teams work hard to have meaningful logs in order to help with investigations, to have the possibility to define alarms based on the content of the logs, or even to help with instrumentation. If there is a log entry that resembles as an exception, then a notification might be sent to a Teams/Slack channel, an email, or even to randomly start the alarms on your team's members' cars (joking, don't do that, you know everyone ignores that Slack channel).

There are many situations when an investigation ends up with no resolution, and with a promise to the client that the missing logging lines will soon be added. This it translates into development costs, reputation loss, and maybe most importantly having a missed opportunity to learn about the system's behavior in the production environment.

As with any added fix or feature, there has to be a test for logging too. With each test, a story is written about why the tested code was added, which were the requirements, the perceived pre-conditions, the expected outputs, and the interactions with the outside world.

Let's consider a PaymentsProcessor, an object which, with the help of a data store collaborator (PaymentsRepository) and a payments processor service (PaymentService) it can iterate through some outstanding orders and initiate the completion of the payments. There are some key requirements here:

• send all outstanding orders to the PaymentService, if anyone is failing, continue with the rest of them
• write a journal about what's happening, like the interactions with the PaymentService, the number of the processed orders, business identifiers, etc
• when the PaymentService returns errors, write a warning in the journal with the specific details, so they can be checked whenever is needed

One possible implementation might look like:

Neither good nor bad. All tests related to business requirements are already written, next is to test the logging part.

Naturally, as a Moq user, one such test could be written:

The test checks that a message related to the batch completion is sent to the logs and it contains the information about the batch size. For this, it sets up the service under test with specific mocks that simulate 100 outstanding orders with successful payments and it asserts that the logger will log the information with the required message.

The problem is, with Moq, it doesn't work. It will raise the following exception:

It is happening because all LogDebug, LogInformation, LogWarning, LogError, LogTrace, and LogCritical methods available with the ILogger interface are in fact extensions methods. Moq doesn't support verifying or setting up extensions methods because basically, these are part of static classes, which is very problematic to mock. To fix the problem, as most of these StackOverflow answers do, is to avoid Moq's features almost entirely, except setting up the interaction with ILogger.Log, which is the actual interface method used by the extensions methods.

This might work for a case or two, but when more interactions are verified, under more or less complex variations, any wrapper would become unmaintainable very soon and also not very user friendly. As a Moq user, there are some expectations regarding what lives in the Verify/Setup expressions. A Moq user would really want to see Verify(logging => logging.LogInformation("message") and not Verify(logging => logging.Log(LogLevel.Information, It.IsAny<EventId>(), It.Is<It.IsAnyType>((o, t) => string.Equals("message", o, StringComparison.InvariantCultureIgnoreCase)), or worst Verify(LogLevel.Information, .. that might be one of those one hundred handy wrappers.

To solve this problem I created Moq.ILogger. It enables the Moq's Verify API over the ILogger extensions (LogInformation, LogError, etc). For a Moq user the only change, and I think not that annoying, is she has to call VerifyLog, which comes from the Moq.ILogger package instead of Verify, which is part of Moq itself. This is because C# will prefer to resolve the bound open generic method (Moq has it) instead of the closed generic variations (ILogger.Moq one) when it comes to method resolution. Everything else remains as expected. The expression in the VerifyLog method can reference all the ILogger extensions that live in the .NET Core implementation. It can use all It.Is Moq primitives and also the Times.* arguments or even passing the failed custom messages when the tests fail.

Moq.ILogger contains also two minor, but useful features:

• ability to verify against a wildcard message, as sometimes it is interesting to check only parts of the logged message, a feature that is borrowed from the FluentAssertions for matching exceptions messages
• ability to verify against the transformed message; sometimes it is interesting to assert the message as it is in the actual logs

Given this. let's re-write the previous test with Moq.ILogger

The only change is VerifyLog is used. Moq.ILogger transforms the provided expression in the VerifyLog call into one expected by the Moq's Verify method for ILogger.Log(...), based on the .NET Core implementation. It does so by parsing the expression and creating a new one. Any Moq's constructs are available to VerifyLog.

Let's see some other examples:

This test checks that relevant information is logged for all processed orders. It ensures the right message format is used so the names of the parameters are correct and not only the final text. It makes sure relevant parameter values are passed: ordered references must contain "Reference", dates are really of a DateTime type, emails have at least an @ and transactions ids are starting with "TRX". 

And finally, there has to be a test that checks how logging is used when having errors during the payment completion. 

The set up of this test specifies that the batch has only two orders and the second one will fail during the payment completion.  The test verifies that proper logging is happening: the error is logged with a Warning level, as any car alarms are not funny, the error message is the expected one from the payment provider and the corresponding logging message contains at least the word exception and the order reference value, ie Reference 2. Here the wildcard matching feature comes to play as programmers tend to overreact with the explanations since they don't have the time to write shorter ones so they write very long ones instead.

That's pretty much it. If you want to give it a try then, you know what to do with one of these:

> Install-Package ILogger.Moq

> dotnet add package ILogger.Moq

<PackageReference Include="ILogger.Moq" Version="1.1.1" />

> paket add ILogger.Moq