In my last post I gave an introduction to structured logging, and described how you can use scopes to add additional key-value pairs to log messages. Unfortunately, the syntax for key-value pairs using ILogger.BeginScope() can be a bit verbose, so I showed an extension method you can use to achieve the same result with a terser syntax.

In this post, I'll show some extension methods you can use to add multiple key-value pairs to a log message. To be honest, I'm not entirely convinced by any of them, so this post is more a record of my attempt rather than a recommendation! Any suggestions on ways to simplify / improve them are greatly received.

Background: the code to optimise

In the last post, I provided some sample code that we're looking to optimise. Namely, the calls to _logger.BeginScope() where we provide a dictionary of key-value pairs:

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");
        }
    }
}

I showed how we could optimise the second call, with a simple extension method that takes a string key and an object value as two separate parameters:

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

This overload simply wraps the creation of the Dictionary<string, object> required by Serilog / Seq to attach key-value pairs to a log message. With this overload, the second BeginScope() call is reduced to:

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

This post describes my attempts to generalise this, so you can pass in multiple key-value pairs. All of these extensions will wrap the creation of Dictionary<> so that Serilog (or any other structured logging provider) can attach the key-value pairs to the log message.

Attempt 1: BeginScope extension method using Tuples

It's worth noting, that if you're initialising a dictionary with several KeyValuePair<>s, the syntax isn't actually very verbose, apart from the new Dictionary<> definition. You can use the dictionary initialisation syntax {key, value} to add multiple keys:

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

I was hoping to create an overload for BeginScope() that had a similar terseness for the key creation, but without the need to explicitly create a Dictionary<> in the calling code.

My first thought was C# 7 tuples. KeyValuePairs are essentially tuples, so it seemed like a good fit. The following extension method accepts a params array of tuples, where the key value is a string and the value is an object:

public static class LoggerExtensions  
{
    public static IDisposable BeginScope(this ILogger logger, params (string key, object value)[] keys)
    {
        return logger.BeginScope(keys.ToDictionary(x => x.key, x => x.value));
    }
}

With this extension method, we could write our sample BeginScope() call as the following:

 using (_logger.BeginScope((key: nameof(productId), value: productId ), ( key: nameof(basketId), value: basketId)))

or even simpler, by omitting the tuple names entirely:

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

Initially, I was pretty happy with this. It's nice and concise and it achieves what I was aiming for. Unfortunately, it has some flaws if you try and use it with only a single tuple.

Overload resolutions with a single tuple

The BeginScope overload works well when you have multiple key-value pairs, but you would expect the behaviour to be the same no matter how many tuples you pass to the method. Unfortunately, if you try and call it with just a single tuple you'll be out of luck:

using (_logger.BeginScope((key: "transactionId", value: transaction.Id))  

We're clearly passing a tuple here, so you might hope our overload would be used. Unfortunately, the main ILogger.BeginScope<T>(T state) is a generic method, so it tends to be quite greedy when it comes to overload selection. Our tuple definition (string key, object value) state is less specific than the generic T state so it is never called. The transactionId value isn't added to the log as a correlation ID, instead it's serialised and added to the Scope property.

Changing our extension method to be generic ((string key, T value) state) doesn't work either; the main generic overload is always selected. How annoying.

Attempt 2: Avoiding overload resolution conflicts with Tuples

There's a simple solution to this problem: don't try and overload the ILogger.BeginScope<T>() method, just call it something else. For example, if we rename the extension to BeginScopeWith, then there won't be any overload resolution issues, and we can happily use single tuples without any issues:

public static class LoggerExtensions  
{
    public static IDisposable BeginScopeWith(this ILogger logger, params (string key, object value)[] keys)
    {
        return logger.BeginScope(keys.ToDictionary(x => x.key, x => x.value));
    }
}

By renaming the extension, we can avoid any ambiguity in method selection. That also gives us some compile-time safety, as only tuples that actually are (string key, object value) can be used:

using (_logger.BeginScopeWith((key: "transactionId", value: transactionId))) // <- explicit names  
using (_logger.BeginScopeWith(("transactionId", transactionId))) // <- names inferred  
using (_logger.BeginScopeWith((oops: "transactionId", wrong: transactionId))) // <- incorrect names ignored, only order and types matter  
using (_logger.BeginScopeWith((key: transactionId, value: "transactionId"))) // <- wrong order, won't compile  
using (_logger.BeginScopeWith(("transactionId", transactionId, basketId))) // <- to many items, wrong tuple type, won't compile  

That's about as far as I could get with tuples. It's not a bad compromise, but I wanted to try something else.

Attempt 3: Anonymous types as dictionaries of key value pairs

I only actually started exploring tuples after I went down this next avenue - using anonymous types as a Dictionary<string, object>. My motivation came from when you would specify additional HTML attributes using the HtmlHelper classes in ASP.NET Razor templates, for example:

@Html.InputFor(m => m.Name, new { placeholder = "Enter your name"})

Note You can still use Html Helpers in ASP.NET Core, but they have been largely superseded by the (basically superior in every way) Tag Helpers.

This syntax was what I had in mind when initially thinking about the problem. It's concise, it clearly contains key-value pairs, and it's familiar. The only problem is, converting an anonymous type to Dictionary<string, object> is harder than the Html Helpers make it seem!

Converting an anonymous type to a Dictionary<string, object>

Given I was trying to replicate the behaviour of the ASP.NET Html Helpers, checking out the source code seemed like a good place to start. I actually used the original ASP.NET source code, rather than the ASP.NET Core source code, but you can find similar code there too.

The code I found initially was for the HttpRouteValueDictionary. This uses a similar behaviour to the Html Helpers, in that it converts an object into a dictionary. It reads an anonymous type's properties, and uses the property name and values as key-value pairs. It also handles the case where the provided object is already a dictionary.

I used this class the basis for a helper method that converts an object into a dictionary (actually an IEnumerable<KeyValuePair<string, object>>):

public static IEnumerable<KeyValuePair<string, object>> GetValuesAsDictionary(object values)  
{
    var valuesAsDictionary = values as IEnumerable<KeyValuePair<string, object>>;
    if (valuesAsDictionary != null)
    {
        return valuesAsDictionary;
    }
    valuesAsDictionary = new Dictionary<string, object>();
    if (values != null)
    {
        foreach (PropertyHelper property in PropertyHelper.GetProperties(values))
        {
            // Extract the property values from the property helper
            // The advantage here is that the property helper caches fast accessors.
            valuesAsDictionary.Add(property.Name, property.GetValue(values));
        }
    }
    return valuesAsDictionary;
}

If the values object provided is already the correct type, we can just return it directly. Otherwise, we create a new dictionary and populate it with the properties from our object. This uses a helper class called PropertyHelper.

This is an internal helper class that's used both in the ASP.NET stack and in ASP.NET Core to extract property names and values from an object. It basically uses reflection to loop over an object's properties, but it's heavily optimised and cached. There's over 500 lines in the class, so I won't list it here, but at the heart of the class is a method that reflects over the provided object type's properties:

IEnumerable<PropertyInfo> properties = type  
    .GetProperties(BindingFlags.Public | BindingFlags.Instance)
    .Where(prop => prop.GetIndexParameters().Length == 0 && prop.GetMethod != null);

This is the magic that allows us to get all the properties as key-value pairs.

Using anonymous types to add scope state

With the GetValuesAsDictionary() helper method, we can now build an extension method that lets us use anonymous types to pass key-value pairs to the BeginScope method:

public static class LoggerExtensions  
{
    public static IDisposable BeginScopeWith(this ILogger logger, object values)
    {
        var dictionary = DictionaryHelper.GetValuesAsDictionary(values);
        return logger.BeginScope(dictionary);
    }
}

Unfortunately, we have the same method overload problem as we saw with the tuples. If we call the method BeginScope, then the "native" generic method overload will always win (unless you explicitly cast to object in the calling code - yuk), and our extension would never be called. The anonymous type object would end up serialised to the Scope property instead of being dissected into key-value pairs. We can avoid the problem by giving our extension a different name, but it does feel a bit clumsy.

Still, this extension means our using statements are a lot shorter and easier to read, even more so than the tuple syntax I think:

using (_logger.BeginScopeWith(new { productId = productId, basketId = basketId)))  
using (_logger.BeginScopeWith(new { transactionId = transaction.Id)))  

A downside is that we can't use nameof() expressions to avoid typos in the key names any more. Instead, we could use inference, which also gets rid of the duplication:

using (_logger.BeginScopeWith(new { productId, basketId)))  
using (_logger.BeginScopeWith(new { transactionId = transaction.Id)))  

Personally, I think that's a pretty nice syntax, which is much easier to read compared to the original:

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

Other possibilities

The main other possibility that came to mind for this was to use dynamic and ExpandoObject, given that these are somewhat equivalent to a Dictionary<string,object> anyway. After a bit of playing I couldn't piece together anything that really worked, but if somebody else can come up with something, I'm all ears!

Summary

It bugs me that there's no way of writing either the tuple-based or object-based extension methods as overloads of BeginScope, rather than having to create a new name. It's maybe a bit silly, but I suspect it means that in practice I just won't end up using them, even though I think the anonymous type version in particular is much easier to read than the original dictionary-based version.

Even so, it was interesting to try and tackle this problem, and to look through the code that the ASP.NET team used to solve it previously. Even if I / you don't use these extension methods, it's another tool in the coding belt should it be useful in a different situation. As always, let me know if you have any comments / suggestions / issues, and thanks for reading.