Logs are a key element for diagnosing, monitoring or auditing the application’s behaviour, so if you are either a library author or you are developing an application, it is important to ensure that the right logs are generated.

Would it be nice if there was an easy solution to write tests for it? Let’s start a journey through the best approaches to tests logs when using Microsoft.Extensions.Logging.

If you don’t want to follow along and you are just looking for a ready to use solution, please skip to the Introducing MELT, a Testing library for Microsoft.Extensions.Logging section.

Microsoft.Extensions.Logging is the defacto standard abstraction in .NET (not only on .NET Core) to generate logs from either libraries or applicaitons, since its introdution alongside the first version of ASP.NET Core.

Usually, with it, you inject an ILogger<T> and then leverage the simplified extension methods to log, like:

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

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

  public void DoSomething()
  {
    _logger.LogInformation("The answer is {number}", 42);
  }
}

This leverage the extension method:

public static void LogInformation(this ILogger logger, string message, params object[] args)

The extension methods are much cleaner to use, as you can simply provide a message template with a list of arguments, similar to a string.Format(), compared to the Log method provided by the ILogger<T> interface, which even requires to provide in each call a formatter to format the state (which in this example would be our message template and its list of arguments).

public interface ILogger
{
    void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter);

    // ...
}

If you want to learn the best practices for logging, I would recommend reading Logging in .NET Core and ASP.NET Core.

What are the implications of this design of the library for testing the emitted logs?

It is tempting to mock an ILogger<T> using a mocking framework that keeps track of the invocations to assert in our tests that we have correctly emitted the required logs. However, as we would have to verify the calls to the Log<TState> method, but in our code we are probably leveraging on the extensions method, we would first need to understand the implementation of these extension methods to figure out which arguments are passed in the Log<TState>() invocation. In doing so, we would be tying our tests to the implementation of the extensions method, which is an internal implementation detail of the logging library. In fact, those extension methods could change what to use as state, and updating the formatter accordingly, without affecting the generated logs, but breaking our tests if we were leveraging on this internal detail.

Let’s take a step back: what we really want to test are the generated logs, not the method’s invocations of the ILogger<T>!

So, probably, mocking an Ilogger<T> is not the best approach. Furthermore, Microsoft.Extensions.Logging has a concept of Scope to decorate the logs, allowing to push and pop scopes on a stack that will be used to decorate the logs, based on which scopes are present at any given point. If we limit ourself to assert the invocations of the methods after the execution, we would not be able to keep track of the scopes. We could create a more complex fake logger so that we could maintain a state, however, this will increase the complexity while still not testing at the right level.

So far we have also looked at the very simple case of writing a unit test. Once we move to integration tests, we would not have a single ILogger<T> anymore, but multiple ones created by an ILoggerFactory, all sharing the same stack of scopes! As you can imagine, the complexity will quickly skyrocket. 🚀

A better approach

If we want to focus on testing the outcome of the logging of our application, which means testing the generated logs without worrying about all the layers of extension methods and the implementation details of Microsoft.Extensions.Logging, we need to first understand the structure of this library so that we can find the best place to hook into.

Without getting into too many details, the Microsoft.Extensions.Logging library (MEL for friends), is made of:

• loggers (ILogger/ILogger<T>)

  The logger used to send the logs to, usually one per class instance.

• a logger factory (ILoggerFactory)

  The factory is responsible to create the loggers

• logger providers (ILoggerProvider)

  A provider defines a target for the logs and you can register multiple providers to the factory so that multiple targets can receive the logs.

When a logger is requested from the factory, the factory will request a logger from each provider, then creating a logger that wrap these multiple loggers, so to send everything to all of them.

What we need to do for our testing, is to create an ILogger that sends the data to an in-memory data structure we can then assert against. It needs to be shared across multiple loggers preserving the orders the entries are received. Furthermore, this should be not only limited to store the log entries, but also the scopes, which needs to be stored on a stack.

In fact, when BeginScope is invoked we need to enqueue the new state and return an instance that, when disposed, will pop that particular scope.

public interface ILogger
{
    IDisposable BeginScope<TState>(TState state);

    // ...
}

Please note that when using Microsoft.Extensions.Logging, it is important to remove the scopes in the opposite order they have been added, as popping out of order is not supported and can lead to unexpected consequences. The best approach is to rely on using statements to reduce the risk of mistakes.

We would also need to capture the current scope when we log an entry, so we can later check if that entry was produced inside the proper scope.

Once we have implemented our logger, we need to implement a provider that would instantiate it when requested from the factory, and the default factory will take care of the rests.

This is a great approach for our integration tests!

In unit tests, we can avoid implementing a provider and instead create a simple factory that would just return a logger, to reduce complexity. Obviously, it would be preferable to leave the logging library completely out of the picture but, for the reason described in the previous paragraphs, it would be more pain than gain. If we can isolate the implementation of the new provider and all the logic to create a factory, with or without registering the provider based on the context, then create the logger to pass to our fixture to test, we could keep our tests clean and have a ready to use solution so not to worry again about it.

Introducing MELT, a Testing library for Microsoft.Extensions.Logging

As you can guess… you are not the only software developer that wants to test logging! 😄 In fact, while developing the logging library and consuming it, the ASP.NET Core team has created Microsoft.Extensions.Logging.Testing, a library used internally in ASP.NET Core for testing the logging.

All good? Not really!

Unfortunately there is currently no plan to offer an official package for it. For this reason, I decided to create MELT, a repackaging with a sweetened API and some omissions of Microsoft.Extensions.Logging.Testing, so you can just add the MELT NuGet package to your test projects and carry on with your life. 😏

MELT is a free, open-source, testing library for the .NET Standard Microsoft Extensions Logging library. It is licensed under Apache License 2.0. Most of the code is copyrighted by the .NET Foundation as mentioned in the files headers.

The original plan was to simply re-package the existing library to make it easily available on NuGet.org. However, once I started to write some usage examples, I realized that it was a bit too powerful: having access to internal aspects of the logging gives great flexibility on testing, but makes tests a little too verbose as well as giving me the impression of not being straightforward to use without a basic understanding of the architecture of the logging library. This made perfect sense in the context where this library has been created and used, but in my opinion, it would have prevented an easy adoption out of that small circle (and I guess this is part of the reason why Microsoft deemed too costly to publish it directly).

As I didn’t want to alter the nature of the library, I started to add some extensions methods to simplify the usage in the really simples scenario, while not modifying the original library. This approach was however increasing the code complexity and, most of all, not allowing me to offer a good discovery and autocompletion experience, as the IntelliSense was overcrowded with duplicated functionalities. In version 0.3 I finally gave up 🙄 and decided to refactor the library to my liking, in the hope of providing a simpler API while keeping the flexibility to get access to all the internal state if needed. Please be aware as is not an exact replica of the Microsoft library, I could have introduced bugs in the process!

I am reasonably happy with the current shape, so I don’t plan to do more breaking changes and I aim to soon release a 1.0 version, once I have improved the documentation shown in IntelliSense. If you want to help to get to the first stable version or you have any suggestions for improvements, this is a good time!

How to write unit tests with MELT?

• Install the NuGet package MELT

  <PackageReference Include="MELT" Version="0.4.0" />
  

• Get a test logger factory

  var loggerFactory = MELTBuilder.CreateLoggerFactory();
  

• Get a logger from the factory, as usual, to pass to your fixture.

  var logger = loggerFactory.CreateLogger<Sample>();
  

Assert log entries

The logger factory exposes a property LogEntries that enumerates all the logs captured. Each entry exposes all the relevant property for a log.

For example, to test with xUnit that a single log has been emitted and it had a specific message:

var log = Assert.Single(loggerFactory.LogEntries);
Assert.Equal("The answer is 42", log.Message);

Assert scopes

The logger factory exposes a property Scopes that enumerates all the scopes captured.

For example, to test with xUnit that a single scope has been emitted and it had a specific message:

var scope = Assert.Single(loggerFactory.Scopes);
Assert.Equal("I'm in the GET scope", scope.Message);

There is also a property Scope in each log entry to have the scope captured with that entry.

Assert message format

var log = Assert.Single(loggerFactory.LogEntries);
Assert.Equal("The answer is {number}", log.Format);

Easily test log or scope properties with xUnit

• Install the NuGet package MELT.Xunit

  <PackageReference Include="MELT.Xunit" Version="0.4.0" />
  

• Use the LogValuesAssert.Contains(...) helpers. For example, to test that a single log has been emitted and it had a property number with value 42:

  var log = Assert.Single(loggerFactory.LogEntries);
  LogValuesAssert.Contains("number", 42, log.Properties);
  

And much more

You can assert against all the characteristic of a log entry: EventId, Exception, LoggerName, LogLevel, Message, Format, Properties and Scope.

Limitations

For simplicity, when log entries are generated, only the innermost scope is captured and assigned to that log entry. So, although all scopes are tracked and can be tested, in the context of a log entry only one scope can be verified, as usual scopes are not deeply nested in a single unit. If this is not enough for you, please leave a comment below or file an issue on GitHub, ideally with a use case.

But you mentioned the complexity is in writing integration tests, how will it help me?

For the integration tests you need some setup, but it is pretty straightforward and support all the different scenarios to write integration tests for ASP.NET Core.

• Install the NuGet package MELT.AspNetCore

  <PackageReference Include="MELT.AspNetCore" Version="0.4.0" />
  

• Create a test sink using MELTBuilder.CreateTestSink(...), where you can also customize the behaviour.

  For example to filter all log entries and scopes not generated by loggers consumed in the SampleWebApplication.* namespace (this filters the logger name so it assumes you are using ILogger<T> or following the default naming convention for your loggers.)

  ITestSink _sink = MELTBuilder.CreateTestSink(options => options.FilterByNamespace(nameof(SampleWebApplication)));
  

  You can also filter by logger name using FilterByTypeName<T>() or FilterByLoggerName(string name).

• Use the AddTestLogger(...) extension method to add the test logger provider to the logging builder. This can be done where you are already configuring the web host builder.

  Configure the logger using WithWebHostBuilder on the factory.

  using Microsoft.AspNetCore.Hosting;
  using Microsoft.AspNetCore.Mvc.Testing;
  // ...
  var factory = factory.WithWebHostBuilder(builder => builder.UseTestLogging(_sink));
  

  Alternatively, you can configure the logger builder in the ConfigureWebHost implementation of your custom WebApplicationFactory<T>. If you chose so, the same sink will be used by all tests using the same factory. You can clear the sink in the test constructor with Clear() if you like to have a clean state before each test, as xUnit will not run tests consuming the same fixture in parallel.

  The logger will be automatically injected with Dependency Injection.

• Alternatively, you can set it up in your custom WebApplicationFactory<TStartup>.

  using Microsoft.AspNetCore.Hosting;
  using Microsoft.AspNetCore.Mvc.Testing;
  
  public class CustomWebApplicationFactory<TStartup> : WebApplicationFactory<TStartup>
      where TStartup : class
  {
      protected override void ConfigureWebHost(IWebHostBuilder builder)
      {
          builder.UseTestLogging(options => options.FilterByNamespace(nameof(SampleWebApplication)));
          // ...
      }
  }
  

  You can then retrieve the sink to assert against using the extension method GetTestSink() on the factory.

  Please note that in this case, all tests sharing the same factory will get the same sink. You can reset it between tests with Clear() in the constructor of your xUnit tests. For example:

  public class LoggingTestWithInjectedFactory : IClassFixture<CustomWebApplicationFactory<Startup>>
  {
      private readonly CustomWebApplicationFactory<Startup> _factory;
  
      public LoggingTestWithInjectedFactory(CustomWebApplicationFactory<Startup> factory)
      {
          _factory = factory;
          // In this case the factory will be resused for all tests, so the sink will be shared as well.
          // We can clear the sink before each test execution, as xUnit will not run this tests in parallel.
          _factory.GetTestSink().Clear();
          // When running on 2.x, the server is not initialized until it is explicitly started or the first client is created.
          // So we need to use:
          // if (_factory.TryGetTestSink(out var testSink)) testSink.Clear();
      }
  }
  

Once you have set it up, the logger will be automatically injected when requested, or you can manually retrieve it from the factory when needed. You can then retrieve the log holder, called sink, from the WebApplicationFactory with GetTestSink() if you don’t have it as a field, depending on which route you followed. Form the sink you can then get the LogEntries and Scopes, and do the assertion as in the unit tests.

But I only need to write a simple test, I don’t want to use a library, not even a mocking one!

I hear you! If you are only after a simple unit test, yes you can create a really simple fake implementation of the logger, without having to worry about factories or providers. For example, you can simply capture all the log calls and store the log level and message on a list to be asserted later, relying on the fact that the logging library implements a sane default ToString() on the data structure passed to the Log() method.

You can write something like:

private class FakeLogger : ILogger<Sample>
{
    public List<(LogLevel Level, string Message)> Entries { get; } = new List<(LogLevel, string)>();

    public IDisposable BeginScope<TState>(TState state) => throw new NotImplementedException();

    public bool IsEnabled(LogLevel logLevel) => throw new NotImplementedException();

    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
    {
        // This is relying on an internal implementation detail, it will break!
        string message = state.ToString();

        Entries.Add((logLevel, message));
    }
}

However, this means relying on a source (either a blog post like this one or the actual source code) or some experimentation to know that you can use ToString() on the state to get the message. If it works in your scenario, that’s good! It’s doesn’t really matter if it will not work in every possible scenario. But will it stop working at some point if you update the logging library or get a newer version through a dependency? Probably! And if you have used this technique are you then going to update it everywhere? 😏

Oh, wait! What about exceptions? Ah, you also rely on structured logging? so you should probably assert that the template and parameters are what you expect (which could be quite important to avoid regressions if you are relying on those parameters on a dashboard).

Ok, so let’s include a bit more in our fake implementation for testing! Once we realize that the state is a list of KeyValuePair<string, object>, it’s pretty trivial.

private class FakeLogger : ILogger<Sample>
{
    public List<(LogLevel Level, string Message, IReadOnlyList<KeyValuePair<string, object>> Properties, Exception Exception)> Entries { get; } =
        new List<(LogLevel, string, IReadOnlyList<KeyValuePair<string, object>>, Exception)>();

    public IDisposable BeginScope<TState>(TState state) => throw new NotImplementedException();

    public bool IsEnabled(LogLevel logLevel) => throw new NotImplementedException();

    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
    {
        // These are relying on an internal implementation detail, they will break!
        var message = state.ToString();
        var properties = state as IReadOnlyList<KeyValuePair<string, object>>;

        Entries.Add((logLevel, message, properties, exception));
    }
}

Assertions are not hard either…. if we don’t need anything too fancy:

// Assert
var log = Assert.Single(logger.Entries);

// Assert the message rendered by a default formatter
Assert.Equal("The answer is 42", log.Message);

// Assert structured logs
var element = Assert.Single(log.Properties, x => x.Key == "number");
Assert.Equal(42, element.Value);
// or
Assert.Contains(new KeyValuePair<string, object>("number", 42), log.Properties);

// Assert Exception
var exception = Assert.IsType<ArgumentNullException>(log.Exception);
Assert.Equal("foo", exception.ParamName);

We can also get the template that was used in the log entry, if we know that is stored in the state with key {OriginalFormat} (yes, with the curly braces):

var template = Assert.Single(log.Properties, x => x.Key == "{OriginalFormat}");
Assert.Equal("The answer is {number}", template.Value);

Ah but you also use scopes, so I need to keep track of the scopes. Actually, it than requiring to keep track of which scopes were present when the log entry was added! 🤯

As you can see, the complexity will quickly skyrocket! 🚀 And we haven’t considered integration tests yet!

All in all, using a library that takes care of the different aspect of testing the logging and works for both libraries and applications doesn’t sound like a bad idea.

Add the MELT NuGet package to your test projects, or check out MELT on GitHub. Asserts your logs and file an issue or get in touch (I’m @AleFranz on Twitter) if you have any idea for improvements!

Happy logging! And happy testing!

self.about()

My name is Alessio Franceschelli. I'm a software developer based in London, UK. I work as Senior Principal Engineer for Trainline but these blog's opinions are my own.