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

public class HomeController : Controller
{
    private static readonly Logger Logger = LogManager.GetCurrentClassLogger();
    
    public async Task<ActionResult> Index()
    {
        await PreprocessRequest(nameof(Index));
        return View();
    }
    
    private static async Task PreprocessRequest(string actionName)
    {
        Logger.Info($"Log from {actionName} action, from thread={Thread.CurrentThread.ManagedThreadId}");
        
        await Task.Run(() => Logger.Info($"Log from {actionName}, from thread {Thread.CurrentThread.ManagedThreadId} assigned by scheduler"))
                  .ConfigureAwait(continueOnCapturedContext: false);
        Logger.Info($"Log from {actionName} action, from async continuation, from thread {Thread.CurrentThread.ManagedThreadId}");
               
        var thread =
            new Thread(() => Logger.Info($"Log from {actionName} action, from explicitly created thread {Thread.CurrentThread.ManagedThreadId}"));
        thread.Start();
        thread.Join();
    }
}

public class HomeController : Controller

{

private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

public async Task<ActionResult> Index()

{

await PreprocessRequest(nameof(Index));

return View();

}

private static async Task PreprocessRequest(string actionName)

{

Logger.Info($"Log from {actionName} action, from thread={Thread.CurrentThread.ManagedThreadId}");

await Task.Run(() => Logger.Info($"Log from {actionName}, from thread {Thread.CurrentThread.ManagedThreadId} assigned by scheduler"))

.ConfigureAwait(continueOnCapturedContext: false);

Logger.Info($"Log from {actionName} action, from async continuation, from thread {Thread.CurrentThread.ManagedThreadId}");

var thread =

new Thread(() => Logger.Info($"Log from {actionName} action, from explicitly created thread {Thread.CurrentThread.ManagedThreadId}"));

thread.Start();

thread.Join();

}

Default log file usually looks like that

TimeStamp=2016-07-03 11:56:02.2327 ThreadId=5 Level=INFO Message=About to start GET / request
TimeStamp=2016-07-03 11:56:02.3797 ThreadId=5 Level=INFO Message=Log from Index action, from thread=5
TimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index, from thread 6 assigned by scheduler
TimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index action, from async continuation, from thread 6
TimeStamp=2016-07-03 11:56:02.3917 ThreadId=14 Level=INFO Message=Log from Index action, from explicitly created thread 14
TimeStamp=2016-07-03 11:56:04.8250 ThreadId=8 Level=INFO Message=Request completed with status code: 200

TimeStamp=2016-07-03 11:56:02.2327 ThreadId=5 Level=INFO Message=About to start GET / request

TimeStamp=2016-07-03 11:56:02.3797 ThreadId=5 Level=INFO Message=Log from Index action, from thread=5

TimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index, from thread 6 assigned by scheduler

TimeStamp=2016-07-03 11:56:02.3797 ThreadId=6 Level=INFO Message=Log from Index action, from async continuation, from thread 6

TimeStamp=2016-07-03 11:56:02.3917 ThreadId=14 Level=INFO Message=Log from Index action, from explicitly created thread 14

TimeStamp=2016-07-03 11:56:04.8250 ThreadId=8 Level=INFO Message=Request completed with status code: 200

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

public class LoggingHttpModule : IHttpModule
{
    private const string CorrelationIdKey = "correlationid";

    private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

    public void Init(HttpApplication context)
    {
        context.BeginRequest += HandleBeginRequest;
        context.EndRequest += HandleEndRequest;
    }

    public void Dispose()
    {
    }

    private void HandleBeginRequest(object sender, EventArgs e)
    {
        var value = Guid.NewGuid().ToString();
        var httpApplication = (HttpApplication) sender;
        var httpContext = httpApplication.Context;
        MappedDiagnosticsLogicalContext.Set(CorrelationIdKey, value);
        Logger.Info($"About to start {httpContext.Request.HttpMethod} {httpContext.Request.RawUrl} request");
    }

    private void HandleEndRequest(object sender, EventArgs e)
    {
        var httpApplication = (HttpApplication) sender;
        var httpContext = httpApplication.Context;
        Logger.Info($"Request completed with status code: {httpContext.Response.StatusCode} ");
    }
}

public class LoggingHttpModule : IHttpModule

{

private const string CorrelationIdKey = "correlationid";

private static readonly Logger Logger = LogManager.GetCurrentClassLogger();

public void Init(HttpApplication context)

{

context.BeginRequest += HandleBeginRequest;

context.EndRequest += HandleEndRequest;

}

public void Dispose()

{

}

private void HandleBeginRequest(object sender, EventArgs e)

{

var value = Guid.NewGuid().ToString();

var httpApplication = (HttpApplication) sender;

var httpContext = httpApplication.Context;

MappedDiagnosticsLogicalContext.Set(CorrelationIdKey, value);

Logger.Info($"About to start {httpContext.Request.HttpMethod} {httpContext.Request.RawUrl} request");

}

private void HandleEndRequest(object sender, EventArgs e)

{

var httpApplication = (HttpApplication) sender;

var httpContext = httpApplication.Context;

Logger.Info($"Request completed with status code: {httpContext.Response.StatusCode} ");

}

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

<!--rest of the code omitted -->
<system.webServer>
  <modules>
  <!--rest of the code omitted -->
    <add name="LoggingHttpModule" type="AspNetMvcLoggingWithCorrelationId.HttpModules.LoggingHttpModule"/>
  </modules>
</system.webServer>
<!--rest of the code omitted -->
<system.web>
<!--rest of the code omitted -->
  <httpModules>
  <!--rest of the code omitted -->
    <add name="ApplicationInsightsWebTracking" type="Microsoft.ApplicationInsights.Web.ApplicationInsightsHttpModule,Microsoft.AI.Web"/>
  </httpModules>
</system.web>