NLog: How to include custom context variables in all your logs

Logging is a very important aspect of every application. There are a lot of logging frameworks available for the .Net platform, and I won't discuss which one is better. Many times it is a matter of taste. For example, if we are .Net developers but develop for Java as well, it makes sense to choose Log4Net since it is port of the well known Log4j, so you can capitalize your knowlodge in both platforms.

In the past I've used a lot Log4Net, but nowadays, my logging framework of choice is NLog. For the vast majority of scenarios there is no big difference between platforms, but since NLog was written entirely with .Net in mind, I tend to prefer NLog. Both platforms have great community support and there are a lot of configuration choices available for different scenarios (file logging, sql logging, etc.)

In this post I would like to show you a not very well known feature, in which we can include some custom context variables in our log statements, without the need to specify the variables every time we are emiting the log.

Here is the scenario: we are developing a SaaS web application, and we want to include in all our logs the subscription id, for all web requests.The subscription id identities univocally the subscription that is issuing the web request.

Introducing Mapped Diagnostics Context

From the NLog documentation

Mapped Diagnostics Context is a thread local structure that keeps a dictionary of strings and provides methods to output them in layouts

Here is the code we have write to add a key to this dictionary

NLog.MappedDiagnosticsContext.Set("subscriptionid", subscriptionId.ToString());

After running this line of code, the key subscriptionid is available in the thread local structure. We now need to configure our logging layout to include this key in our logs. Here is a typical configuration

To include the subscription id in the logs we've just used ${mdc:item=subscriptionid}

We can now to grep/find all logs for a given "suspicious" subscription. Let me check some suspicious activity on subscription 25

grep "[S:25]" *.log 

When to set Mapped Diagnostics Context

We wish to set our mapped diagnostics context keys as soon as possible. For example, if your application is an Asp.Net MVC application, you can set at the beginning of your action, or as an alternative, in an action filter.

Is this works with async/await?

One thing to notice about MappedDiagnosticsContext is that is a dictionary stored in thread local storage (TLS). This is very important to perceive, in particular if you are in a multi-thread environment. Even if you are using the new paradigm of async and await for asynchronous programing, which is awesome and makes extremely easy for the developer to program in asynchronous way, we have to understand that the TLS does not flow in async points. This means that we will loose this information as soon as we get another thread different from the one where we set the value.

So, how can we make this works with async/await, and guarante that we have always our subscription id in our logs, even if a web request is served by multiple threads during the lifecycle of the request? Basically, we will have to use a different storage from the TLS, one that flows in async poinst. We can use the CallContext. In my next post I will show you how to implement this feature.

Btw, if you are using Log4net, it is already supported out of the box with contexts.

Log4Net supports different scope contexts:

• Global (log4net.GlobalContext) - The global context is shared by all threads in the current AppDomain. This context is thread safe for use by multiple threads concurrently. The NLog equivalent is the NLog.GlobalDiagnosticsContext
• Thread (log4net.ThreadContext) - The thread context is visible only to the current managed thread. The NLog equivalent is the NLog.MappedDiagnosticsContext.
• LogicalTread (log4net.ThreadLogicalContext). The logical thread context is visible to a logical thread. Logical threads can jump from one managed thread to another. For more details see the .NET API System.Runtime.Remoting.Messaging.CallContext.

I haven't figured the equivalent in NLog to the log4net.ThreadLogicalContext. So I had to implement it in my current project. Wait for the next post.