NLog - How to include custom context variables in all your logs, that will flow across over async points

Update: The Mdlc feature shown in this post is now part of NLog.

TL;DR:If you need to have custom context variables that will flow across async points, you can use the NLog.Contrib nuget package to have the MappedDiagnosticsLogicalContext class and the ${mdlc} layout render.

In my previous post, NLog: How to include custom context variables in all your logs, I presented the NLog.MappedDiagnosticsContext class and how can it be used to emit custom context variables to all of your logs. This class keeps a dictionary of strings in the thread local storage (TLS). When I want to emit always a given context property, I have to add this line of code

NLog.MappedDiagnosticsContext.Set("subscriptionid", SubscriptionId);

In this case the SubscriptionId is the custom context property that I will be attaching to all my log statements. For example, if you are in the context of Web API 2, you can set the property on a base controller, just like this

public override Task<HttpResponseMessage> ExecuteAsync(HttpControllerContext controllerContext, CancellationToken cancellationToken)
{
    if (User != null && User.Identity != null && User.Identity.IsAuthenticated)
        NLog.MappedDiagnosticsContext.Set("subscriptionid", CurrentSubscriptionId);
    else
        NLog.MappedDiagnosticsContext.Set("subscriptionid", null);

    Logger.Info("Begin Request {1} {0}", controllerContext.Request.RequestUri.PathAndQuery, controllerContext.Request.Method);
    return base.ExecuteAsync(controllerContext, cancellationToken);
}

We are overriding the ExecuteAsync method, which is the method that is invoked to start processing the request, and set the subscriptionid property for logging purposes. From this point, all logs will include this new property. My NLog target is defined in configuration as this

<target xsi:type="File" name="f" fileName="${basedir}/App_Data/Logs/App.log"
    layout="${longdate} [T:${threadid}] [L:${uppercase:${level}}] [S:${mdc:item=subscriptionid}] ${message} ${exception:format=tostring}" 
    archiveFileName="${basedir}/App_Data/Logs/Archive/App_${shortdate}.log"
    archiveEvery="Day"
    maxArchiveFiles="30"                
    />

The magic happens using the layout render ${mdc} ${mdc:item=subscriptionid}, which expands the property subscriptionid in the log statement. This is great, since to have the subscriptionid emitted in log files, I don't have to specify the subscriptionid property in all my Logger invocations. Layout renders are macros, and you can know more about layout renders here.

Now let's imagine this code in a ASP.Net Web API 2 controller

[HttpPut, Route("{id:int}/start")]
public async Task<IHttpActionResult> Start(int id) 
{
    Integration integration = await Db.MyIntegrations.FirstOrDefaultAsync(x => x.Id == id);
    if (integration == null) 
    {
        Logger.Warn("The user is trying to start an integration with id={0}, which it doesn't belongs to him", id); 
        return NotFound();
    }  
    
    integration.IsActive = true;
    await Db.SaveChangesAsync();

    Logger.Info("Integration {0} is now active and will start to process", id);

    return Ok();
}

What I want to notice here is, first that I am using async API, and second that I am using Entity Framework 6, which already supports async API, which means that the code in this action will eventually jump from thread to thread while processing the current request. So, the action will start to process in a given thread, and while it is awaiting for the first database call FirstOrDefaultAsync, the thread will be released to the thread pool instead of being blocked awaiting for the database to return. When the database returns, the action will continue to run in another thread from the thread pool. The same process happens when invoking the method SaveChangesAsync. The major advantage of this async paradigm, is scalability, releasing threads that are not doing any job, allowing to use them to process otherrequests. Do not think that your code will run faster by using the async API.

So, the web request will be served using different threads, and this is a problem to my main goal of having the subscriptionid in all my logs. Why? Because the MappedDiagnosticsContext class uses the thread local storage (TLS) to keep the dictionary with the properties, and the TLS does not flow across over async points, which means that when the first database call returns, the thread that will run the continuation it will not have anymore the subscriptionid in the TLS. This behavior relates how .Net deals with ExecutionContext, which is not an easy subject.

To achieve our goal we need to store the dictionary in something that will flow across async points. One possible solution is to use the ancient CallContext. Let's do this in a new class that I will name MappedDiagnosticaLogicalContext

 namespace NLog 
 {
    public static class MappedDiagnosticsLogicalContext
    {
        private const string LogicalContextDictKey = "NLog.MappedDiagnosticsLogicalContext";

        private static IDictionary<string, string> LogicalContextDict
        {
            get
            {
                var dict = CallContext.LogicalGetData(LogicalContextDictKey) as ConcurrentDictionary<string, string>;
                if (dict == null)
                {
                    dict = new ConcurrentDictionary<string, string>();
                    CallContext.LogicalSetData(LogicalContextDictKey, dict);
                }
                return dict;
            }
        }

        public static void Set(string item, string value)
        {
            LogicalContextDict[item] = value;
        }

        public static string Get(string item)
        {
            string s;

            if (!LogicalContextDict.TryGetValue(item, out s))
            {
                s = string.Empty;
            }

            return s;
        }
    }
 }

Now we can rewrite our base controller to use this class instead of the class MappedDiagnosticsContext

NLog.MappedDiagnosticsLogicalContext.Set("subscriptionid", SubscriptionId);

But we also need a custom layout render that can read and expand this items

 namespace NLog.LayoutRenderers
 {
    [LayoutRenderer("mdlc")]
    public class MdlcLayoutRenderer : LayoutRenderer
    {
        [RequiredParameter]
        [DefaultParameter]
        public string Item { get; set; }

        protected override void Append(StringBuilder builder, LogEventInfo logEvent)
        {
            string msg = MappedDiagnosticsLogicalContext.Get(this.Item);
            builder.Append(msg);
        }
    }
 }

This new layout render can be used like this ${mdlc:item=subscriptionid} (mdlc means mapped diagnostics logical context). We need to change our NLog config file, replacing all ocurrences of ${mdc:} by ${mdlc:}.

Finally, and since we are using a custom layout render we have to register it, in the startup of the application

NLog.Config.ConfigurationItemFactory.Default.LayoutRenderers.RegisterDefinition("mdlc", typeof(MdlcLayoutRenderer));

I made a pull request to NLog.Contrib project to incorporate this new feature, and it was already merged and incorporated it in the NuGet NLog.Contrib. So, just grab the Nuget and start using without the need to know the internals.