Structured Logging with .NET ILogger

post-thumb

TL;DR:

Stop doing interpolated strings for logging and use the appropriate ILogger extension methods instead to enable structured logging from your .NET application. This allows for better log queries, analysis and searching through your logs in logging backends like Application Insights.

Bad

log.LogError($"Job with Id {jobId} returned error code -1 and is now in {jobState} state.");

Good

log.LogError("Job with Id {JobId} returned error code {ErrorCode} and is now in {JobState} state.", jobId, -1, jobState);

What is Structured Logging?

We speak of structured logging when delivering log messages not only as plain text but rather text enriched with additional information or data. While plain text ist hard to analyze and parse, with structured logging we give it a structure so it can be operated on based on specific, pre-defined and labeled data blocks embedded in our log messages. In practice this is done by transforming the log message string into an object (e.g. in JSON) which can then be processed by logging backends or providers like Application Insights.

Behind the curtains, that is exactly what ILogger can do for you.

ILogger

The ILogger interface provided by Microsoft.Extensions.Logging.Abstractions is probably the most ubiquitous log writer in the .NET world and Azure when it comes to all things logging. It is injected into the service collection in newer versions of Azure Functions by default and forms pretty much the standard in ASP .NET Core as well. We heavily use it in our projects to write our application logs to Application Insights.

For writing structured logs to a logging provider supporting it like Application Insight does, the ILogger interface exposes appropriate method overrides for all the common log levels e.g. LogError.

public static void LogError (this Microsoft.Extensions.Logging.ILogger logger, string? message, params object?[] args);

They provide separate parameters for supplying a message template and some varargs containing the matching values to substitute for in the template. A complete list of all the available extension methods for structured logging can be found in the docs.

The message template may look like an interpolated string on first sight but happens to be a normal string instead with (named) references to the respective values supplied, embedded between curly braces (Notice the dropped $-sign in comparison). Those will be substituted with the supplied values when printed out but serve as a reference when analyzing or searching logs for all occurences of such values.

You can pretty much compare that with relational database columns (the named references) and rows (the supplied values).

log.LogError("Job with Id {JobId} returned error code {ErrorCode} and is now in {JobState} state.", jobId, -1, JobState.Canceled);

If you instead use interpolated strings here, substitution takes place in your application rather than in the logging backend, emitting just plain text so you loose all the benefits from structured logging.

Speaking of which …

The benefits of Structured Logging

If we instructed our application to emit structured logs we can take advantage of that for example in Application Insights when writing log queries. We are now able to reference the properties from the message template to filter efficiently e.g. for all errors where a job resulted in the canceled state:

traces
| state = tostring(customDimensions["prop__JobState"])
| where state == "canceled"

That’s all I wanted to share with you for now real quick.

Der Objektkultur-Newsletter

Mit unserem Newsletter informieren wir Sie stets über die neuesten Blogbeiträge,
Webcasts und weiteren spannende Themen rund um die Digitalisierung.

Newsletter abonnieren