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

I am using NLog 4.3.5 and .Net framework 4.6.1

When I start the server side operation, I call:

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

This is displayed and displayed in my log files. All is well .... or is it not? When viewing my log files, I noticed that this id value of the operation does not work as I expected.

Example:

  • In thread 19, the operation begins and sets the context.

  • It uses .ConfigureAwait (false) for all pending calls

  • He performs

     var tasks = items.Select(item => Task.Run( () => { /* do stuff */} await Task.WhenAll(tasks).ConfigureAwait(false) 
  • One of the threads used for these tasks is thread 31 (remember this later)
  • Meanwhile, in thread 36, another server method is called and a new operation begins. Multiple log messages written with a unique operation identifier
  • This operation makes 2 different wait calls using ConfigureAwait (false)
  • The next log statement occurs on stream 31. From that moment, it registers the identifier of the operation that was created for the operation that started on stream 19!

I did not expect this to happen, and I do not know how this happened. But looking through the history of the magazine, I see that this kind of thing happened before.

I thought the boolean call context should have carried over. Can I use ConfigureAwait (false), which causes this behavior? This is the only thing I can think of ....

+6
source share
2 answers

Found what I consider a problem. https://github.com/NLog/NLog/issues/934

+2
source

You can get 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 )); } 

Use in configuration file:

 ${mdlc2:OperationId} 
+1
source

All Articles