CODEWITHSUNDEEP
nlog
Lorenh
Lorenh

Reputation: 13

Why is Nlog archiving files every few minutes?

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:

My-Log-File.20200713.0
My-Log-File.20200713.1
:
My-Log-File.20200713.365
My-Log-File.log

Here are the highlights of the settings we are using in Nlog.config:

<?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>

The internal log isn't much help, no errors are logged, just randomly timed archiving

2020-07-14 15:34:31.0322 Info Message Template Auto Format enabled
2020-07-14 15:34:31.0478 Info Loading assembly: MyApp.Common.Web
2020-07-14 15:34:31.1103 Info Adding target AsyncTargetWrapper(Name=logFile)
2020-07-14 15:34:31.1572 Info Validating config: TargetNames=logFile, ConfigItems=61, FilePath=C:\inetpub\wwwroot\NLog.config
2020-07-14 15:34:31.1885 Info Configuration initialized.
2020-07-14 15:34:31.2041 Info NLog, Version=4.0.0.0, Culture=neutral, PublicKeyToken=5120e14c03d0593c. File version: 4.7.2.11786. Product version: 4.7.2+024896f64b840a743d3fd89e29c2186681e7795f. GlobalAssemblyCache: False
2020-07-14 15:36:35.6895 Info FileTarget(Name=logFile_wrapped): Archiving C:\Logs\My-Log-File.log to C:\Logs\My-Log-File.20200714.179.log
2020-07-14 15:41:34.0223 Info FileTarget(Name=logFile_wrapped): Archiving C:\Logs\My-Log-File.log to C:\Logs\My-Log-File.20200714.180.log
2020-07-14 15:46:14.8703 Info FileTarget(Name=logFile_wrapped): Archiving C:\Logs\My-Log-File.log to C:\Logs\My-Log-File.20200714.181.log

I turned on debug logging and it doesn't seem to tell me much more about why it's archiving so frequently:

2020-08-03 22:06:36.8157 Debug FileAppender Closing Invalidate - C:\Logs\My-Log-File.log
2020-08-03 22:06:36.8157 Debug FileTarget(Name=logFile_wrapped): Archive mutex not available: C:\Logs\My-Log-File.log
2020-08-03 22:06:36.8157 Debug FileTarget(Name=logFile_wrapped): Do archive file: 'C:\Logs\My-Log-File.log'
2020-08-03 22:06:36.8157 Info FileTarget(Name=logFile_wrapped): Archiving C:\Logs\My-Log-File.log to C:\Logs\My-Log-File.20200803.426.log
2020-08-03 22:06:36.8157 Debug FileTarget(Name=logFile_wrapped): Move file from 'C:\Logs\My-Log-File.log' to 'C:\Logs\My-Log-File.20200803.426.log'
2020-08-03 22:06:36.8157 Debug FileTarget(Name=logFile_wrapped): Preparing for new file 'C:\Logs\My-Log-File.log'
2020-08-03 22:06:36.8157 Debug Creating file appender: C:\Logs\My-Log-File.log
2020-08-03 22:10:12.9027 Debug FileAppender Closing Invalidate - C:\Logs\My-Log-File.log
2020-08-03 22:10:12.9027 Debug FileTarget(Name=logFile_wrapped): Archive mutex not available: C:\Logs\My-Log-File.log
2020-08-03 22:10:12.9027 Debug FileTarget(Name=logFile_wrapped): Do archive file: 'C:\Logs\My-Log-File.log'
2020-08-03 22:10:12.9027 Info FileTarget(Name=logFile_wrapped): Archiving C:\Logs\My-Log-File.log to C:\Logs\My-Log-File.20200803.427.log
2020-08-03 22:10:12.9027 Debug FileTarget(Name=logFile_wrapped): Move file from 'C:\Logs\My-Log-File.log' to 'C:\Logs\My-Log-File.20200803.427.log'
2020-08-03 22:10:12.9027 Debug FileTarget(Name=logFile_wrapped): Preparing for new file 'C:\Logs\My-Log-File.log'
2020-08-03 22:10:12.9027 Debug Creating file appender: C:\Logs\My-Log-File.log

I have updated to a private build of NLog with better logging around the archiving process at the request of @RolfKristensen and here is the output:

2020-08-05 13:50:24.3516 Debug FileTarget(Name=logFile_wrapped): Start archiving 'C:\Logs\My-Log-File.log' because FileCreatedTime=20200805 is older than now 20200804
2020-08-05 13:50:24.3516 Debug FileAppender Closing Invalidate - C:\Logs\My-Log-File.log
2020-08-05 13:50:24.3516 Debug FileTarget(Name=logFile_wrapped): Start archiving 'C:\Logs\My-Log-File.log' because FileCreatedTime=20200805 is older than now 20200804
2020-08-05 13:50:24.3516 Debug FileTarget(Name=logFile_wrapped): Do archive file: 'C:\Logs\My-Log-File.log'
2020-08-05 13:50:24.3672 Info FileTarget(Name=logFile_wrapped): Archiving C:\Logs\My-Log-File.log to C:\Logs\My-Log-File.20200805.196.log
2020-08-05 13:50:24.3672 Debug FileTarget(Name=logFile_wrapped): Move file from 'C:\Logs\My-Log-File.log' to 'C:\Logs\My-Log-File.20200805.196.log'
2020-08-05 13:50:24.3672 Debug FileTarget(Name=logFile_wrapped): Preparing for new file 'C:\Logs\My-Log-File.log'
2020-08-05 13:50:24.3672 Debug Creating file appender: C:\Logs\My-Log-File.log

Any idea what's going on here? It's not a huge problem for us at the moment because we are forwarding these logs to Splunk, but I would still like to understand what's going on.

Upvotes: 0

Views: 964

Answers (1)

Rolf Kristensen
Rolf Kristensen

Reputation: 19847

After having added extra diagnostic logging to NLog, then it was discovered that it was LogEvent-Timestamps coming out-of-order. Timestamps that was several days old was mixed together with recent timestamp.

NLog treats the LogEvent timestamp as they are "current" time (Also the ones several days old). This caused active filetime-stamp to differ from "current" time, and triggered file-archive operation.

Created PullRequest https://github.com/NLog/NLog/pull/4073 that adds a crude validation of timestamps when it triggers file-archive operation. Will be included in NLog 4.7.4

Upvotes: 1

Related Questions