Nlog: Why is Nlog archiving files every few minutes?

[lorenh]

This is a continuation of the issue posted on Stack Overflow here https://stackoverflow.com/questions/62899627/why-is-nlog-archiving-files-every-few-minutes Moved discussion here so that more information can be provided.

We are using NLog 4.7.2 in an ASP.NET WebAPI app running on Windows Server 2016 under full .NET Framework v4.8. I have configured the archive settings in a way that I think is supposed to roll the logs slowly throughout the day when it hits 1GB in size. At our load this should produce maybe 1 or two log files. Instead I see log files archiving rapidly at unpredictable times 300 to 600 times a day, sometimes every few minutes, with unpredictable sizes ranging from 1 KB to 32,917 KB in size.

Using the settings below I look in our logging folder and see hundreds of files:

NLog version: 4.7.2
Platform: .Net 4.5
Current NLog config (xml or C#, if relevant)

<?xml version="1.0"?>
<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:\Logs\nlog-internal.log">

  <extensions>
    <add assembly="MyApp.Common.Web"/> <!-- adds the context-properties renderer -->
  </extensions>

  <targets async="true">
    <target
      name="logFile"
      xsi:type="File"
      layout="${longdate:universalTime=true}Z ${pad:padding=-7:inner=[${level:uppercase=true}]} [${machinename}] ${pad:padding=-5:inner=[${threadid}]} [${logger}] [${context-properties}] ${message} ${onexception:${exception:format=ToString}}"
      fileName="C:\Logs\My-Log-File.log"
      maxArchiveDays="2"
      archiveAboveSize="1000000000"
      archiveFileName="C:\Logs\My-Log-File.{#}.log"
      archiveEvery="Day"
      archiveNumbering="DateAndSequence"
      archiveDateFormat="yyyyMMdd"
      concurrentWrites="false"
      encoding="utf-8" />
  </targets>

  <rules>
    <!-- many rules here (omitted for clarity) --> 

    <logger name="*" minlevel="Info" writeTo="logFile" />
  </rules>

</nlog>

Current result - Files are getting archived every few minutes.
Expected result - Files should be archived according to size or time parameters instead of seemingly randomly.

Here is an example of the internal log at Debug level from the pre-release version Rolf Kristensen provided for me

internal-log.txt

[welcome[bot]]

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

[snakefoot]

It is very interesting how you generate new LogEvents with timestamp one day older than DateTime.UtcNow

I guess NLog could add some extra validation in case creating LogEvents from yesterday.

[lorenh]

@snakefoot OK, so help me understand that. When we see things like the following, the comparison dates are coming from the timestamps on the log events themselves?

Start archiving 'C:\Logs\My-Log-File.log' because FileCreatedTime=20200805 is older than now 20200804
Start archiving 'C:\Logs\My-Log-File.log' because FileCreatedTime=20200805 is older than now 20200801
Start archiving 'C:\Logs\My-Log-File.log' because FileCreatedTime=20200805 is older than now 20200717

We have an offline scenario where log messages may be cached for a time on a mobile client, then sent when connectivity is regained, so they may not be coming in order. We forward everything to Splunk which sorts everything out for us chronologically.

I'll do some digging and see if I can confirm that's what's happening. But that gives me a lead into what could be different in our case.

[lorenh]

I have confirmed that whenever one of our out-of-order events due to client-side offline cache gets logged the archive process starts. So now we know why. Is there anything we can do about it in NLog to help this situation? Should I look for a different logging solution?

[snakefoot]

NLog has an optimization where it expects the timestamp on the LogEventInfo is super close to current time.

This means all locations where a timestamp is needed, then instead of calling DateTime.UtcNow then NLog just uses the timestamp from the LogEventInfo.

This optimization doesn't work when LogEventInfo has been buffered for a long time. The can occur when using BufferingWrapper that only flushes on certain events (Can contain very old LogEventInfo-objects).

Think it would make sense to improve the NLog-logic to not be confused by LogEventInfo-objects with timestamp in the past.

[snakefoot]

Have created PullRequest #4073 to better handle LogEvent from the past, that arrives out-of-order.

[snakefoot]

@lorenh If you could try this pre-release for NLog 4.7.4 then it would be very helpful:

https://ci.appveyor.com/project/nlog/nlog/builds/34519669/artifacts

It adds extra validation when detecting LogEvent-timestamps coming out-of-order.

[snakefoot]

Improvements has been implemented with #4073 for NLog 4.7.4

[snakefoot]

@304NotModified Any reason why the pendingr-bot strips away all labels on merge?

[304NotModified]

No that's new I think :o

[snakefoot]

@304NotModified No that's new I think :o

Also happened here #4052 and here #4030 (Think it has been like this since the pendingpr-bot arrived).

[304NotModified]

The bot has been uninstalled

[lorenh]

I am trying out the prerelease version with the fix and it appears to be working properly now. It is no longer archiving the log when events arrive out of order. Thank you so much for the quick action on this @snakefoot !! I'll keep monitoring it and report back if something changes.

[304NotModified]

Hi! NLog 4.7.4 has been released! https://www.nuget.org/packages/NLog/4.7.4