为什么 Nlog 每隔几分钟归档一次文件？

Question

我们在完整的 .NET Framework v4.8 下 Windows Server 2016 上的 ASP.NET WebAPI 应用程序运行中使用 NLog 4.7.2。我以一种我认为应该在日志大小达到 1GB 时全天缓慢滚动日志的方式配置了存档设置。在我们的负载下，这应该会产生 1 个或两个日志文件。相反，我看到日志文件在不可预测的时间快速归档，每天 300 到 600 次，有时每隔几分钟一次，不可预测的大小从 1 KB 到 32,917 KB 不等。

使用下面的设置，我在我们的日志文件夹中查看了数百个文件：

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

以下是我们在 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>

内部日志没什么用，没有记录错误，只是随机定时归档

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

我打开了调试日志记录，它似乎并没有告诉我更多关于为什么如此频繁地归档的信息：

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

应@RolfKristensen 的要求，我已经更新到 NLog 的私有版本，可以更好地记录归档过程，这里是输出：

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

知道这里发生了什么吗？目前这对我们来说不是一个大问题，因为我们正在将这些日志转发到 Splunk，但我仍然想了解发生了什么。

Answer 1

在向 NLog 添加额外的诊断日志记录后，发现 LogEvent-Timestamps 即将 out-of-order。几天前的时间戳与最近的时间戳混合在一起。

NLog 将 LogEvent 时间戳视为“当前”时间（还有几天前的时间）。这导致活动 filetime-stamp 与“当前”时间不同，并触发了 file-archive 操作。

创建了 PullRequest https://github.com/NLog/NLog/pull/4073，它在触发 file-archive 操作时添加了时间戳的粗略验证。将包含在 NLog 4.7.4

为什么 Nlog 每隔几分钟归档一次文件？

Why is Nlog archiving files every few minutes?

nlog