Defining custom logging messages with LoggerMessage.Define in ASP.NET Core

https://andrewlock.net/defining-custom-logging-messages-with-loggermessage-define-in-asp-net-core/

One of the nice features introduced in ASP.NET Core is the universal logging infrastructure. In this post I take a look at one of the helper methods in the ASP.NET Core logging library, and how you can use it to efficiently log messages in your libraries.

Before we get into it, I'll give a quick overview of the ASP.NET Core logging infrastructure. Fell free to skip down to the section on helper methods if you already know the basics of how it works.

Logging overview

The logging infrastructure is exposed in the form of the ILogger<T> and ILoggerFactory interfaces, which you can inject into your services using dependency injection to log messages in a number of ways. For example, in the following ProductController, we log a message when the View action is invoked.

public class ProductController : Controller
{
    private readonly ILogger _logger;

    public ProductController(ILoggerFactory loggerFactory)
    {
        _logger = loggerFactory.CreateLogger<ProductController>();
    }

    public IActionResult View(int id)
    {
        _logger.LogDebug("View Product called with id {Id}", id);
        return View();
    }
}

The ILogger can log messages at a number of different levels given by LogLevel:

public enum LogLevel
{
    Trace = 0,
    Debug = 1,
    Information = 2,
    Warning = 3,
    Error = 4,
    Critical = 5,
}

The final aspect to the logging infrastructure are logging providers. These are the "sinks" that the logs are actually written to. You can plug in multiple providers, and write logs to a variety of different locations, for example the console, to a file, to Serilog etc.

One of the nice things about the logging infrastructure, and the ubiquitous use of DI in the ASP.NET Core libraries is that these same interfaces and classes are used throughout the libraries themselves, as well as in your application.

Controlling the logs produced by different categories

When creating a logger with CreateLogger<T>, the type name you pass in is used to create a category for the logs. At the application level, you can choose which LogLevels are actually output for a given category.

For example, you could specify that by default, Debug or higher level logs are written to providers, but for logs written by services in the Microsoft namespace, only logs of at least Warning level or above are written.

With this approach you can control the amount of logging produced by the various libraries in your application, increasing logging levels for only those areas that need them.

For example, the following screenshot shows the logs generated by default in an MVC application when we first hit the home page:

That's a lot of logs! And notice that most of them are coming from internal components, from classes in the Microsoft namespace. It's basically just noise in this case. We can filter out Warning logs in the Microsoft namespace, but keep other logs at the Debug level:

With the default ASP.NET Core 1.X template, all you need to do is change the appsettings.json file, and set the loglevels to Warning as appropriate:

{
  "Logging": {
    "IncludeScopes": false,
    "LogLevel": {
      "Default": "Debug",
      "System": "Warning",
      "Microsoft": "Warning"
    }
  }
}

Note, in ASP.NET Core 1.X, filtering is a little bit of an afterthought. Some logging providers, such as the Console provider let you specify how to filter the categories. Alternatively, you can apply filters to all providers together using the WithFilter method. The logging in ASP.NET Core 2.0 will likely tidy up this approach - it is due to be updated in preview 2, so I won't dwell on it here.

Filtering considerations

It's a good idea to instrument your code with as many log messages are useful, and you can filter out the most verbose Trace and Debug log levels. These filtering capabilities are a really useful way of cutting through the cruft, but there's one particular downside.

If you add thousands of logging statements, that will inevitably start having a performance impact on your libraries, simply by the virtue of the fact you're running more code. One solution to this is to check whether the particular log level is enabled for the current logger, before trying to write to it. For example:

public class ProductController : Controller
{
    public IActionResult Index()
    {
        if(_logger.IsEnabled(LogLevel.Debug))
        {
            _logger.LogDebug("Calling HomeController.Index");
        }
        return View();
    }
}

That's a bit of a pain to have to do every time you write a log though right? Luckily ASP.NET Core comes with a helper class, LoggerMessage to make using this pattern easier.

Creating logging delegates with the LoggerMessage Helper

The static LoggerMessage class is found in the Microsoft.Extensions.Logging.Abstractions package, and contains a number of static, generic Define methods that return an Action<> which in turn can be used to create strongly-typed logging extensions. That probably all sounds a bit confusing so lets break it down from the top.

The strongly-typed logging extension methods

We'll start with the logging code we want to use in our application. In this really simple example, we're just going to log the time that the HomeController.Index action method executes:

public class HomeController : Controller
{
    public IActionResult Index()
    {
        _logger.HomeControllerIndexExecuting(DateTimeOffset.Now);
        return View();
    }
}

The HomeControllerIndexExecuting method is a custom extension method that takes a DateTimeOffsetparameter. We can define it as follows:

internal static class LoggerExtensions
{
    private static Action<ILogger, DateTimeOffset, Exception> _homeControllerIndexExecuting;

    static LoggerExtensions()
    {
        _homeControllerIndexExecuting = LoggerMessage.Define<DateTimeOffset>(
            logLevel: LogLevel.Debug,
            eventId: 1,
            formatString: "Executing 'Index' action at '{StartTime}'");
    }

    public static void HomeControllerIndexExecuting(
        this ILogger logger, DateTimeOffset executeTime)
    {
        _homeControllerIndexExecuting(logger, executeTime, null);
    }
}

The HomeControllerIndexExecuting method is an ILogger extension method that invokes a static Actionfield on our static LoggerExtensions method. The _homeControllerIndexExecuting field is initialised using the ASP.NET Core LoggerMessage.Define method, by providing a logLevel, an eventId and the formatString to use to create the log.

That probably seems like a lot of effort right? Why not just call _logger.LogDebug() directly in the HomeControllerIndexExecuting extension method?

Remember, our goal was to improve performance by only logging messages for unfiltered categories, without having to explicitly write: if(_logger.IsEnabled(LogLevel.Debug). The answer lies in the LoggerMessage.Define<T> method.

The LoggerHelper.Define method

The purpose of the static LoggerMessage.Define<T> method is three-fold:

1. Encapsulate the if statement to allow performant logging
2. Enforce the correct strongly-typed parameters are passed when logging the message
3. Ensure the log message contains the correct number of placeholders for parameters

This post is long enough, so I won't go into to much detail, but in summary, this gives you an idea of what the method looks like:

public static class LoggerMessage
{
    public static Action<ILogger, T1, Exception> Define<T1>(
        LogLevel logLevel, EventId eventId, string formatString)
    {
        var formatter = CreateLogValuesFormatter(
            formatString, expectedNamedParameterCount: 1);

        return (logger, arg1, exception) =>
        {
            if (logger.IsEnabled(logLevel))
            {
                logger.Log(logLevel, eventId, new LogValues<T1>(formatter, arg1), exception, LogValues<T1>.Callback);
            }
        };
    }
}

First, this method performs a check that the provided format string, ("Executing 'Index' action at '{StartTime}'") contains the correct number of named parameters. Then, it returns an action method with the necessary number of generic parameters, including the if(logger.IsEnabled) clause. There are multiple overloads of the Define method, that take 0-6 generic parameters, depending on the number you need for your custom logging message.

If you want to see the details, including how the LogValues<> class works, check out the source code on GitHub.

Summary

If you take one thing away from the post, consider the way you log messages in your own application or libraries. Consider creating a static LoggerExtensions class, using LoggerMessage.Define to create a set of static fields, and adding strongly typed extension methods like HomeControllerIndexExecuting using the static Action<> fields.

If you want to see the logger messages in action, check out the sample app in the logging repo, or take a look at the ImageSharp library, which puts them to good effect.