Structured Logging and Interpolated Strings in C# 10

Structured logging is gaining more and more popularity in the developers' community. So it makes no surprise that Microsoft has added support for it to the Microsoft.Extensions.Logging package being the part of .Net Core/.Net 5/.Net 6. In this article I'd like to demonstrate how we can use structured logging with this package and show the idea how we can extend it using the new features of C# 10.

Initial Setup

Microsoft.Extensions.Logging is known to be a façade supporting different pluggable underlying logging providers. In this article I will use the Serilog provider and will set it up to output logs to the console in JSON format.

I will use simple console application as an example (GitHub Link). Logging configuration looks the following way:

// Serilog configuration
Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Information()
    .WriteTo.Console(new CompactJsonFormatter())
    .CreateLogger();   

// Register Serilog while creating Microsoft.Extensions.Logging.LoggerFactory
using var loggerFactory = LoggerFactory.Create(
    builder => builder.AddSerilog(dispose: true));
// Create an instance of ILogger using the factory
var logger = loggerFactory.CreateLogger();

Let's also create two records which will be used in the further examples:

public record Point(double X, double Y);

public record Segment(Point Start, Point End)
{
    public double GetLength()
    {
      var dx = Start.X - End.X;
      var dy = Start.Y - End.Y;
      return Math.Sqrt(dx * dx + dy * dy);
    }
}

Using ILogger

We will use the ILogger interface for logging. This interface provides several overloads of the Log method which take the log level as a parameter. It also provides overloads of methods Log<Level>, e.g. LogInformation, LogError, etc. All these method take the message template string and the array of arguments (params object[]) as their parameters.

For example, let's log the result of a segment length calculation:

var segment = new Segment(new (1, 2), new (4, 6));
var length = segment.GetLength();
logger.LogInformation(
    "The length of segment {@segment} is {length}.", segment, length);

The template string contains two arguments enclosed in braces: segment and length. Their values are passed to the method as the following parameters. The @ symbol before the segment argument is a part of the Message Template specification which means that Serilog must expand the argument's structure as an object. Without this symbol Serilog would just log the result of segment.ToString().

As the result we will get the following log item:

{
    "@t": "2021-11-13T19:57:31.8636016Z",
    "@mt": "The length of segment {@segment} is {length}.",
    "segment": {
        "Start": {
            "X": 1,
            "Y": 2,
            "$type": "Point"
        },
        "End": {
            "X": 4,
            "Y": 6,
            "$type": "Point"
        },
        "$type": "Segment"
    },
    "length": 5,
    "SourceContext": "Program"
}

The resulting JSON object has a property @mt containing the template string, and properties segment and length containing the arguments.

While this approach is quite easy and straightforward, it has some significant disadvantages:

• It is necessary to parse the template string at runtime, but it's a quite expensive operation. The logging infrastructure uses an internal cache of 1024 string to make this issue less significant.

• The memory is allocated for the arguments array even if the specified log level is disabled.

• Arguments of value types are boxed when being placed into the object array.

• Names of the variables are duplicated in the template string and in the method parameters.

• It is easy to forget some argument or use a wrong argument order.

.Net 6 provides a new source code generator as a better alternative without these disadvantages. We can declare a partial method taking the required parameters and mark it with the LoggerMessageAttribute as follows:

[LoggerMessage(0, LogLevel.Information, "The length of segment {segment} is {length}.")]
public static partial void LogSegmentLength(this ILogger logger, Segment segment, double length);

This approach provides the best logging performance, however it also has its own disadvantages:

• It clutters up the source code with the partial method declarations.

• It does not allow to use the @ symbol before the argument names, preventing Serilog from expanding them into JSON objects.

Adding Support for Interpolated Strings to ILogger

So, we would like to find an expressive way to write structured logs without the mentioned disadvantages. String interpolation could be a convenient way to achieve it, but it will require some additional work from us.

If we try to call a usual logging method with an interpolated string, e.g.:

logger.LogInformation($"The length of segment {segment} is {length}.");

we will get the following log record:

{
    "@t": "2021-11-13T23:40:23.1323976Z",
    "@mt": "The length of segment Segment { Start = Point { X = 1, Y = 2 }, End = Point { X = 4, Y = 6 } } is 5.",
    "SourceContext": "Program"
}

As expected, we have lost information about the arguments because C# compiler has converted our interpolated string into a simple call to String.Format.

Generally speaking, until C# 10 the compiler could transform the interpolated string to either a FormattableString instance or a simple string. FormattableString objects look almost like the thing we need to solve our problem, as they contain the format string and the argument array. Unfortunately, they still do not contain the argument names. Moreover, when the compiler chooses the method overload, it prefers one taking a string, that makes it no so convenient to use.

Luckily, C# 10 provides a new mechanism for the interpolated strings which allows us to implement the solution. We can create a special struct that acts as an interpolated string handler and provides the required functionality especially for our use case:

[InterpolatedStringHandler]
public ref struct StructuredLoggingInterpolatedStringHandler
{
    // The actual code will be shown below
}

Next, we can use it as a method argument. For example, let's create a Log extension method:

public static partial class LoggerExtensions
{
    public static void Log(this ILogger logger, LogLevel logLevel, 
        [InterpolatedStringHandlerArgument("logger", "logLevel")] ref StructuredLoggingInterpolatedStringHandler handler)
    {
        // The actual code will be shown below
    }
}

If we try to pass an interpolated string to our Log method now:

logger.Log(LogLevel.Information, $"The length of segment {segment} is {length}.");

the compiler will transform it to the following code:

var handler = new StructuredLoggingInterpolatedStringHandler(
    27, 2, logger, LogLevel.Information, out bool isEnabled);
if (isEnabled)
{
    handler.AppendLiteral("The length of segment ");
    handler.AppendFormatted(segment);
    handler.AppendLiteral(" is ");
    handler.AppendFormatted(length);
    handler.AppendLiteral(".");
}
logger.Log(LogLevel.Information, ref handler);

We can see that the compiler uses calls to the AppendLiteral method in order to add literal parts of the string and calls to the AppendFormatted method(s) for the arguments. Thus, we can write our handler in a way that it creates a template string to be passed into the original ILogger.Log, as well as the argument array.

The next question is how we can get the names of the arguments. Fortunately, C# 10 provides another feature that can help us, namely CallerArgumentExpressionAttribute. Like with the other Caller*-attributes, if we mark an optional string parameter of the AppendFormatted method with this attribute, the compiler will pass the C# expression used for the other method's parameter as this parameter's value.

So, let's put everything together and write the code for our handler.

First, we'll declare fields for the message template and its arguments, as well as a property indicating whether the required log level is enabled:

[InterpolatedStringHandler]
public ref struct StructuredLoggingInterpolatedStringHandler
{
    private readonly StringBuilder _template = null!;
    private readonly List<object?> _arguments = null!;

    public bool IsEnabled { get; }
  
    // ...
}

Next, we must create a constructor taking the length of the string literal, the number of arguments, the instance of ILogger, the log level and the output parameter isEnabled:

public StructuredLoggingInterpolatedStringHandler(
    int literalLength, 
    int formattedCount, 
    ILogger logger, 
    LogLevel logLevel, 
    out bool isEnabled)
{
    IsEnabled = isEnabled = logger.IsEnabled(logLevel);
    if (isEnabled)
    {
        _builder = new StringBuilder(literalLength);
        _arguments = new List<object?>(formattedCount);
    }
}

Note that we create StringBuilder and List<object?> only if the log level passed to the method is enabled.

You might wonder how the compiler knows where it can get the ILogger and the log level from. If you look at the declaration of the Log method above, you can see that the handler parameter is marked with the [InterpolatedStringHandlerArgument("logger", "logLevel")] attribute with two arguments. The arguments specify the names of the method parameters containing these values.

Next, we will add the AppendLiteral method:

public void AppendLiteral(string s)
{
    if (!IsEnabled) 
        return;

    _template.Append(s.Replace("{", "{{", StringComparison.Ordinal).Replace("}", "}}", StringComparison.Ordinal));
}

I used two calls to String.Replace in order to escape the braces in this method. For sure, we could implement this escaping in a more optimal way, but let's leave it as it is in this article for simplicity.

Next, we will add the AppendFormatted method:

public void AppendFormatted<T>(
    T value, 
    [CallerArgumentExpression("value")] string name = "")
{
    if (!IsEnabled)
        return;

    _arguments.Add(value);
    _template.Append($"{{@{name}}}");
}

As I mentioned before, it contains the optional name parameter marked with the [CallerArgumentExpression("value")] attribute. The compiler will pass the string representation of the C# expression used for the value parameter as the value of this parameter (a variable name in the simplest case).

Note that I always add the @ symbol before the argument name. As far as I can see, Serilog handles it well even for primitive types. However, if it didn't, we could always create separate overloads for such types.

At last, we will add a method that returns the built message template and the argument array:

public (string, object?[]) GetTemplateAndArguments() => (_template.ToString(), _arguments.ToArray());

Our handler is ready! You can find its full source code under the spoiler:

[InterpolatedStringHandler]
public ref struct StructuredLoggingInterpolatedStringHandler
{
    private readonly StringBuilder _template = null!;
    private readonly List<object?> _arguments = null!;

    public bool IsEnabled { get; }

    public StructuredLoggingInterpolatedStringHandler(int literalLength, int formattedCount, ILogger logger, LogLevel logLevel, out bool isEnabled)
    {
        IsEnabled = isEnabled = logger.IsEnabled(logLevel);
        if (isEnabled)
        {
            _template = new (literalLength);
            _arguments = new (formattedCount);
        }
    }

    public void AppendLiteral(string s)
    {
        if (!IsEnabled) 
            return;

        _template.Append(s.Replace("{", "{{", StringComparison.Ordinal).Replace("}", "}}", StringComparison.Ordinal));
    }

    public void AppendFormatted<T>(
        T value, 
        [CallerArgumentExpression("value")] string name = "")
    {
        if (!IsEnabled)
            return;

        _arguments.Add(value);
        _template.Append($"{{@{name}}}");
    }

    public (string, object?[]) GetTemplateAndArguments() => (_template.ToString(), _arguments.ToArray());
}

Our Log method can use it in the following way:

public static partial class LoggerExtensions
{
    public static void Log(this ILogger logger, LogLevel logLevel, 
        [InterpolatedStringHandlerArgument("logger", "logLevel")] ref StructuredLoggingInterpolatedStringHandler handler)
    {
        if (handler.IsEnabled)
        {
            var (template, arguments) = handler.GetTemplateAndArguments();
            logger.Log(logLevel, template, arguments);
        }
    }
}

Now we can use it to perform logging:

logger.Log(LogLevel.Information, $"The length of segment {segment} is {length}.");

We will get a correct log record as the result:

{
    "@t": "2021-11-14T02:13:34.8380946Z",
    "@mt": "The length of segment {@segment} is {@length}.",
    "segment": {
        "Start": {
            "X": 1,
            "Y": 2,
            "$type": "Point"
        },
        "End": {
            "X": 4,
            "Y": 6,
            "$type": "Point"
        },
        "$type": "Segment"
    },
    "length": 5,
    "SourceContext": "Program"
}

By the way, note that the method overload taking the handler has a priority over the one taking a string. In my humble opinion, this behavior is much more correct than the one we have had with FormattableString overloads since C# 6.

So, now we have an extension method letting us write to the logs with the log level specified in one of the parameters. We would also like to have methods specific for each log level like LogError. We can create them in the same way, however our original handler requires the log level passed as one of the parameters. Thus, we will have to create a separate handler for each log level. Luckily, we can use composition and reuse our StructuredLoggingInterpolatedStringHandler inside these handlers, e.g.:

[InterpolatedStringHandler]
public ref struct StructuredLoggingErrorInterpolatedStringHandler
{
    private readonly StructuredLoggingInterpolatedStringHandler _handler;

    public StructuredLoggingErrorInterpolatedStringHandler(int literalLength, int formattedCount, ILogger logger, out bool isEnabled)
    {
        _handler = new StructuredLoggingInterpolatedStringHandler(literalLength, formattedCount, logger, LogLevel.Error, out isEnabled);
    }

    public bool IsEnabled => _handler.IsEnabled;

    [MethodImpl(MethodImplOptions.AggressiveInlining)]
    public void AppendLiteral(string s) => _handler.AppendLiteral(s);

    [MethodImpl(MethodImplOptions.AggressiveInlining)]
    public void AppendFormatted<T>(T value, [CallerArgumentExpression("value")] string name = "") => _handler.AppendFormatted(value, name);

    [MethodImpl(MethodImplOptions.AggressiveInlining)]
    public (string, object?[]) GetTemplateAndArguments() => _handler.GetTemplateAndArguments();
}

public static void LogError(this ILogger logger, [InterpolatedStringHandlerArgument("logger")] ref StructuredLoggingErrorInterpolatedStringHandler handler)
{
    if (handler.IsEnabled)
    {
        var (template, arguments) = handler.GetTemplateAndArguments();
        logger.LogError(template, arguments);
    }
}

The full source code of the demo project (with some improvements) can be found at GitHub.

Performance

I used BenchmarkDotNet to measure the performance. The result for logging to Serilog with an empty logger are the following:

In this table:

• Template and Args - a usual call of LogInformation(string, object[]).

• Interpolated Handler - our code with interpolated string handler.

• Logger Message Delegate - cached delegate created by LoggerMessage.Define. This approach is also used by the source generator.

• Formattable String * - different approaches from the https://github.com/Drizin/InterpolatedLogging library.

We can see, that if the log level is disabled, our approach is faster and allocates no wasted memory.

If the log level is enabled, our approach is approximately 7-10% slower than using a raw template or a cached delegate, however it still performs much better than https://github.com/Drizin/InterpolatedLogging.

Conclusion

Using C# 10, we were able to add the structured logging support with string interpolation and get rid of the issues with the argument duplication, wrong argument number or order as well as wasting memory when the log level is disabled.

The source code still has some issues like missing escaping of names (as Serilog requires the names to be valid C# identifiers) or suboptimal implementation in some places. You can find a production ready solution in my library called ISLE.

Useful Links

• https://github.com/fedarovich/isle

• https://andrewlock.net/exploring-dotnet-6-part-8-improving-logging-performance-with-source-generators/

• https://docs.microsoft.com/en-us/dotnet/core/extensions/logger-message-generator

• https://docs.microsoft.com/en-us/dotnet/csharp/whats-new/tutorials/interpolated-string-handler

• https://docs.microsoft.com/en-us/dotnet/api/system.runtime.compilerservices.callerargumentexpressionattribute?view=net-6.0