Nlog: MappedDiagnosticsLogicalContext clears value?

Created on 1 Jul 2016 · 7Comments · Source: NLog/NLog

Type (choose one):

Question

NLog version: 4.3.5

Platform: .Net 4.5.2

Current NLog config (xml or C#, if relevant)

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
      autoReload="true"
      throwExceptions="false"
      internalLogLevel="Off" internalLogFile="c:\temp\nlog-internal.log" >
  <variable name="myvar" value="myvalue"/>
  <targets>
    <target xsi:type="File" name="f" fileName="${basedir}/logs/${shortdate}.log"
            layout="TimeStamp=${longdate} CorrelationId=${mdlc:item=correlationid} Level=${uppercase:${level}} Message=${message}" />
  </targets>
  <rules>
    <logger name="*" minlevel="Debug" writeTo="f" />
  </rules>
</nlog>

I am using MappedDiagnosticsLogicalContext to track flow of requests in my ASP NET MVC 5 application. Every request goes through LoggingHttpModule where I set correlationId variable like that

private void HandleBeginRequest(object sender, EventArgs e)
        {
                        // rest of the code omitted
            MappedDiagnosticsLogicalContext.Set("correlationid", Guid.NewGuid().ToString());
            Logger.Info($"About to start {httpContext.Request.HttpMethod}{httpContext.Request.RawUrl} request");
        }

when the requests ends I also log it in LoggingHttpModule

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

Result of logging looks ok when I don't create new threads in controllers actions

TimeStamp=2016-06-30 21:52:04.8772 CorrelationId=9a6113c3-a41a-400e-ab5a-8b8c10ae7d10 Level=INFO Message=About to start GET /Home/SecondContact request
TimeStamp=2016-06-30 21:52:04.8932 CorrelationId=9a6113c3-a41a-400e-ab5a-8b8c10ae7d10 Level=INFO Message=Information
TimeStamp=2016-06-30 21:52:09.1750 CorrelationId=9a6113c3-a41a-400e-ab5a-8b8c10ae7d10 Level=INFO Message=Request completed with status code: 200

However if action in controller process some stuff in new thread correlationId is lost when request is finished. So the result looks like that

TimeStamp=2016-06-30 21:52:19.1390 CorrelationId=e939d03d-fa1b-407d-8b68-2d829257d895 Level=INFO Message=About to start GET /Home/Contact request
TimeStamp=2016-06-30 21:52:19.1480 CorrelationId=e939d03d-fa1b-407d-8b68-2d829257d895 Level=INFO Message=Log from Contact action, from thread=6
TimeStamp=2016-06-30 21:52:19.1560 CorrelationId=e939d03d-fa1b-407d-8b68-2d829257d895 Level=INFO Message=Log from thread assigned by scheduler 7
TimeStamp=2016-06-30 21:52:19.1560 CorrelationId=e939d03d-fa1b-407d-8b68-2d829257d895 Level=INFO Message=Log from continuation from thread 7
TimeStamp=2016-06-30 21:52:19.1720 CorrelationId=e939d03d-fa1b-407d-8b68-2d829257d895 Level=INFO Message=Log from explicitly created thread 11
TimeStamp=2016-06-30 21:52:31.1529 CorrelationId= Level=INFO Message=Request completed with status code: 200

Note that CorrelationId is empty in last entry. There is nothing particularly interesting in internal logs so I am not sure if I am doing sth wrong or this is a bug. Can someone advise?
PS
The code can be found https://github.com/tpodolak/Blog/tree/master/AspNetMvcLoggingWithCorrelationId

question

Source