Nlog: Async: NLog is swallowing log messages, even with overflowAction="Block"

[ColinNg]

Hi,

When I put an AsyncWrapper around a slow target like AzureBlobStorage, even though I specify overflowAction="Block", the end result is that I lose a majority of the log messages.

NLog version: 4.7.4

Platform: .NET 4.6.1

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

<?xml version="1.0" encoding="utf-8" ?>
<!-- NOTE:  'throwExceptions' turned ON so we can quickly diagnose configuration glitches -->
<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"
      internalLogFile="D:\home\LogFiles\NLog\nlog-internal.log" internalLogLevel="Trace"
      autoReload="true">

  <!-- optional, add some variables
  https://github.com/nlog/NLog/wiki/Configuration-file#variables
  -->

  <variable name="logDirectory" value="${when:when='${environment:HOME}'=='':inner=${basedir}:else=${environment:HOME}}/LogFiles/NLog" />
  <variable name="commonLayout" value="${longdate:universalTime=True}|${pad:${uppercase:${level}}:padding=5:fixedLength=True}|CID:${mdlc:item=VideoIQ.Cloud.Logging.CorrelationId}|OrigMsgId:${mdlc:item=Avigilon.Cloud.Logging.OriginalMessageId}|${message}|TenandId:${mdlc:item=Avigilon.Cloud.Logging.TenantId}|UserId:${mdlc:item=Avigilon.Cloud.Logging.UserId}|SiteId:${mdlc:item=Avigilon.Cloud.Logging.SiteId}|GatewayId:${mdlc:item=Avigilon.Cloud.Logging.GatewayId}|ServerId:${mdlc:item=Avigilon.Cloud.Logging.ServerId}|ClipId:${mdlc:item=Avigilon.Cloud.Logging.ClipId}|ActivityId:${mdlc:item=Avigilon.Cloud.Logging.ActivityId}|EventId:${mdlc:item=Avigilon.Cloud.Logging.EventId}|BlobUri:${mdlc:item=Avigilon.Cloud.Logging.BlobUri}|${logger}|${machinename}|${appdomain}|[${threadname}(${threadid})] ${onexception:${newline}EXCEPTION\:${exception:format=tostring,Data:maxInnerExceptionLevel=10}}" />

  <extensions>
    <add assembly="VideoIQ.Cloud.Core" />
    <add assembly="NLog.Extensions.AzureBlobStorage" />
  </extensions>

  <!--
  See https://github.com/nlog/nlog/wiki/Configuration-file
  for information on customizing logging rules and outputs.
   -->
  <targets>

    <!--
    add your targets here
    See https://github.com/nlog/NLog/wiki/Targets for possible targets.
    See https://github.com/nlog/NLog/wiki/Layout-Renderers for the possible layout renderers.
    -->

    <target name="AsyncWrappedAzureBlobStorage" xsi:type="AsyncWrapper"
           overflowAction="Block"
           queueLimit="10000"
           batchSize="200"
           timeToSleepBetweenBatches="0">
      <target xsi:type="AzureBlobStorage"
              name="AzureBlobStorage"
              layout="${commonLayout}"
              connectionString="DefaultEndpointsProtocol=https;AccountName=blueduckops;AccountKey=(redacted);EndpointSuffix=core.windows.net"
              container="bkg-logs"
              blobName="${machinename}/${logger}/${date:universalTime=true:format=yyyy-MM-dd}/${date:universalTime=true:format=hh}.log" />
    </target>

    <target name="PerfTestSummary" xsi:type="File"
        layout="${commonLayout}"
        fileName="${logDirectory}/BackgroundProcessingWebJob.PerfTest.Summary.${machinename}.log"
        archiveFileName="${logDirectory}/LogArchives/BackgroundProcessingWebJob.PerfTest.Summary.${machinename}.{#####}.log"
        archiveAboveSize="209715200"
        concurrentWrites="false"
        keepFileOpen="false"
        autoFlush="false"
        encoding="utf-8"
            />

  </targets>



  <rules>
    <!-- These are very noisy and have been disabled with no writeTo -->
    <logger name="Verbose.VideoIQ.Cloud.DataModel.DeviceModelContext" level="Trace" final="true" />
    <logger name="*_Secret" final="true" />
    <logger name="*_Verbose" final="true" />

    <!--Specific to help diagnose these Exceptions -->
    <logger name="VideoIQ.Cloud.DataModel.DbRetryHandler.DbConcurrencyException" level="Warn" final="true" writeTo="FilePerInstanceRolling" />

    <!-- Only write auditing to a file -->
    <logger name="auditing" minlevel="Info" writeTo="auditfile" final="true" />

    <!-- Specific to NLog PerfTest -->
    <logger name="NLogTest.Program_AzureBlobStorage" levels="Info,Debug,Trace,Warn,Error,Fatal" writeTo="AzureBlobStorage" final="true" />
    <logger name="NLogTest.Program_AsyncWrappedAzureBlobStorage" levels="Info,Debug,Trace,Warn,Error,Fatal" writeTo="AsyncWrappedAzureBlobStorage" final="true" />
    <logger name="NLogTest.Program_PerfTestSummary" levels="Info,Debug,Trace,Warn,Error,Fatal" writeTo="PerfTestSummary" final="true" />

    <!--
    Write all events with minimal level of Debug (So Debug, Info, Warn, Error and Fatal, but not Trace)  to "f"
    -->
    <logger name="*.Timing" minlevel="Info" writeTo="appInsightsTarget" />
    <logger name="*" minlevel="Debug" writeTo="appInsightsTarget" />

    <logger name="VideoIQ.*" minlevel="Debug" writeTo="FilePerInstanceRolling" final="true" />
    <logger name="Avigilon.*" minlevel="Debug" writeTo="FilePerInstanceRolling" final="true" />
    <logger name="*" minlevel="Debug" writeTo="FilePerInstanceRolling" final="true" />
  </rules>
</nlog>

• What is the current result?
  Logs are written to AzureBlobStorage, but many log items are missing. It seems to write out batches of 100, skipping many batches in between.

In the second comment I include a script that analyzes the resulting log files and outputs this summary. It shows lines 1-200 were logged, but 201-1000 are missing, etc.

Iteration | Start | End
------------|-------|-------
0 | 1 | 200
0 | 1001 | 1100
0 | 2001 | 2100
0 | 3001 | 3100
0 | 4001 | 4100
0 | 6001 | 6100
0 | 16001 | 16100
0 | 26001 | 26100
0 | 38001 | 38100

• What is the expected result?
  All 600 iterations (0-599) will output all 38,476 lines of The Hobbit into the Azure Blob Storage files.

• Did you checked the Internal log?
  It says:

...
2020-09-03 16:40:43.0285 Debug Async queue is full
2020-09-03 16:40:43.0285 Debug Discarding one element from queue
2020-09-03 16:40:43.0441 Trace AsyncWrapper(Name=AsyncWrappedAzureBlobStorage): Writing 200 events (Timer)
2020-09-03 16:40:43.0441 Trace AzureBlobStorageTarget: Using provided blob name: RD501AC56A914E/NLogTest.Program_AsyncWrappedAzureBlobStorage/2020-09-03/04.log
2020-09-03 16:40:43.0441 Trace Entered critical section.
2020-09-03 16:40:43.0441 Debug Async queue is full
2020-09-03 16:40:43.0441 Trace Async queue limit ok.
2020-09-03 16:40:43.0441 Debug Discarding one element from queue
2020-09-03 16:40:43.0597 Debug Async queue is full
2020-09-03 16:40:43.0597 Debug Async queue is full
2020-09-03 16:40:43.0597 Debug Blocking because the overflow action is Block...
2020-09-03 16:40:43.0754 Debug Discarding one element from queue
2020-09-03 16:40:43.0754 Debug Async queue is full
2020-09-03 16:40:43.0754 Debug Discarding one element from queue
...

• Please post full exception details (message, stacktrace, inner exceptions)
  Message (from internal log)

2020-09-03 16:40:43.0597 Debug Async queue is full
2020-09-03 16:40:43.0597 Debug Blocking because the overflow action is Block...
2020-09-03 16:40:43.0754 Debug Discarding one element from queue

There was no stacktrace or exceptions (none related to this issue - there is an unrelated configuration glitch with including one of my company's DLLs but it does not affect the test).

• Are there any workarounds? no
• Is there a version in which it did work? no (I tried 4.6.8 and 4.4.11, and for the extension, tried the current 2.4.0 and previous 2.3.0)
• Can you help us by writing an unit test?
  Would love to, but I don't yet know how to repro this except by a sample app, because it involves configuring a slow (external) plugin.

NLogTest.zip

[welcome[bot]]

Hi! Thanks for opening your first issue here! Please make sure to follow the issue template - so we could help you better!

[ColinNg]

Deploy the code to Azure App Service as a WebJob, and then start the webjob. It will run for a few minutes and output logs to the specified Azure Blob Storage.

Attached please find a LINQPad script will read the log files and output a summary of the lines that are present in the log file (similar to the table included in the intial post).

Parse BackgroundProcessingWebJob.zip

[snakefoot]

Tried to make an answer here: https://github.com/JDetmar/NLog.Extensions.AzureStorage/issues/76#issuecomment-686705937

[ColinNg]

Thanks! Sorry it was my misconfiguration. I'll re-test with the recommendations.

[ColinNg]

Indeed it was my misconfiguration. I do have some tuning to do with batch sizes because AzureBlobStorage allows only 50,000 blocks (i.e. 49,999 appends) but I think that can be managed. Thanks!