NLog MappedDiagnosticsLogicalContext not working in async/await with ConfigureAwait(false)

Question

I am using NLog 4.3.5 and .Net framework 4.6.1

When I begin a server side operation I call:

NLog.MappedDiagnosticsLogicalContext.Set("OperationId", Guid.NewGuid());

This gets mapped through and appears in my log files. All is good.... or is it? When reviewing my log files, I noticed that this operation id value doesn't seem to be working as I expected it to.

Example:

1. In thread 19 an operation begins and sets the context.

2. It uses .ConfigureAwait(false) on all await calls

3. It performs a

   var tasks = items.Select(item => Task.Run( () => { /* do stuff */}
   await Task.WhenAll(tasks).ConfigureAwait(false)
   

4. One of the threads used for these tasks is thread 31 (keep that in mind for later)
5. Meanwhile, in thread 36, a different server method is called and begins a new operation. Several log messages are written with it's unique operation id
6. This operation performs 2 different await calls with ConfigureAwait(false)
7. The next log statement occurs on thread 31. From then on, it logs the operation id that was created for the operation that began on thread 19!

I did not expect this to happen and am unsure of how it happened. But, as I look through my log history, I see that this type of thing has happened before.

I thought the logical call context was supposed to carry over. Is it my use of ConfigureAwait(false) that is causing this behavior? That is the only thing I can think of....

Answer 1

Found what I believe is the problem. https://github.com/NLog/NLog/issues/934

Answer 2

You could work around this as follows:

public static class LogicalThreadContext  
{ 
    private const string KeyPrefix = "NLog.LogicalThreadContext"; 

    private static string GetCallContextKey(string key)
    {
        return string.Format("{0}.{1}", KeyPrefix, key);
    }

    private static string GetCallContextValue(string key)
    {
        return CallContext.LogicalGetData(GetCallContextKey(key)) as string ?? string.Empty;
    }

    private static void SetCallContextValue(string key, string value)
    {
        CallContext.LogicalSetData(GetCallContextKey(key), value);         
    }

    public static string Get(string item)
    {
        return GetCallContextValue(item);
    }

    public static string Get(string item, IFormatProvider formatProvider)
    {
        if ((formatProvider == null) && (LogManager.Configuration != null))
        {
            formatProvider = LogManager.Configuration.DefaultCultureInfo;
        }

        return string.Format(formatProvider, "{0}", GetCallContextValue(item));
    }

    public static void Set(string item, string value)
    {
        SetCallContextValue(item, value);
    }
}

[LayoutRenderer("mdlc2")]
public class LogicalThreadContextLayoutRenderer : LayoutRenderer
{
   [DefaultParameter]
   public bool Name {get;set;}

    protected override void Append(StringBuilder builder, LogEventInfo logEvent)
    {
        builder.Append(LogicalThreadContext.Get(Name, null));
    }
}

//or application_start for ASP.NET 4
static void Main(string[] args) 
{ 
    //layout renderer
    ConfigurationItemFactory.Default.LayoutRenderers
          .RegisterDefinition("mdlc2", typeof(LogicalThreadContextLayoutRenderer ));
}

Usage in the config file:

${mdlc2:OperationId}