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

【问题标题】：Why is Nlog archiving files every few minutes?为什么 Nlog 每隔几分钟就归档一次文件？
【发布时间】：2020-07-14 16:24:11
【问题描述】：

我们在一个 ASP.NET WebAPI 应用程序中使用 NLog 4.7.2，该应用程序在完整的 .NET Framework v4.8 下运行在 Windows Server 2016 上。我以一种我认为应该在日志大小达到 1GB 时全天缓慢滚动日志的方式配置了存档设置。在我们的负载下，这应该会产生 1 或 2 个日志文件。相反，我看到日志文件在不可预测的时间快速归档，每天 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，但我仍然想了解发生了什么。

【问题讨论】：

我无法解释这一点。你确定这是正确的配置吗？你的 bin 文件夹中没有第二个配置吗？
整个应用程序目录树中没有其他的 NLog 配置文件（只是再次检查确定）
@Lorenh 你能改成internalLogLevel="Debug"，然后发布输出吗？
@RolfKristensen 文件很大，有没有什么好办法可以放到可以看的地方？
@Lorenh 你可以在 GitHub 上创建一个问题，并附上文件：github.com/NLog/NLog/issues/new/choose

标签： nlog

【解决方案1】：

在向 NLog 添加额外的诊断日志之后，发现它是 LogEvent-Timestamps 乱序。几天前的时间戳与最近的时间戳混合在一起。

NLog 将 LogEvent 时间戳视为“当前”时间（也是几天前的时间）。这会导致活动文件时间戳与“当前”时间不同，并触发文件归档操作。

创建的 PullRequest https://github.com/NLog/NLog/pull/4073 在触发文件归档操作时添加了对时间戳的粗略验证。将包含在 NLog 4.7.4 中

【讨论】：