Purview.Logging.SourceGenerator.VS2019 0.9.3-prerelease

Purview Logging Source Generator

.NET Logging Source Generator, used for generating LoggerMessage-based High Performance logging from a custom interface.

What problem does this solve?

Creating readable, performant, testable logging with minimum effort.

The interface-based approach has a few key benefits:

• better testing through the use of mocks and assertions in your tests
• interfaces and their methods are also more readable than LogXXX and strings.
• natively supports DI.

Turns this:

_logger.LogInformation("Received A Request To Process {State}", e.SomeData);

into:

_logger.ReceivedRequest(e.SomeData);

Quick demo:

Define the interface:

public interface IProcessingServiceLogs
{
  IDisposable BeginProcessing(Guid contextId);

  void OperationPart1(string aStringParam);

  void OperationPart2(int anIntParam);

  [LogEvent(Level = LogLevel.Trace)]
  void OperationPart3(SomeData aComplexTypeParam);

  void CompletedProcessing(TimeSpan duration);

  [LogEvent(Level = LogLevel.Warning)]
  void MissingPayload(string name);
}

Create an interface (public or internal). Log interfaces must end with Log, Logs or Logger (case-sensitive) to be picked up by the source generator.

Notice here we're also using IDisposable for scoped-supported logging.

Register with DI

services.AddLog<IProcessingServiceLogs>() // this is an auto-generated extension method.

...Log!

sealed class ProcessingService
{
  readonly IProcessingServiceLogs _logs;

  public ProcessingService(IProcessingServiceLogs logs)
  {
    _logs = logs;
  }

  public void Process(Guid contextId, SomeData someData)
  {
    var sw = Stopwatch.StartNew();
    // Note here we're using the scoped based log event,
    // so all other logs will contain the contextId. 
    using (_logs.BeginProcessing(contextId))
    {
      if (string.IsNullOrWhiteSpace(someData.Payload))
        _logs.MissingPayload(nameof(someData.Payload));
      else
        _logs.OperationPart1(someData.Payload);
        
      if (someData.ACount == null)
        _logs.MissingPayload(nameof(someData.ACount));
      else
        _logs.OperationPart2(someData.ACount.Value);
        
      _logs.OperationPart3(someData);
      
      sw.Stop();
      
      // Super-quick elapsed time...!
      _logs.CompletedProcessing(sw.Elapsed);
    }
  }
}

How does testing work?

Full example is in the DemoService.UnitTests project, this is just the abridged version.

It uses the excellent xunit and NSubstitute.

[Fact]
public void Process_WhenProcessIsCalled_LogsBeginProcessingWithContext()
{
  // Arrange
  Guid contextId = Guid.NewGuid();

  IProcessingServiceLogs logs = CreateLogs();
  ProcessingService processingService = CreateProcessingService(logs: logs);
  SomeData someData = new();

  // Act
  processingService.Process(contextId, someData);

  // Assert
  logs
    .Received(1)
    .BeginProcessing(contextId: Arg.Is(contextId));
}

static ProcessingService CreateProcessingService(IProcessingServiceLogs? logs = null)
  => new(logs ?? CreateLogs());

static IProcessingServiceLogs CreateLogs()
  => Substitute.For<IProcessingServiceLogs>();

Reference the NuGet package

Reference the appropriate NuGet package in your CSPROJ file:

<ItemGroup>
  
  <PackageReference Include="Purview.Logging.SourceGenerator" Version="0.9.3-prerelease" />
  
  <PackageReference Include="Purview.Logging.SourceGenerator.VS2019" Version="0.9.3-prerelease" />
</ItemGroup>

Found an issue using VS2019/ .NET 5 SDK that requires a different build of the generator. You may have better luck, but if you encounter issues with Microsoft.CodeAnalysis.CSharp version 4 missing then using the VS2019 version.

Currently you must have the Microsoft.Extensions.DepdencyInjection and Microsoft.Extensions.Logging (version 5 or higher) packages installed along with the Purview.Logging.SourceGenerator package in your target project.

Log Event Configuration

By default each assembly where a logging interface is defined get two attributes generated that can be used to control the log event:

1. DefaultLogLevelAttribute - use on an interface to control the default log level for all events on that interface, or as an assembly attribute to control the default for all log events within an assembly. If declared on both, the one on the interface takes precedence.
2. LogEventAttributte - use to configure individual log events, including their Event Id, Event Name, Log Level and Message Template. If the level is specified, this will overwrite any defined by the DefaultLogLevelAttribute.

If no log level is defined (via the LogEventAttribute) and the method contains an Exception parameter, the level is automatically set to Error regardless of other defaults.

The exception is also passed to the Exception parameter of the Define method from the LoggerMessage class.

Extensions

The generated classes are partial, and match the interfaces accessibility modifier (public or internal), their name is the interface name, with the I removed and Core suffixed to the end - simply as a means of preventing clashes.

It does mean you can extend the class if you really need too:

public interface IImportantLogger {  }	// Your interface.

public partial class ImportantLoggerCore : IImportantLogger {} // Generated logger.

partial class ImportantLoggerCore // Mark your class as file and give it the same name...
{
  public void MyAdditionalMethod()
  {
    // ... 
  }
}

Performance

Using BenchmarkDotNet I've tested the following examples where we compare:

• Direct calls toILogger<T>
• LoggerMessage.Define via extension methods
• the interface-based source generation approach

Each test is setup in the following way:

• Has it's own IServiceProvider and ILoggerFactory to generate ILoggers.
• Logging level is set to Trace.
• Benchmarking is setup for the following:
  • Iterations: 1, 10, 100
  • Frameworks: net462, net472, net48, netcoreapp3.1, net5.0, net6.0
• Each iteration calls a scoped log event wrapping calls to log events for each level - Trace through to Critical.

E.g.

// This is direct ILogger approach.
using (Logger.BeginScope("TestStart => Started: {Started}", DateTimeOffset.UtcNow))
{
  Logger.LogTrace("TestTrace: {StringParam}, {IntParam}", "A Trace Parameter", 1);
  Logger.LogDebug("TestDebug: {StringParam}, {IntParam}", "A Debug Parameter", 11);
  Logger.LogInformation("LogInformation: {StringParam}, {IntParam}", "A Information Parameter", 111);
  Logger.LogWarning("LogWarning: {StringParam}, {IntParam}", "A Warning Parameter", 1111);
  Logger.LogError("LogError: {StringParam}, {IntParam}", "A Error Parameter", 11111);
  Logger.LogCritical("LogCritical: {StringParam}, {IntParam}", "A Critical Parameter", 111111);
}

BenchmarkDotNet Results

It appears as though the interface approach is nearly always as fast (or faster depending on the runtime) than the extension method approach, and certainly always faster than directly calling ILogger.

This project is available in the repo as the LoggingBenchmark project.

BenchmarkDotNet=v0.13.1, OS=Windows 10.0.22000
Intel Core i9-10900KF CPU 3.70GHz, 1 CPU, 20 logical and 10 physical cores
  [Host]               : .NET Framework 4.8 (4.8.4420.0), X64 RyuJIT
  .NET 5.0             : .NET 5.0.13 (5.0.1321.56516), X64 RyuJIT
  .NET 6.0             : .NET 6.0.1 (6.0.121.56705), X64 RyuJIT
  .NET Framework 4.6.2 : .NET Framework 4.8 (4.8.4420.0), X64 RyuJIT
  .NET Framework 4.7.2 : .NET Framework 4.8 (4.8.4420.0), X64 RyuJIT
  .NET Framework 4.8   : .NET Framework 4.8 (4.8.4420.0), X64 RyuJIT

Notes

This project is very early days - code is pretty messy at the moment, and it doesn't have much in the way of testing currently. All this is in-part because Source Generators are incredibly hard to debug and test in their current state. As I get time, I'll improve the codebase and testability of the whole project.

There is a demo project called LoggerTest. It's a bit of a mish-mash at the moment! The DemoService project is nothing more than a few classes and interface to demo how to test the logging interfaces.

The history of this project was a little interesting, I've been doing this for years, but using C# generated at runtime and creating a dynamic assembly to enable this behaviour. Using Source Generators was a natural step forward.

Unsupported

Currently unsupported are logging interfaces nested in classes, i.e.:

sealed class ClassWithNestedLogInterface
{
  interface INestedLogger
  {
    void Test();
  }
}