If you want to easily filter your application logs, structured logging is the way to go. However, using just the standard .NET libraries, structured logging in C# can be both cumbersome and inefficient. In this article, we will explore how to make structured logging efficient and simple.
In this article, you will learn:
- What is structured logging
- What’s wrong with using the vanilla LogInformation method for structured logging?
- Why not use the standard C# string interpolation for logging?
- What are custom string interpolation handlers?
- How to make structured logging efficient?
- How to make structured logging clean and compact?
- How to automatically add structured logging to your code?
What is structured logging?
Structured logging involves reporting errors, warnings, and messages in a consistent and organized format, making it straightforward to read, search, and analyze by applications or individuals. A common format for structured logging is JSON because it is both compact and readable. By contrast, unstructured logging reports unstructured text that can only be searched by substrings or regular expressions.
In C#, the most common logging API is the Microsoft.Extensions.Logging namespace. Typically, your structured logging code might look something like this:
_logger.LogInformation("Product {product} sold for {price}.", product, price);
Here, we specify the names of the arguments, product and price, allowing a structured logging backend to recognize them. The server might receive and index a JSON message like this:
{
"EventId": 0,
"LogLevel": "Information",
"Category": "LoggingWithInterpolation.Shop",
"Message": "Product llama T-shirt sold for 10.0.",
"State": {
"Message": "Product llama T-shirt sold for 10.0.",
"product": "llama T-shirt",
"productPrice": 10.0,
"{OriginalFormat}": "Product {product} sold for {productPrice}."
}
}
As you can see, the message parameters are stored and indexed separately from the formatted message text, making it easier to filter messages.
What’s wrong with using the vanilla LogInformation method for structured logging?
From a server point of view, structured logging looks great. However, there are two problems with the C# code above:
There is some redundancy between the argument names in the formatting string and the argument list, i.e.
productandpriceare duplicated. Not only does it require additional work, but it may also lead to inconsistencies if the formatting string is not synchronized with its argument list.This code isn’t efficient. It allocates an array for the arguments and boxes value type arguments every time, even when logging for this log level isn’t enabled. The inefficiency escalates if the computation of one of the arguments is expensive.
If you’re familiar with the string.Format method, you know that string interpolation was invented specifically to address these two issues. So, why not use string interpolation here?
Why not use the standard C# string interpolation for logging?
You might think of the following code:
_logger.LogInformation($"Product {product} sold for {price}.");
But you’ll quickly realize that this approach is actually worse!
- It doesn’t resolve the performance issue.
- It loses argument names for structured logging.
This is why using string interpolation for logging is generally not recommended.
What are custom string interpolation handlers?
Both problems of the default C# string interpolation can be solved thanks to the improvements to string interpolation brought by C# 10. Unfortunately, the necessary supporting classes and extension methods have not been implemented in the system libraries, so we need to implement them ourselves.
We must implement two artifacts ourselves:
- a custom string interpolation handler that gathers all the information and then calls the
ILogger.Logmethod, and - a custom extension method of the
ILoggerextension, calledLogInformation, but accepting our custom string interpolation handler instead of the formatting string.
Let’s start with a basic implementation. It will not address any of the two issues above, but at least we can learn the API.
public static class LoggingExtensions
{
public static void LogInformation(
this ILogger logger,
[InterpolatedStringHandlerArgument( nameof(logger) )]
LogInformationInterpolatedStringHandler handler )
=> handler.Log();
}
[InterpolatedStringHandler]
public ref struct LogInformationInterpolatedStringHandler
{
private readonly StringBuilder messageBuilder;
private readonly ILogger logger;
public LogInformationInterpolatedStringHandler(
int literalLength, int formattedCount, ILogger logger )
{
this.messageBuilder = new StringBuilder( literalLength + (formattedCount * 10) );
this.logger = logger;
}
public void AppendLiteral( string literal )
=> this.messageBuilder.Append( literal );
public void AppendFormatted<T>( T value )
=> this.messageBuilder.Append( value?.ToString() );
public void Log()
=> this.logger.Log(
LogLevel.Information, this.messageBuilder.ToString() );
}
To get the full source code of the article, please refer to the original article.
What does this do? When the C# compiler encounters a call to a method like LogInformation, where an interpolated string is passed to a parameter whose type is marked with the [InterpolatedStringHandler] attribute, it first calls the constructor of that type. The constructor is passed basic information about the interpolated string, which can be used to guess an initial size of a buffer (here, StringBuilder). The constructor also receives the values of other arguments, as specified by the [InterpolatedStringHandlerArgument] attribute. Next, the compiler calls the AppendLiteral and AppendFormatted methods for each part of the interpolated string. Finally, the method is called with the newly constructed handler.
When applied to the earlier logging code, this process results in the following code:
var handler = new LogInformationInterpolatedStringHandler(19, 2, _logger);
handler.AppendLiteral("Product ");
handler.AppendFormatted(product);
handler.AppendLiteral(" sold for ");
handler.AppendFormatted(price);
handler.AppendLiteral(".");
_logger.LogInformation(handler);
This works, but, as announced, it neither addresses the issue of parameter names nor of efficiency.
Let’s address the performance problem first.
How to make structured logging efficient?
Let’s first make sure that we don’t do too much work when logging is disabled. This is relatively straightforward: a custom string interpolation handler can have an out bool parameter on its constructor. When this parameter is set to false, it signifies that the handler is not enabled, so no further processing is done. This avoids all performance costs associated with that:
public LogInformationInterpolatedStringHandler(
int literalLength,
int formattedCount,
ILogger logger,
out bool isEnabled )
{
isEnabled = logger.IsEnabled( LogLevel.Information );
if ( isEnabled )
{
this.messageBuilder = new StringBuilder(
literalLength + (formattedCount * 10) );
this.logger = logger;
}
this.isEnabled = isEnabled;
}
For this modified handler, the C# compiler generates the following code:
var handler = new LogInformationInterpolatedStringHandler(
19, 2, _logger, out var isEnabled);
if (isEnabled)
{
handler.AppendLiteral("Product ");
handler.AppendFormatted(product);
handler.AppendLiteral(" sold for ");
handler.AppendFormatted(price);
handler.AppendLiteral(".");
}
_logger.LogInformation(handler);
This is a significant improvement: most of the code is executed only when logging is enabled, which is exactly what we wanted.
How to make structured logging more compact?
So, what about argument names? For this, we’ll leverage another C# feature: caller argument expression. This feature allows us to obtain the C# code for an argument passed to a method. In the case of the AppendFormatted method, that would be the interpolated value, which is precisely what we’re looking for.
To ensure we don’t lose the ability to have a custom name for a logged argument, we can (ab)use the format string component of an interpolated value, i.e. the substring after the : character:
_logger.LogInformation($"Product {product} sold for {price:productPrice}.");
In the example above, the name of the product argument would be left to its default value (product), while the name of the second argument would be overridden to productPrice. Fortunately, this can be combined with a caller argument expression, provided we name the parameter to AppendFormatted as format.
When we combine these elements, we get:
[InterpolatedStringHandler]
public ref struct LogInformationInterpolatedStringHandler
{
private readonly StringBuilder messageBuilder;
private readonly object?[] arguments;
private readonly ILogger logger;
private readonly bool isEnabled;
private int argumentsIndex;
public LogInformationInterpolatedStringHandler(
int literalLength,
int formattedCount,
ILogger logger,
out bool isEnabled )
{
isEnabled = logger.IsEnabled( LogLevel.Information );
if ( isEnabled )
{
this.messageBuilder = new StringBuilder(
literalLength + (formattedCount * 10) );
this.arguments = new object?[formattedCount];
this.logger = logger;
}
this.isEnabled = isEnabled;
}
public readonly void AppendLiteral( string literal )
=> this.messageBuilder.Append( literal.Replace( "{", "{{", StringComparison.Ordinal ).Replace( "}", "}}", StringComparison.Ordinal ) );
public void AppendFormatted<T>( T value,
[CallerArgumentExpression( nameof(value) )] string format = null! )
{
this.messageBuilder.Append( $"{{{format}}}" );
this.arguments[this.argumentsIndex] = value;
this.argumentsIndex++;
}
public readonly void Log()
{
if ( this.isEnabled )
{
this.logger.Log( LogLevel.Information, this.messageBuilder.ToString(), this.arguments );
}
}
}
This time, the C# compiler generates the following code:
var handler = new LogInformationInterpolatedStringHandler(19, 2, _logger, out var isEnabled);
if (isEnabled)
{
handler.AppendLiteral("Product ");
handler.AppendFormatted(product, "product");
handler.AppendLiteral(" sold for ");
handler.AppendFormatted(price, "productPrice");
handler.AppendLiteral(".");
}
_logger.LogInformation(handler);
Note how the format argument for product is set by the caller argument expression to "product" and for price to "productPrice" from the format string.
When logging with the simple console logger, this produces output like:
info: LoggingWithInterpolation.Shop[0]
Product llama T-shirt sold for 10.0.
And with JSON logger (to see the structured logging in action):
{
"EventId": 0,
"LogLevel": "Information",
"Category": "LoggingWithInterpolation.Shop",
"Message": "Product llama T-shirt sold for 10.0.",
"State": {
"Message": "Product llama T-shirt sold for 10.0.",
"product": "llama T-shirt",
"productPrice": 10.0,
"{OriginalFormat}": "Product {product} sold for {productPrice}."
}
}
How to automatically add structured logging to your code?
We’ve seen how to achieve compact and efficient logging with clean code. However, there are situations where you want to log all method executions and their parameter values. This can lead to code repetition! Traditional code generators like T4 or source generators don’t help because they can only generate new files - they cannot add code into our hand-written code.
Enter Metalama, a code generation toolkit that can mix generated code with user-written code, all at build time.
Let’s see how we can use it to automate the logging of method calls.
First, we need to create an aspect, which is like a template describing how the code should be transformed.
public class LogAttribute : OverrideMethodAspect
{
[IntroduceDependency]
private readonly ILogger _logger;
public override dynamic? OverrideMethod()
{
// LogInformation can't be called as an extension method here,
// because Metalama uses the dynamic type to represent
// run-time values
// and dynamic is not compatible with extension methods.
LoggingExtensions.LogInformation( this._logger,
BuildInterpolatedString().ToValue() );
return meta.Proceed();
}
[CompileTime]
private static InterpolatedStringBuilder BuildInterpolatedString()
{
var stringBuilder = new InterpolatedStringBuilder();
// Include the type and method name.
stringBuilder.AddText(
$"{meta.Target.Type}.{meta.Target.Method.Name}(" );
var first = true;
// Include each parameter.
foreach ( var parameter in meta.Target.Parameters )
{
if ( !first )
{
stringBuilder.AddText( ", " );
}
stringBuilder.AddText( $"{parameter.Name}: " );
stringBuilder.AddExpression( parameter.Value );
first = false;
}
stringBuilder.AddText( ") started." );
return stringBuilder;
}
}
Most of the above code executes at compile time.
You can add the logging aspect to methods one at a time using the [Log] attribute. This feature is completely free. Another option is to use a Metalama fabric to add logging more widely using a single piece of code, but this is a commercial feature:
internal class Fabric : ProjectFabric
{
public override void AmendProject( IProjectAmender amender )
{
amender.Outbound
.SelectMany( c => c.Types )
.Where( t => t.TypeKind is not TypeKind.RecordClass
or TypeKind.RecordStruct )
.Where( t => t.Accessibility == Accessibility.Public )
.SelectMany( c => c.Methods )
.Where( m => m.Accessibility == Accessibility.Public )
.AddAspectIfEligible<LogAttribute>();
}
}
When applied to the void Sell(Product product, decimal price) method (whether using an attribute or using a fabric), the aspect generates the following code at the start of the method:
LoggingExtensions.LogInformation(_logger,
$"Shop.Sell(product: {product}, price: {price}) started.");
This code produces the following output from the simple console logger:
info: LoggingWithInterpolation.Metalama.Shop[0]
Shop.Sell(product: llama T-shirt, price: 10.0) started.
And with JSON:
{
"EventId": 0,
"LogLevel": "Information",
"Category": "LoggingWithInterpolation.Metalama.Shop",
"Message": "Shop.Sell(product: llama T-shirt, price: 10.0) started.",
"State": {
"Message": "Shop.Sell(product: llama T-shirt, price: 10.0) started.",
"product": "llama T-shirt",
"price": 10.0,
"{OriginalFormat}": "Shop.Sell(product: {product}, price: {price}) started."
}
}
Of course, you can also customize what is logged to suit your needs, such as logging exceptions or return values.
Summary
Structured logging can be incredibly useful in production, and with just a couple of additional files in your project, you can use it easily and efficiently with familiar interpolated string builders. As a bonus, to automatically add structured logging to your code, you can create a Metalama aspect.
This article was first published on a https://blog.postsharp.net under the title Fast and Compact Structured Logging in C# Using String Interpolation.
Top comments (0)