LogManager.Configuration.Variables throws in high traffic

[nibblesnbits]

Type: Bug

NLog version: 4.5.10

NLog.Web/NLog.Web.AspNetCore version: 4.7.0

Platform: .NET Core 2.2

Current NLog config

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      autoReload="true"
      internalLogLevel="info"
      internalLogFile="C:\tmp\nlog\internal.txt">

  <extensions>
    <add assembly="NLog.Web.AspNetCore" />
  </extensions>

  <targets>
    <target xsi:type="File" name="web" fileName=".\logs\${shortdate}.log"
            layout="${longdate}|${var:requestId}|${uppercase:${level}}|${message} ${exception:format=tostring}|url: ${aspnet-request-url}" />
  </targets>

  <rules>

    <logger name="Microsoft.*" maxLevel="Info" final="true" />
    <logger name="*" minlevel="Trace" writeTo="web" />
  </rules>
</nlog>

• What is the current result?
  Exception 2019-09-17 13:57:57.8658||ERROR|Connection id "0HLPREORAFF1D", Request id "0HLPREORAFF1D:00000003": An unhandled exception was thrown by the application. System.InvalidOperationException: Operations that change non-concurrent collections must have exclusive access. A concurrent update was performed on this collection and corrupted its state. The collection's state is no longer correct.
  at System.Collections.Generic.Dictionary2.TryInsert(TKey key, TValue value, InsertionBehavior behavior) at System.Collections.Generic.Dictionary2.set_Item(TKey key, TValue value)
  at Ecp.CmsApi.Startup.<>c.b__6_0(HttpContext c, Func1 n) in /home/vsts/work/1/s/EcpCmsApiFacade/EcpCmsApiFacade/Startup.cs:line 167 at Microsoft.AspNetCore.Builder.UseExtensions.<>c__DisplayClass0_1.<Use>b__1(HttpContext context) at Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware.Invoke(HttpContext context) at Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware.Invoke(HttpContext httpContext) at Microsoft.AspNetCore.Hosting.Internal.HostingApplication.ProcessRequestAsync(Context context) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication1 application)|url: http://api.ecpinc.net/js/main.chunk.js

• What is the expected result?
  Setting of a configuration variable succeeds

• Did you checked the Internal log?
  Currently Unable

• Please post full exception details (message, stacktrace, inner exceptions)
  2019-09-17 13:57:57.8658||ERROR|Connection id "0HLPREORAFF1D", Request id "0HLPREORAFF1D:00000003": An unhandled exception was thrown by the application. System.InvalidOperationException: Operations that change non-concurrent collections must have exclusive access. A concurrent update was performed on this collection and corrupted its state. The collection's state is no longer correct.
  at System.Collections.Generic.Dictionary2.TryInsert(TKey key, TValue value, InsertionBehavior behavior) at System.Collections.Generic.Dictionary2.set_Item(TKey key, TValue value)
  at Ecp.CmsApi.Startup.<>c.b__6_0(HttpContext c, Func1 n) in /home/vsts/work/1/s/EcpCmsApiFacade/EcpCmsApiFacade/Startup.cs:line 167 at Microsoft.AspNetCore.Builder.UseExtensions.<>c__DisplayClass0_1.<Use>b__1(HttpContext context) at Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware.Invoke(HttpContext context) at Microsoft.AspNetCore.Hosting.Internal.RequestServicesContainerMiddleware.Invoke(HttpContext httpContext) at Microsoft.AspNetCore.Hosting.Internal.HostingApplication.ProcessRequestAsync(Context context) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication1 application)|url: http://api.ecpinc.net/js/main.chunk.js

• Are there any workarounds? yes/no
  Unkown

• Is there a version in which it did work?
  No

• Can you help us by writing an unit test?
  Not sure how to replicate this in a unit test

NOTES

The code causing this is pretty simple:

public void Configure(IApplicationBuilder app, IHostingEnvironment env) {

            app.Use((c, n) => {
                // the line below throws
                LogManager.Configuration.Variables["requestId"] = Guid.NewGuid().ToString("n");
                return n();
            });

I'm guessing if LogManager.Configuration.Variables is changed to a System.Collections.Concurrent.ConcurrentDictionary<TKey, TValue> this issue would go away, but that's probably a non-trivial change. It only occurs on my production server when there's far more traffic.

[snakefoot]

ThreadSafeDictionary has been introduced for NLog Config Variables with NLog ver. 4.6.4. See also NLog/NLog#3430

[snakefoot]

@nibblesnbits But it looks like you are trying to save the RequestId for the HttpRequest in the global NLog Config Variable using AspNetCore Middleware. This will not work if you have an application that handles more than one HttpRequest at a time (Cannot have two active requestids in the same global variable).

I would suggest that you make use of MEL-BeginScope or NLog MappedDiagnosticsLogicalContext.

An even better approach for capturing HttpContext-information is to make use of the army of ${aspnet}-layoutrenderers in your NLog-target-output. Maybe just make use of ${aspnet-traceidentifier} ?

[snakefoot]

Reading the documentation for ASP.NET Core. Then you could also do this:

        app.Use(async (context, next) =>
        {
            context.Items["myRequestId"] = Guid.NewGuid().ToString("n");
            // Call the next delegate/middleware in the pipeline
            await next();
        });

Then add ${aspnet-item:variable=myRequestId} to your NLog target ouput.

You can probably also do this:

        app.Use(async (context, next) =>
        {
           using (NLog.MappedDiagnosticsLogicalContext.SetScoped("myRequestId", Guid.NewGuid().ToString("n"))
           {
                // Call the next delegate/middleware in the pipeline
               await next();
           }
        });

And extract it like this ${mdlc:item=myRequestId}

Did you know that AspNetCore by default automatically capture requestid as BeginScope-property if you register NLog as MEL LoggingProvider by calling UseNLog() ? It can be extracted like this: ${mdlc:item=RequestId}

NLog JsonLayout has the IncludeMdlc-property that will make it automatically output all captured MDLC-variables.

[nibblesnbits]

I'll give these options a shot. I'm thinking all I need is the ${aspnet-traceidentifier}, actually, so thank you so much.