This is the first in a short series of posts exploring the process I went through to make working with scopes a little nicer in ASP.NET Core (and Serilog / Seq). In this post I'll create an extension method for logging a single key-value pair as a scope. In the next post, I'll extend this to multiple key-value pairs.

I'll start by presenting an overview of structured logging and why you should be using it in your applications. This is largely the same introduction as in my last post so feel to skip ahead if I'm preaching to the choir!

Next, I'll show how scopes are typically recorded in ASP.NET Core, with a particular focus on Serilog and Seq. This will largely demonstrate the semantics described by Nicholas Blumhardt in his post on the semantics of ILogger.BeginScope(), but it will also set the scene for the meat of this post. In particular, we'll take a look at the syntax needed to record scope state as a series of key-value pairs.

Finally, I'll show an extension method you can add to your application to make recording key-value scope state that little bit easier.

Introduction to structured logging

Structured logging involves associating key-value pairs with each log entry, instead of just outputting an unstructured string "message". For example, an unstructured log message, something that might be output to the console, might look something like:

info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]  
      Request starting HTTP/1.1 GET http://localhost:51919/

This message contains a lot of information, but if it's just stored as a string like this, then it's not easy to search or filter the messages. For example, what if you wanted to find all of the error messages generated by the WebHost class? You're limited to what you can achieve in a text editor - doable to an extent, but a lot of work.

The same method stored as a structured log would essentially be stored as a JSON object making it easily searchable, as something like:

{
    "eventLevel" : "Information",
    "category" : "Microsoft.AspNetCore.Hosting.Internal.WebHost",
    "eventId" : 1,
    "message" : "Request starting HTTP/1.1 GET http://localhost:51919/",
    "protocol" : "HTTP/1.1",
    "method" : "GET",
    "url" : "http://localhost:51919/"
}

The complete message is still there, but you also have each of the associated properties available for filtering without having to do any messy string processing.

Some of the most popular options for storing and searching structured logs are Elastic Search with a Kibana front end, or to use Seq. The Serilog logging provider also supports structured logging, and is typically used to write to both of these destinations.

Nicholas Blumhardt is behind both the Serilog provider and Seq, so I highly recommend checking out his blog if you're interested in structured logging. In particular, he recently wrote a post on how to easily integrate Serilog into ASP.NET Core 2.0 applications.

Adding additional properties using scopes

Once you're storing logs in a structured manner, it becomes far easier to query and analyse your log files. Structured logging can extract parameters from the format string passed in the log message, and attach these to the log itself.

For example, the log message Request starting {protocol} {method} {url} contains three parameters, protocol, method, and url, which can all be extracted as properties on the log.

The ASP.NET Core logging framework also includes the concept of scopes which lets you attach arbitrary additional data to all log messages inside the scope. For example, the following log entry has a format string parameter, {ActionName}, which would be attached to the log message, but it also contains four scopes:

using (_logger.BeginScope("Some name"))  
using (_logger.BeginScope(42))  
using (_logger.BeginScope("Formatted {WithValue}", 12345))  
using (_logger.BeginScope(new Dictionary<string, object> { ["ViaDictionary"] = 100 }))  
{
    _logger.LogInformation("Hello from the {ActionName}!", name);
}

The state passed in the call to ILogger.BeginScope(state) can be anything, as shown in this example. The problem is, how this state should be logged is not clearly defined by the ILogger interface, so it's up to the logger implementation to decide.

Luckily Nicholas Blumhardt has thought hard about this problem, and has baked his rules into the Serilog / Seq implementation. There are effectively three different rules:

  1. If the state is an IEnumerable<KeyValuePair<string, object>>, attach each KeyValuePair as a property to the log.
  2. If the state is a format string / message template, add the parameters as properties to the log, and the formatted string to a Scope property.
  3. For everything else, add it to the Scope property.

For the LogInformation call shown previously, these rules result in the WithValue, ViaDictionary, and Scope values being attached to the log:

Scopes created in Seq

Adding correlation IDs using scope

Of all these rules, the most interesting to me is the IEnumerable<KeyValuePair<string, object>> rule, which allows attaching arbitrary key-values to the log as properties. A common problem when looking through logs is looking for relationships. For example, I want to see all logs related to a particular product ID, a particular user ID, or a transaction ID. These are commonly referred to as correlation IDs as they allow you to easily determine the relationship between different log messages.

My one bugbear, is the somewhat lengthy syntax required in order to attach these correlation IDs to the log messages. Lets start with the following, highly contrived code. We're simply adding a product to a basket, but I've added correlation IDs in scopes for the productId, the basketId and the transactionId:

public void Add(int productId, int basketId)  
{
    using (_logger.BeginScope(new Dictionary<string, object> {
        { nameof(productId), productId }, { nameof(basketId), basketId} }))
    {
        _logger.LogDebug("Adding product to basket");
        var product = _service.GetProduct();
        var basket = _service.GetBasket();

        using (var transaction = factory.Create())
        using (_logger.BeginScope(new Dictionary<string, object> {{ "transactionId", transaction.Id }}))
        {
            basket.Add(product);
            transaction.Submit();
            _logger.LogDebug("Product added to basket");
        }
    }
}

This code does exactly what I want, but it's a bit of an eye-sore. All those dictionaries flying around and nameof() to avoid typos is a bit ugly, so I wanted to see if I could tidy it up. I didn't want to go messing with the framework code, so I thought I would create a couple of extension methods to tidy up these common patterns.

Creating a single key-value pair scope state extension

In this post we'll start with the inner-most call to BeginScope<T>, in which we create a dictionary with a single key, transactionId. For this case I created a simple extension method that takes two parameters, the key name as a string, and the value as an object. These are used to initialise a Dictionary<string, object> which is passed to the underlying ILogger.BeginScope<T> method:

public static class LoggerExtensions  
{
    public static IDisposable BeginScope(this ILogger logger, string key, object value)
    {
        return logger.BeginScope(new Dictionary<string, object> { { key, value } });
    }
}

The underlying ILogger.BeginScope<T>(T state) method only has a single argument, so there's no issue with overload resolution here. With this small addition, our second using call has gone from this:

using (_logger.BeginScope(new Dictionary<string, object> {{ "transactionId", transaction.Id }}))  

to this:

using (_logger.BeginScope("transactionId", transaction.Id))  

Much nicer, I think you'll agree!

This was the most common use case that I was trying to tidy up, so stopping at this point would be perfectly reasonable. In fact, I could already use this to tidy up the first using method too, if I was happy to change the semantics somewhat. For example

using (_logger.BeginScope(new Dictionary<string, object> {{ nameof(productId), productId }, { nameof(basketId), basketId} }))  

could become

using (_logger.BeginScope(nameof(productId), productId))  
using (_logger.BeginScope(nameof(basketId), basketId))  

Not strictly the same, but not too bad. Still, I wanted to do better. In the next post I'll show some of the avenues I explored, their pros and cons, and the final extension method I settled on.

Summary

I consider structured logging to be a no-brainer when it comes to running apps in production, and key to that are correlation IDs applied to logs wherever possible. Serilog, Seq, and the ASP.NET Core logging framework make it possible to add arbitrary properties to a log message using ILogger.BeginScope(state), but the semantics of the method call are somewhat ill-defined. Consequently, in order for scope state to be used as correlation ID properties on the log message, the state must be an IEnumerable<KeyValuePair<string, object>>.

Manually creating a Dictionary<string,object> every time I wanted to add a correlation ID was a bit cumbersome, so I wrote a simple extension overload to BeginScope method that takes a string key and and object value. This extension simply initialises a Dictionary<string, object> behind the scenes, and calls to the underlying BeginScope<T> method. This makes the call site easier to read when you are adding a single key-value pair.