Structured Logging
Why a log message is written as a template with named placeholders instead of an interpolated string, and what that buys you.
logger.LogInformation("text {FieldName} more text", value);A log line has two readers: a person, and the search box of a log system. A message template serves both. It is a constant string with named holes in it, and the values are passed separately.
logger.LogInformation("order {OrderId} shipped to {City}", orderId, city);The logger keeps the template and the values apart. The console prints one readable sentence. A provider that stores structured data keeps OrderId and City as named fields, plus the template itself under the key {OriginalFormat}. Now you can ask the log store for every line where OrderId is 7, or count lines grouped by City. That query is impossible over free text.
Interpolation throws the fields away
Writing logger.LogInformation($"order {orderId} shipped to {city}") looks almost the same and prints the same sentence. But the interpolated string is built before the logger is called. The logger receives one finished string, no fields, and a template that is different on every call, so nothing groups. The analyser rule CA2254, Template should be a static expression, flags this; in .NET 10 it is enabled by default as a suggestion.
The one habit
Name every placeholder, use PascalCase for the name, and use the same name for the same thing in every service you own. If one place logs {OrderId} and another logs {Order}, no single query finds both. A numeric placeholder such as {0} works but produces a field literally named 0.
What trips people up: the values fill the holes left to right, by position, not by name.
Example
// dotnet add package Microsoft.Extensions.Logging.Console
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Console;
using ILoggerFactory factory = LoggerFactory.Create(builder =>
{
builder.SetMinimumLevel(LogLevel.Information);
builder.AddSimpleConsole(options =>
{
options.ColorBehavior = LoggerColorBehavior.Disabled;
});
});
ILogger logger = factory.CreateLogger("Orders");
int orderId = 7;
string city = "Leeds";
// Interpolated. The text is finished before the logger sees it, so the
// logger gets one opaque string and no fields. Analyser rule CA2254.
logger.LogInformation($"order {orderId} shipped to {city}");
// Template. The logger gets the template plus two named values.
logger.LogInformation("order {OrderId} shipped to {City}", orderId, city);
// The console prints the same sentence twice. Only the second line
// carries OrderId and City as fields a log store can query.
// Output:
// info: Orders[0]
// order 7 shipped to Leeds
// info: Orders[0]
// order 7 shipped to LeedsWhen to use it
- Find every log line for one order id across a day of traffic.
- Count failed payments grouped by country without parsing text.
- Alert when the same error field appears more than fifty times in five minutes.
More examples
Seeing the fields with the JSON console provider
This is the proof that the fields survive. AddJsonConsole writes one JSON object per entry, and OrderId is a JSON number, not text. Containers on Kubernetes usually run this formatter, because the log collector can then read the fields without guessing at the sentence. Note that the template is kept verbatim under {OriginalFormat}.
// dotnet add package Microsoft.Extensions.Logging.Console
using System.Text.Json;
using Microsoft.Extensions.Logging;
using ILoggerFactory factory = LoggerFactory.Create(builder =>
{
builder.SetMinimumLevel(LogLevel.Information);
builder.AddJsonConsole(options =>
{
options.JsonWriterOptions = new JsonWriterOptions { Indented = true };
});
});
ILogger logger = factory.CreateLogger("Orders");
logger.LogInformation("order {OrderId} shipped to {City}", 7, "Leeds");
// Output:
// {
// "EventId": 0,
// "LogLevel": "Information",
// "Category": "Orders",
// "Message": "order 7 shipped to Leeds",
// "State": {
// "Message": "order 7 shipped to Leeds",
// "OrderId": 7,
// "City": "Leeds",
// "{OriginalFormat}": "order {OrderId} shipped to {City}"
// }
// }Four ways to write it, one that is right
All four print the same sentence, which is why the wrong ones survive code review. Keep this list in mind when you read someone else's code: the first three are the shapes to change. The fix is mechanical, so it is worth doing to a whole file at once.
using Microsoft.Extensions.Logging;
public static class Examples
{
public static void Show(ILogger logger, int orderId, string city)
{
// Concatenation: one string, no fields, new template every call.
logger.LogInformation("order " + orderId + " shipped to " + city);
// Interpolation: reads better, same loss.
logger.LogInformation($"order {orderId} shipped to {city}");
// Numbered holes: fields are named "0" and "1".
logger.LogInformation("order {0} shipped to {1}", orderId, city);
// Named holes: this is the one to write.
logger.LogInformation("order {OrderId} shipped to {City}", orderId, city);
}
}Agreeing on field names across services
A const string is still a constant expression, so CA2254 is satisfied and the template stays searchable. Pulling the templates into one place is how two teams end up spelling it OrderId rather than orderID, OrderNumber and Order. Reach for this when more than one service logs about the same kind of thing.
using Microsoft.Extensions.Logging;
public static class LogFields
{
// Both services log the same template text, so one query finds both.
public const string OrderAccepted = "order {OrderId} accepted for {CustomerId}";
public const string OrderRejected = "order {OrderId} rejected: {Reason}";
public static void Accepted(ILogger logger, int orderId, int customerId)
{
logger.LogInformation(OrderAccepted, orderId, customerId);
}
}
Discussion