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

Question

我们在一个ASP.NET WebAPI应用程序中使用NLog 4.7.2，该应用程序在完整的.NET Framework v4.8下运行在Windows Server 2016上。我配置了归档设置，我认为当日志大小达到1GB时，应该全天缓慢滚动日志。在我们的负载下，这应该会产生一两个日志文件。相反，我看到日志文件每天以不可预测的时间快速归档300到600次，有时每几分钟归档一次，大小从1 KB到32917 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:Logsnlog-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:LogsMy-Log-File.log"
maxArchiveDays="2"
archiveAboveSize="1000000000"
archiveFileName="C:LogsMy-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:inetpubwwwrootNLog.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:LogsMy-Log-File.log to C:LogsMy-Log-File.20200714.179.log
2020-07-14 15:41:34.0223 Info FileTarget(Name=logFile_wrapped): Archiving C:LogsMy-Log-File.log to C:LogsMy-Log-File.20200714.180.log
2020-07-14 15:46:14.8703 Info FileTarget(Name=logFile_wrapped): Archiving C:LogsMy-Log-File.log to C:LogsMy-Log-File.20200714.181.log

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

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

应@RolfKristensen的要求，我已更新到NLog的私人版本，并在归档过程中进行了更好的日志记录，以下是输出：

2020-08-05 13:50:24.3516 Debug FileTarget(Name=logFile_wrapped): Start archiving 'C:LogsMy-Log-File.log' because FileCreatedTime=20200805 is older than now 20200804
2020-08-05 13:50:24.3516 Debug FileAppender Closing Invalidate - C:LogsMy-Log-File.log
2020-08-05 13:50:24.3516 Debug FileTarget(Name=logFile_wrapped): Start archiving 'C:LogsMy-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:LogsMy-Log-File.log'
2020-08-05 13:50:24.3672 Info FileTarget(Name=logFile_wrapped): Archiving C:LogsMy-Log-File.log to C:LogsMy-Log-File.20200805.196.log
2020-08-05 13:50:24.3672 Debug FileTarget(Name=logFile_wrapped): Move file from 'C:LogsMy-Log-File.log' to 'C:LogsMy-Log-File.20200805.196.log'
2020-08-05 13:50:24.3672 Debug FileTarget(Name=logFile_wrapped): Preparing for new file 'C:LogsMy-Log-File.log'
2020-08-05 13:50:24.3672 Debug Creating file appender: C:LogsMy-Log-File.log

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

Answer 1

在NLog中添加了额外的诊断日志记录后，发现LogEvent时间戳出现了问题。几天前的时间戳与最近的时间戳混合在一起。

NLog将LogEvent时间戳视为"事件"时间戳；当前"；时间(还有几天前的(。这导致活动文件时间戳与"；当前"；时间，并触发文件归档操作。

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