Using Source-Generated Logging

/ Identity Server, Logging

🧹Housekeeping – Cleaning Up My Source Code

Keeping source code tidy and well organised is crucial for maintaining readability and ease of maintenance, especially as projects grow in size and complexity. As I continue to build up my Identity Provider and its various features, I find that I can occasionally come across missplellings and other typo’s. After all, people do on the odd occasion, make mistakes.

One area of focus I want to start with, is my logging strategy. At the moment, I have a mishmash of calls to Log.Debug(...) and its other variants. These all have varying levels of descriptiveness and inconsistent log level. I want to fix that by simplifying the logger calls and consolidating them into a common library which will make organising and updating them later, much more palatable long term. Que Source-Generated Logging.

🤔What is Source-Generated Logging?

Source-generated logging is a technique where log messages are generated at compile time rather than runtime. This approach leverages source generators to create logging code automatically, making the logging process more efficient and maintainable. A few other benefits are:

  • Improving performance by avoiding unnecessary string allocations when the logging level is disabled.
  • Compile-time safety by checking for missing placeholders.
  • Consistency in the log messages.

A quick read through the Microsoft Documentation gives us a few great examples to work from. For example (below), we build up a partial class with a partial method that returns void. We then decorate this with the logger message we want.

public static partial class Log
{
    [LoggerMessage(
        EventId = 0,
        Level = LogLevel.Critical,
        Message = "Could not open socket to `{HostName}`")]
    public static partial void CouldNotOpenSocket(
        ILogger logger, string hostName);
}

We are then able to call this partial method in code as an extension over our Dependency Injected instance of ILogger.

_logger.CouldNotOpenSocket("SomeHostName");

🚦Picking Somewhere to Start

There are a few things I need to decide, like which Log calls to replace, and where to put the new logger code. I’ll start off by finding somewhere to put the extensions, which will go into a convenient “Common” library project I already have as part of my solution.

I already have an “Extensions” folder so that looks like the most logical place to put ILogger extensions. My namespaces follow a convention of being named for the folders they sit in, so naturally we’re using Project.Common.Extensions.Logging – here’s what I scaffolded so far.

using Microsoft.Extensions.Logging;

namespace Project.Common.Extensions.Logging;

public static partial class LoggingExtensions
{
    // TODO: Add some logging extensions.
}

Now I have somewhere to put the new extensions, I need to start replacing the existing code and migrating it to this extensions file.

🔍Finding and Replacing Old Code

In an earlier article, I implemented ICustomAuthorizeRequestValidator as part of my Conditional Access strategy. I included some logging there to help with debugging and it’s as good a place to start as any. I won’t include the entire implementation, just enough to demonstrate the effect I’m after. Note the egregious injection and none-use of ILogger here in favour of plain old Log – not great 🥲

public class CustomAuthorizeEndpointValidator(
    ILogger<CustomAuthorizeEndpointValidator> logger,
    IProfileService profileService) : ICustomAuthorizeRequestValidator
{
    private readonly IProfileService _profileService = profileService;
    private readonly ILogger<CustomAuthorizeEndpointValidator> _logger = logger;

    public Task ValidateAsync(CustomAuthorizeRequestValidationContext context)
    {
        Log.Information(messageTemplate: "Starting custom Authorize Endpoint validation");

        bool hasRequiredClaim = false;

        // If the required role wasn't found, we raise an error.
        if (!hasRequiredClaim)
        {
            Log.Warning(messageTemplate: "Authorization rejected because of missing application permissions");

            context.Result.IsError = true;
            context.Result.Error = "missing_basic_access";
            context.Result.ErrorDescription = "User doesn't have permission to access the specified client.";
        }

        return Task.CompletedTask;
    }
}

There are two places where I want to factor out the call to Log and move the logging detail. 

Log.Information(messageTemplate: "Starting custom Authorize Endpoint validation");
Log.Warning(messageTemplate: "Authorization rejected because of missing application permissions");

I’ll copy these as comments into the new extensions file as reference while I’m writing the partial methods.

using Microsoft.Extensions.Logging;

namespace Project.Common.Extensions.Logging;

public static partial class LoggingExtensions
{
    // Log.Information(messageTemplate: "Starting custom Authorize Endpoint validation");

    // Log.Warning(messageTemplate: "Authorization rejected because of missing application permissions");

}

Following the source documentation as a guide, I’ll write out the extension methods. Starting with the Log.Information

[LoggerMessage(eventId: 1001, LogLevel.Information, message: "Handling custom authorize request validation", EventName = "HandleCustomAuthorizeRequestValidation")]
public static partial void HandlingCustomAuthorizeRequestValidation(this ILogger logger);

I’ve updated the message, set the event name and given it an arbitrary event identifier. I’ll repeat for the rejection message and replace the original lines of code with the new extension methods.

using Microsoft.Extensions.Logging;

namespace Project.Common.Extensions.Logging;

public static partial class LoggingExtensions
{
    [LoggerMessage(eventId: 1001, LogLevel.Debug, message: "Handling custom authorize request validation", EventName = "HandleCustomAuthorizeRequestValidation")]
    public static partial void HandlingCustomAuthorizeRequestValidation(this ILogger logger);

    [LoggerMessage(eventId: 1002, LogLevel.Warning, message: "Authorization rejected because of missing application permissions", EventName = "AuthorizationRejected")]
    public static partial void AuthorizationRejected(this ILogger logger);
}

🏁Finishing Up

I’m now making use of the previously ignored ILogger instance and using short, descriptive method names that are maintained in a single easy to manage location. Much better! Time to go hunting for the rest.

public class CustomAuthorizeEndpointValidator(
    ILogger<CustomAuthorizeEndpointValidator> logger,
    IProfileService profileService) : ICustomAuthorizeRequestValidator
{
    private readonly IProfileService _profileService = profileService;
    private readonly ILogger<CustomAuthorizeEndpointValidator> _logger = logger;

    public Task ValidateAsync(CustomAuthorizeRequestValidationContext context)
    {
        _logger.HandlingCustomAuthorizeRequestValidation();

        bool hasRequiredClaim = false;

        // If the required role wasn't found, we raise an error.
        if (!hasRequiredClaim)
        {
            _logger.AuthorizationRejected();

            context.Result.IsError = true;
            context.Result.Error = "missing_basic_access";
            context.Result.ErrorDescription = "User doesn't have permission to access the specified client.";
        }

        return Task.CompletedTask;
    }
}
Scroll to Top