Logging with Source Generators in .NET

19 Feb, 2023

.NET 6 added a new feature called Source Generators, allowing projects to generate code at compile time. This opens up a whole load of cool new opportunities for libraries to implement new functionality or improve existing functionality by eliminating boilerplate code.

One such library is Microsoft.Extensions.Logging, the standard logging library supplied by many of the built in templates for apps like web apps and worker apps.

The logging library supports compile-time logging source generation via the LoggerMessage attribute. It generates code which includes calls to LoggerMessage.Define and includes checks for whether the log level is enabled or not (though this check can be omitted by passing a parameter to the attribute).

So, what does this look like?

The definition for logging methods is pretty simple:

using Microsoft.Extensions.Logging;


internal static partial class Logging
{
    [LoggerMessage(
        EventId = 0,
        EventName = "Main",
        Level = LogLevel.Information,
        Message = "Program is starting"
    )]
    internal static partial void ProgramStarting(ILogger logger);

    [LoggerMessage(
        EventId = 1,
        EventName = "Main",
        Level = LogLevel.Error,
        Message = "Error dividing by divisor: {divisor}"
    )]
    internal static partial void DivisionError(ILogger logger, Exception ex, decimal divisor);
}

So far, pretty simple. You define a static partial class to contain your logging methods, which are in turn defined as static partial void. You then decorate each logging method with the LoggerMessage attribute and provide an event ID, an optional event name, a log level and a message. Your methods can take parameters to be substituted within the log message, along with an exception to be logged for error logging purposes.

At compile time, this then generates code like the following:

partial class Logging
{
    [global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "7.0.7.1805")]
    private static readonly global::System.Action<global::Microsoft.Extensions.Logging.ILogger, global::System.Exception?> __ProgramStartingCallback =
        global::Microsoft.Extensions.Logging.LoggerMessage.Define(global::Microsoft.Extensions.Logging.LogLevel.Information, new global::Microsoft.Extensions.Logging.EventId(0, "Main"), "Program is starting", new global::Microsoft.Extensions.Logging.LogDefineOptions() { SkipEnabledCheck = true });

    [global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "7.0.7.1805")]
    internal static partial void ProgramStarting(global::Microsoft.Extensions.Logging.ILogger logger)
    {
        if (logger.IsEnabled(global::Microsoft.Extensions.Logging.LogLevel.Information))
        {
            __ProgramStartingCallback(logger, null);
        }
    }
    [global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "7.0.7.1805")]
    private static readonly global::System.Action<global::Microsoft.Extensions.Logging.ILogger, global::System.Decimal, global::System.Exception?> __DivisionErrorCallback =
        global::Microsoft.Extensions.Logging.LoggerMessage.Define<global::System.Decimal>(global::Microsoft.Extensions.Logging.LogLevel.Error, new global::Microsoft.Extensions.Logging.EventId(1, "Main"), "Error dividing by divisor: {divisor}", new global::Microsoft.Extensions.Logging.LogDefineOptions() { SkipEnabledCheck = true });

    [global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "7.0.7.1805")]
    internal static partial void DivisionError(global::Microsoft.Extensions.Logging.ILogger logger, global::System.Exception ex, global::System.Decimal divisor)
    {
        if (logger.IsEnabled(global::Microsoft.Extensions.Logging.LogLevel.Error))
        {
            __DivisionErrorCallback(logger, divisor, ex);
        }
    }
}

Usage is simple too:

using ILoggerFactory loggerFactory = LoggerFactory.Create(b =>
{
    b.AddConsole();
});

ILogger logger = loggerFactory.CreateLogger<Program>();

Logging.ProgramStarting(logger);

// some time later when an error occurs...

Logging.DivisionError(logger, ex, divisor);

So, what are the advantages?

There are a couple of advantages to this as I see them:

Your log message parameters are presence checked at compile time. This means if you define a parameter in your logger message but forget to pass it within the method definition, the project will fail to compile with an error such as: error SYSLIB1014: Template 'divisor' is not provided as argument to the logging method.
In addition to the above, parameters are checked to ensure that parameters are named the same in both the logger message definition and the method parameter. Failure to do so also results in a compile error such as: SYSLIB1015: Argument 'd' is not referenced from the logging message.
As message parameter names are checked at compile time and used by name, you can provide parameters in the method signature in any order. This means that if you decide to change the log message in the future to add a parameter, you can simply add it to the end of the method signature rather.
Provides compile warnings for duplicated event IDs. If you define two log methods with the same event ID you get a compile warning such as: warning SYSLIB1006: Multiple logging methods are using event id 0 in class Logging.

#C Sharp