Unit Testing with ILogger<T>

转载文章: Unit Testing with ILogger

An effective logging system is essential for application monitoring and analysis. .NET Core supports a logging API that works with a variety of built-in and third-party logging providers, such as the Console provider, the Azure Application Insights provider, Serilog, elma.io, and so on.
In order to create logs, we need to use an ILogger object, which is readily accessible in our applications. (1) In a web application or a hosted service, we can get an ILogger object from the native .NET Core dependency injection (DI) system. (2) In a non-host console application, we can use the LoggerFactory to create an ILogger object.
Because ILogger objects are frequently used in controllers and service classes, we cannot avoid them in unit tests. In this post, we will go over some common ways to work with ILogger objects in unit testing. The full project can be found in this repository.

Table of Contents

1. Replace ILogger with NullLogger
2. Create a Real ILogger that Logs to Console
3. Mock an ILogger Object

Let’s consider a service class CalculationService that has a dependency on an ILogger object. We are going to test the contrived AddTwoPositiveNumbers(int a, int b) method.

public class CalculationService : ICalculationService
{
    private readonly ILogger<CalculationService> _logger;

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

    public int AddTwoPositiveNumbers(int a, int b)
    {
        if (a <= 0 || b <= 0)
        {
            _logger.LogError("Arguments should be both positive.");
            return 0;
        }
        _logger.LogInformation($"Adding {a} and {b}");
        return a + b;
    }
}

1. Replace ILogger with NullLogger
   The NullLogger implements ILogger and it is a minimalistic logger that does nothing. In other words, it doesn’t log messages to any place and it swallows exceptions. It is worth mentioning that both the ILogger interface and the NullLogger class are included in the NuGet package Microsoft.Extensions.Logging.Abstractions.
   In a lot of cases, the logging system doesn’t participate in business logic or business rules. Therefore, we don’t need to care much about what the ILogger does in the system under test (SUT). Then in these scenarios, the NullLogger object is a perfect replacement of the ILogger object in unit tests. The following code snippet shows an example.

[TestMethod]
public void TestWithNullLogger()
{
    var svc = new CalculationService(new NullLogger<CalculationService>());
    var result = svc.AddTwoPositiveNumbers(1, 2);
    Assert.AreEqual(3, result);
}

In the unit test above, we substitute a new NullLogger() (or NullLogger.Instance) object to the service constructor, which indicates that the test has nothing to do with the logging system. I would say that it is acceptable in most cases. Thanks to .NET library. The NullLogger implementation saves us a lot of overhead.

2. Create a Real ILogger that Logs to Console
   In some unit tests, we might want to take a peek at the message which the ILogger object outputs. Particularly, we would like to log messages to Console so that we can analyze the result or save a copy of the test report during the Continuous Integration process.
   We have two ways to get a logger: (1) create a logger through a logger factory and (2) get a logger from the DI system. In either way, the underlying mechanism is using a logger factory, which adds a Console provider, to create a logger.
   During unit testing, you might find that the console output does not always flush out, because logging in .NET Core runs in a separate thread. In order to force the output stream to flush to console, we need to use the tricks of calling Console.WriteLine() in the unit test or disposing the logger factory.
   The following unit test shows how to instantiate a logger factory by calling var loggerFactory = new LoggerFactory().AddConsole(). Note that, starting from .NET Core 3.0, we need to update the instantiation method to be var loggerFactory = LoggerFactory.Create(builder => builder.AddConsole()). In the unit test, the using clause is necessary to flush the Console output, which disposes the logger factory.

[TestMethod]
public void TestWithConsoleLogger()
{
     using var loggerFactory = LoggerFactory.Create(builder => builder.AddConsole());
     var logger = loggerFactory.CreateLogger<CalculationService>();
     var svc = new CalculationService(logger);
     var result = svc.AddTwoPositiveNumbers(1, 2);
     Assert.AreEqual(3, result);

     // If you are using .NET Core 2.1.
     //using (var loggerFactory = new LoggerFactory().AddConsole())   // Need to use "using" in order to flush Console output
     //{
     //    var logger = loggerFactory.CreateLogger<CalculationService>();
     //    var svc = new CalculationService(logger);
     //    var result = svc.AddTwoPositiveNumbers(1, 2);
     //    Assert.AreEqual(3, result);
     //}
}

We need to install a NuGet package Microsoft.Extensions.Logging.Console in order to work with this method. The following screenshot shows the unit test result and the Console output.

As mentioned above, the other way to get a logger is through the DI system, in which we first build service providers, then get the logger factory, then create a logger. Please take a look at the code snippet below.

[TestMethod]
public void TestWithDependencyInjectionLogger()
{
    var services = new ServiceCollection()
        .AddLogging(config => config.AddConsole())      // can add any logger(s)
        .BuildServiceProvider();
    using (var loggerFactory = services.GetRequiredService<ILoggerFactory>())
    {
        var svc = new CalculationService(loggerFactory.CreateLogger<CalculationService>());
        var result = svc.AddTwoPositiveNumbers(1, 2);
        Assert.AreEqual(3, result);
    }
}

As expected, we can view the Console output in the Test Explorer, as shown in the screenshot below.

Both the methods above work very well and we can use either one based on our use cases.
Note that we should be careful about Console logging in the actual production application, because Console logging might deteriorate the application performance. Here, for temporary usage or unit testing, Console output is still useful.

3. Mock an ILogger Object
   Occasionally, we may come across scenarios in which logging is a part of business requirements and we need to test and verify logging is actually working. In these kinds of scenarios, we can borrow Moq (NuGet link) to create a stub.
   You will quickly notice that logger.LogInformation(), logger.LogError(), and other methods are extension methods of the ILogger type. We certainly can do something fancy to test whether the calls actually hit the Log method. However, we might ask ourselves do we really need to test down to the infrastructure level? Let’s face the trade-off.
   To mock an ILogger object, we can use Moq library to instantiate a new Mock<ILogger>() object. Make sure you have installed the latest Moq package (v4.15.1 as of Nov. 16, 2020, which contains an update to support “nested” type matchers). Then the unit test is straightforward. We can verify the logger is called at a specific log level and with a specific message. The following code snippet shows an example unit test, which verifies an Information level message, and an error level message.

[TestMethod]
public void TestWithMockLogger()
{
    var loggerMock = new Mock<ILogger<CalculationService>>();
    var svc = new CalculationService(loggerMock.Object);

    var result = svc.AddTwoPositiveNumbers(1, 2);
    Assert.AreEqual(3, result);
    loggerMock.Verify(
        m => m.Log(
            LogLevel.Information,
            It.IsAny<EventId>(),
            It.Is<It.IsAnyType>((v, _) => v.ToString().Contains("Adding 1 and 2")),
            null,
            It.IsAny<Func<It.IsAnyType, Exception, string>>()),
        Times.Once);

    result = svc.AddTwoPositiveNumbers(-1, 1);
    Assert.AreEqual(0, result);
    loggerMock.Verify(
        m => m.Log(
            LogLevel.Error,
            It.IsAny<EventId>(),
            It.Is<It.IsAnyType>((v, _) => v.ToString().Contains("Arguments should be both positive.")),
            null,
            It.IsAny<Func<It.IsAnyType, Exception, string>>()),
        Times.Once);
}

That’s all for today. If you want to checkout the complete project, you can find it here. Thanks for reading.