Between now and the Serilog 2.0 release that’s due sometime in July, I’ve decided to go back to basics and write some posts on the fundamentals of modern structured logging in .NET.

In the complex, distributed, asynchronous systems being built today, answering questions about behavior – what caused this issue? – is a horribly tedious thing to have to do without the right instrumentation. I hope this series will be useful for anyone wanting to build more manageable .NET apps with the new crop of frameworks and tools.

The examples use Serilog, but most of the same concepts appear in other libraries, so where possible I’ll call out the alternative APIs.

A tentative plan of attack, following this post:

But now, let’s get the ball rolling!

What is structured logging?

Approaches to application diagnostic logging can be roughly divided into text-based logging and structured, or event-based, logging.

Text logging, sometimes also called ‘printf debugging’ after the C printf() family of functions, is the first one most programmers encounter. As your code executes, it prints lines of text out to the terminal that describe what’s going on.

12:23:10 [INF] Service "loyalty-card-printer" starting up on host 8fd342hkg22u
12:23:11 [INF] Listening on http://8fd342hkg22u.example.com:1234
12:23:20 [INF] Card replacement request received for customer-109972
12:40:55 [INF] Card replacement request received for customer-98048
…

Because text logs are written as a narrative in natural language, they’re nice and easy to read.

Text is a very expressive format, and tools including full-text indexing and regular expressions can do a lot with it, but answering anything non-trivial with text log data can still take some painstaking work.

Structured logging is an umbrella term for alternatives focusing on easier searching and analysis at scale. A structured log event, rather than being a line of text, is conceptually a timestamped set of name/value properties.

Structured logging systems separate the way the event is captured (the logging API) from the way that it is transported (perhaps JSON) and how it is rendered in a user interface or file.

A rough translation of the sequence above to structured events might be conceptually like:

time=12:23:10, level=INF, service=loyalty-card-printer, host=8fd342hkg22u, activity=started
time=12:23:11, level=INF, endpoint=http://8fd342hkg22u.example.com:1234, activity=listening
time=12:23:20, level=INF, customer=customers-1099972, activity=replacement
time=12:40:55, level=INF, customer=customer-98048, activity=replacement
…

Structured logs are easier to navigate because the properties in the event are first-class: a log server can return results for a query like activity == "replacement" && customer == "customer-98048" without any configuration to describe how the events should be parsed.

The line between structured and text logs is blurry:

  • Text logs can provide some structure by encoding well-known fields like the timestamp, logging level and thread id at the start of each line, and by including name=value formatted fields in the message itself
  • Structured logs sometimes look a lot like text logs when formatted out to a flat file or the terminal, and often include a message field that is itself free text

But, these similarities are skin deep. Structured logging and text logging require different mindsets in order to use each well.

Historical barriers to adoption

Structured logging isn’t always 100% rainbows-and-unicorns-awesome. My guess is that two warts have kept adoption of structured logging in second place.

First, structured logging implementations can be more labor-intensive at development time than text-based alternatives.

In .NET, the EventSource API illustrates this well. Writing a structured log event with EventSource requires an event definition in the form of a C# method in a separate class, along with the line of code to actually record the event:

[Event(123, Message = "Card replacement request received for: {0}")]
internal void CardReplacementRequested(string customerId)
{
  if (this.IsEnabled()) this.WriteEvent(123, customerId); 
}

// Elsewhere:
// eventSource.CardReplacementRequested(customerId);

Switching between files and creating an annotated method just to record a single log event is a tough cost to bear, in comparison with the single line of code to record a typical text log event.

Second, many structured logging implementations produce output that is harder to visually scan. This phenomenon is exaggerated in the earlier example – there are nicer ways to format the same structured events – but it’s still very hard to complete with natural language for readability.

The topic of this series is the most recent structured logging approach for .NET, specifically designed to avoid these issues.

Logging with message templates

Since the technique was introduced by Serilog a few years ago, many .NET applications have adopted a style of logging that captures a structured event, as well as a human-friendly text representation of it, in the same line of code.

// var customerId = "customer-109972";
Log.Information("Card replacement request received for {CustomerId}", customerId);

The description of the event, called the message template, uses named ‘holes’ instead of the anonymous {0} and {1} numeric placeholders found in .NET format strings.

Under the hood, instead of immediately substituting the value of customerId into the template to create a text event, the logging library captures the template and the argument values individually. By matching the named holes in the template with the positional arguments, the customerId value is associated with a property called CustomerId on the event.

You can imagine the resulting event in JSON format might look like:

{
    "time": "2016-06-01T02:23:10Z",
    "level": "INF",
    "template": " Card replacement request received for {CustomerId}",
    "properties": {
        "customerId": " customer-109972"
    }
}

The event can be rendered as text using the template and properties, or stored and searched as structured data, achieving the best of both worlds: events that are optimally human-friendly and optimally machine-readable.

At the time of writing, you can use message templates in .NET with Serilog, Microsoft.Extensions.Logging (ASP.NET Core) and Logary.

(I actually heard the term “modern” used to describe this style of structured logging via Jason Roberts’ Pluralsight course on Serilog and Seq, which is a couple of versions behind but still well worth checking out if you have a subscription.)

It sounds like I’ve told the whole story of modern structured logging already with this post! One line of code is enough to convey the basic idea, but there really is more to know if you want to use it effectively. I’m aiming to fill two installments of this series each week, so if all goes well you won’t have to wait too long for the next post on events and levels….