NLog – tracking flow of requests using MappedDiagnosticsLogicalContext

1. Problem

Everyone who has ever had to analyze logs from production environment knows, that quite often it is not an easy task. Usually application flow is deduced by log entries matched by thread id, which is problematic when you deal with multithreading scenarios. Say for example we have following piece of code

Default log file usually looks like that

Having multiple simultaneous Index requests, makes it almost impossible to figure out which log entry is part of which call. Fortunately with NLog it is possible to solve this problem without too much of a hassle.

2. Proposed solution

The whole idea is to leverage MappedDiagnosticsLogicalContext “storage” to keep some unique identifier of request for entire call. Note, that this identifier will be accessible also from other threads created from within given call. In order to set unique request id (also known as correlation id) I will use custom HttpModule. The very first implementation looks like that

Once the HttpModule is ready it is necessary to register it in web.config.

From now on, every request goes through LogginHttpModule and proper correlationId is set in MappedDiagnosticsLogicalContext.
As we want to have correlationId included in log files it is necessary to modify Nlog.config. In my case it looks like that

Note that we can access our correlationId variable via ${mdlc:item=correlationid}
Log file after the changes looks like that

This is almost perfect, however for some reasons correlationId is lost in EndRequest event handler. I am not sure if this is bug in NLog (I’ve posted question in Nlog’s github) or it is by design, however there is easy workaround for that. We can store our correlationId in HttpContext.Items collection and reassign it to MappedDiagnosticsLogicalContext in EndRequest event handler.

After these changes our log file finally looks OK

Source code for this post can be found here

NLog – tracking flow of requests using MappedDiagnosticsLogicalContext