Structural Logging and Interpolated Strings in C # 10

In recent years, structured logging has become increasingly popular among developers. Therefore, it is not surprising that Microsoft added support for it to the Microsoft.Extensions.Logging package, which is part of .Net Core / .Net 5 / .Net 6. In this article, I would like to look at how we can use structured logging with this package and show idea how we can extend it using the new features of C # 10.

Initial setup

As you know, Microsoft.Extensions.Logging is a facade to which we can connect various underlying logging providers. In this article, I will use Serilog as such a provider and configure it to output logs to the console in JSON format.

As an example, we will consider a simple console application (link to github), in which the logging configuration looks like this:

// Конфигурируем Serilog
Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Information()
    .WriteTo.Console(new CompactJsonFormatter())
    .CreateLogger();   

// Регистрируем Serilog при создании Microsoft.Extensions.Logging.LoggerFactory
using var loggerFactory = LoggerFactory.Create(builder => builder.AddSerilog(dispose: true));
// Создаем экземпляр ILogger при помощи фабрики
var logger = loggerFactory.CreateLogger<Program>();

Also, we will create two records that we will use in 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

For logging we will use the interface ILoggerwhich provides several method overloads Log, which allows you to specify the logging level as a parameter, as well as methods of the form Log<уровень>, for example LogInformation, LogError etc. All of these methods take as parameters a template string and an array of arguments (params object[]).

Let’s log, for example, the result of calculating the length of the segment:

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 format string has two arguments, enclosed in curly braces: segment and length… The argument values ​​are passed as subsequent parameters to the method. Symbol @ before argument segment is part of the agreement Message Template and means Serilog should expand the argument structure as an object. Without this symbol, Serilog would simply log the result of a method call by default. segment.ToString()…

As a result, we will get the following entry in the log:

{
	"@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 the property @mtcontaining our template string as well as properties segment and lengthcontaining our arguments.

Despite the fact that this approach is quite simple and straightforward, it has a number of significant disadvantages:

• Having to parse a format string at runtime, which is quite expensive. To mitigate this shortcoming, the logging infrastructure has 1024 line cache…

• The need to allocate memory for an array of arguments even if the specified logging level is disabled.

• Significant type arguments are packed when placed in an array of objects.

• Duplicate variable names in the template string and in method parameters.

• It’s easy to forget one of the parameters or to confuse their order.

As an alternative, devoid of all these drawbacks, .Net 6 suggests using a new source code generator: we can declare a partial method that takes the parameters we need and mark it with the attribute LoggerMessageAttributeas shown in the following example:

[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 allows you to provide the highest logging performance, but it also has its drawbacks:

• Clutters up the source code with partial method declarations.

• Doesn’t allow the use of the symbol @ before the argument names, which prevents Serilog from expanding their values ​​to JSON objects.

Adding support for interpolated strings to ILogger

So, we would like to find an expressive way to write structured logs and avoid the disadvantages described above if possible. A convenient way would be to interpolate strings. However, for this we will have to do some additional work first.

If we try to call the logging method with an interpolated string, for example:

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

then in the logs we will get the following entry:

{
	"@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 you might expect, we have lost all the information about the arguments. This happened because the C # compiler turned our interpolated string into a regular method call String.Format…

Generally speaking, prior to C # 10, the compiler could convert an interpolated string to either an object of type FormattableString, or into a regular string. Objects of type FormattableString are already more similar to what we need to solve our problem, since they contain a formatting string and an array of arguments unchanged, but their capabilities are still not enough, since we lose the names of the arguments. In addition, when choosing method overloading, C # gives preference to the version that accepts a string, which is also not very convenient in practice.

Fortunately, C # 10 introduces a new mechanism for interpolated strings that will allow us to get what we want. In short, we can create an interpolated string handler structure specifically for our task:

[InterpolatedStringHandler]
public ref struct StructuredLoggingInterpolatedStringHandler
{
    // Код обработчика будет приведен ниже
}

We can then use it as an argument to the method. Let’s create, for example, an extension method Log:

public static partial class LoggerExtensions
{
    public static void Log(this ILogger logger, LogLevel logLevel, 
        [InterpolatedStringHandlerArgument("logger", "logLevel")] ref StructuredLoggingInterpolatedStringHandler handler)
    {
        // Код метода будет приведен ниже
    }
}

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

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

then the compiler will turn this call into 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);

As we can see, the compiler uses a method call AppendLiteral to add the literal part of the string and call the method AppendFormatted for arguments, which means we can write our handler so that it forms a template string that we can pass to the original method ILogger.Logas well as a list of arguments.

You may wonder where we get the names of our arguments. Another new feature of C # 10 will help us with this – CallerArgumentExpressionAttribute… As with other relatives Caller*-attributes, we can mark them with an additional string parameter of the method AppendFormatted, and the compiler will insert as the value the C # expression used when calling a method for another parameter of the same method.

So let’s put what we’ve learned together and write the code for our handler.

First, we will declare fields for storing the message template and its arguments, as well as a property IsEnabled, in which we will store a value indicating whether the required logging 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 that takes the length of the string literal, the number of arguments, an instance ILogger, the log level for the message 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);
    }
}

Please note that we are creating StringBuilder and List<object?> only if the passed logging level is enabled, thereby saving resources if it is not.

Also, you might have a question, where does the compiler get ILogger and the logging level. If you look a little higher at the method declaration Log, you will see that the handler parameter is marked with the attribute [InterpolatedStringHandlerArgument("logger", "logLevel")] with two arguments. These arguments indicate the names of the parameters to this method that contain these objects.

Next, let’s add a method AppendLiteral:

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

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

In the code for this method, we also escape the curly braces by calling the method String.Replace… In fact, we could do the escaping in one pass, but for the sake of simplicity of the example, we will leave this code as it is.

Finally, let’s 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 said earlier, it contains the parameter name with a default value and marked with an attribute [CallerArgumentExpression("value")]… Instead of the default value, the compiler will substitute the C # expression used when calling for the parameter value (in the simplest case, a variable name).

Please note that I always add the symbol @ before the argument name. As far as I can see, Serilog handles it fine, including for primitive / built-in types. However, if this were not the case, we could always make separate method overloads AppendFormatted for such types.

Finally, let’s add a method that returns the constructed message template and an array of arguments:

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

Our processor is ready! You can find its full 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 extension method Log can use it like this:

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 everything is ready to use it for logging:

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

As a result, we will get the correct message:

{
	"@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 that takes a handler takes precedence over the overload that takes a string. In this case, in my opinion, the C # developers fixed a priority error they made with FormattableString in C # 6.

So now we have an extension method that allows us to write to the log at the specified level. We would also like to have methods specific to each logging level, such as LogError… We can create them by analogy, however, our original handler requires passing the log level as an argument, which is not in our methods. To solve this problem, we will have to create a separate handler for each logging level. Fortunately, we can take advantage of composition and reuse our StructuredLoggingInterpolatedStringHandler inside these handlers. An example of such a handler is shown under the spoiler:

[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 complete project code can be found at Github…

Conclusion

As a result, using C # 10, we managed to add support for structural logging using interpolated strings and get rid of problems with duplicate arguments, passing the wrong number of arguments, and memory allocation when this logging level is disabled.

There are still some issues in the code, such as the lack of name escaping (for example, Serilog requires names to be valid C # identifiers) or the suboptimal implementation of curly brace escaping. Nevertheless, it may well serve as a basis for creating a complete industrial solution for structural logging.

useful links