Nlog: Time-based file archival does not work correctly (single target with multiple files)

[kinshines]

Type :Bug

NLog version: 4.5.2

Platform: .Net 4.5

Current NLog config (xml or C#, if relevant)

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
      autoReload="true"
      throwExceptions="false"
      internalLogLevel="Off" internalLogFile="c:\temp\nlog-internal.log">

  <targets>
    <target xsi:type="File" name="file" encoding="utf-8" fileName="${basedir}\log\${logger}.log"
            layout="${time} ${message}" archiveEvery="Day" maxArchiveFiles="3" 
            archiveFileName="${basedir}\log\${logger}\${logger}_{#}.log" archiveNumbering="Date" />
  </targets>

  <rules>
    <logger name="*" minlevel="Debug" writeTo="file" />
  </rules>
</nlog>

C# code

class Program
    {
        static void Main(string[] args)
        {
            LogInfo("module1", "message");
            LogInfo("module2", "message");
        }

        static void LogInfo(string module,string message)
        {
            Logger logger = LogManager.GetLogger(module);
            logger.Info(message);
        }
    }

• What is the current result?
  I want to log message by module and every module will log one file in every day.
  in date:2018-04-12,
  the program log two file: \log\module1.log and \log\module2.log,it is all right
  When it comes to date:2018-04-13,
  the old file \log\module1.log will be moved to \log\module1\module1_20180412.log,
  But the old file \log\module2.log will be moved to \log\module2\module2_20180413.log
  why the two module moved to archiveFileName with different date?

• What is the expected result?
  Expected result is that the module2 also be moved to \log\module2\module2_20180412.log
  this issue was resolved in milestone 4.5 beta2 https://github.com/NLog/NLog/milestone/49
  But it reappear in 4.5 rc and later version

• Did you checked the Internal log?
  Internal log has nothing

• Please post full exception details (message, stacktrace, inner exceptions)
  no more details
• Are there any workarounds?
  no
• Is there a version in which it did work?
  no
• Can you help us by writing an unit test?
  if needed

[kinshines]

this issue was resolved in milestone 4.5 beta2 https://github.com/NLog/NLog/milestone/49
But it reappear in 4.5 rc and later version

[304NotModified]

Did you checked the Internal log?
Internal log has nothing

Could you please enable the internal log (trace level) and post it here? ( internalLogLevel="Trace")

[304NotModified]

Can you help us by writing an unit test?
if needed

We need this eventually, unfortunate the code is not mockable yet

[kinshines]

Sorry，Internal log is here:

2018-04-13 16:19:21.1045 Debug ScanAssembly('NLog, Version=4.0.0.0, Culture=neutral, PublicKeyToken=5120e14c03d0593c')
2018-04-13 16:19:21.2165 Debug Search for auto loading files, location: C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\
2018-04-13 16:19:21.2165 Debug Start auto loading, location: C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\
2018-04-13 16:19:21.2165 Debug Auto loading done
2018-04-13 16:19:21.2165 Info Message Template Auto Format enabled
2018-04-13 16:19:21.2445 Trace FindReachableObject<NLog.Internal.IRenderable>:
2018-04-13 16:19:21.2445 Trace Scanning LongDateLayoutRenderer 'Layout Renderer: ${longdate}'
2018-04-13 16:19:21.2555 Debug Setting 'UppercaseLayoutRendererWrapper.uppercase' to 'true'
2018-04-13 16:19:21.2555 Trace Wrapping LevelLayoutRenderer with UppercaseLayoutRendererWrapper
2018-04-13 16:19:21.2555 Trace FindReachableObject<NLog.Internal.IRenderable>:
2018-04-13 16:19:21.2555 Trace Scanning LevelLayoutRenderer 'Layout Renderer: ${level}'
2018-04-13 16:19:21.2555 Trace FindReachableObject<NLog.Internal.IRenderable>:
2018-04-13 16:19:21.2555 Trace Scanning UppercaseLayoutRendererWrapper 'Layout Renderer: ${uppercase}'
2018-04-13 16:19:21.2555 Trace  Scanning Property Culture '' System.Globalization
2018-04-13 16:19:21.2705 Trace  Scanning Property Inner 'SimpleLayout=Layout Renderer: ${level}' NLog.Layouts
2018-04-13 16:19:21.2705 Trace  Scanning SimpleLayout 'SimpleLayout=Layout Renderer: ${level}'
2018-04-13 16:19:21.2705 Trace   Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel
2018-04-13 16:19:21.2705 Trace   Scanning LevelLayoutRenderer 'Layout Renderer: ${level}'
2018-04-13 16:19:21.2705 Trace FindReachableObject<NLog.Internal.IRenderable>:
2018-04-13 16:19:21.2705 Trace Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}'
2018-04-13 16:19:21.2705 Trace FindReachableObject<NLog.Internal.IRenderable>:
2018-04-13 16:19:21.2705 Trace Scanning MessageLayoutRenderer 'Layout Renderer: ${message}'
2018-04-13 16:19:21.2705 Debug Setting 'FileTarget.name' to 'file'
2018-04-13 16:19:21.2705 Debug Setting 'FileTarget.encoding' to 'utf-8'
2018-04-13 16:19:21.2855 Debug Setting 'FileTarget.fileName' to '${basedir}\log\${logger}.log'
2018-04-13 16:19:21.2855 Trace FindReachableObject<NLog.Internal.IRenderable>:
2018-04-13 16:19:21.2855 Trace Scanning BaseDirLayoutRenderer 'Layout Renderer: ${basedir}'
2018-04-13 16:19:21.2855 Trace FindReachableObject<NLog.Internal.IRenderable>:
2018-04-13 16:19:21.2855 Trace Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}'
2018-04-13 16:19:21.2855 Debug Setting 'FileTarget.layout' to '${time} ${message}'
2018-04-13 16:19:21.3025 Trace FindReachableObject<NLog.Internal.IRenderable>:
2018-04-13 16:19:21.3025 Trace Scanning TimeLayoutRenderer 'Layout Renderer: ${time}'
2018-04-13 16:19:21.3025 Trace FindReachableObject<NLog.Internal.IRenderable>:
2018-04-13 16:19:21.3025 Trace Scanning MessageLayoutRenderer 'Layout Renderer: ${message}'
2018-04-13 16:19:21.3025 Debug Setting 'FileTarget.archiveEvery' to 'Day'
2018-04-13 16:19:21.3025 Debug Setting 'FileTarget.maxArchiveFiles' to '3'
2018-04-13 16:19:21.3025 Debug Setting 'FileTarget.archiveFileName' to '${basedir}\log\${logger}\${logger}_{#}.log'
2018-04-13 16:19:21.3025 Trace FindReachableObject<NLog.Internal.IRenderable>:
2018-04-13 16:19:21.3185 Trace Scanning BaseDirLayoutRenderer 'Layout Renderer: ${basedir}'
2018-04-13 16:19:21.3185 Trace FindReachableObject<NLog.Internal.IRenderable>:
2018-04-13 16:19:21.3185 Trace Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}'
2018-04-13 16:19:21.3185 Trace FindReachableObject<NLog.Internal.IRenderable>:
2018-04-13 16:19:21.3185 Trace Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}'
2018-04-13 16:19:21.3185 Debug Setting 'FileTarget.archiveNumbering' to 'Date'
2018-04-13 16:19:21.3185 Info Adding target File Target[file]
2018-04-13 16:19:21.3335 Debug Registered target file: NLog.Targets.FileTarget
2018-04-13 16:19:21.3335 Trace ParseRulesElement
2018-04-13 16:19:21.3335 Info Configured from an XML element in C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\NLog.config...
2018-04-13 16:19:21.3515 Debug Unused target checking is started... Rule Count: 1, Target Count: 1
2018-04-13 16:19:21.3515 Debug Unused target checking is completed. Total Rule Count: 1, Total Target Count: 1, Unused Target Count: 0
2018-04-13 16:19:21.3515 Debug --- NLog configuration dump ---
2018-04-13 16:19:21.3515 Debug Targets:
2018-04-13 16:19:21.3515 Debug File Target[file]
2018-04-13 16:19:21.3515 Debug Rules:
2018-04-13 16:19:21.3655 Debug logNamePattern: (:All) levels: [ Debug Info Warn Error Fatal ] appendTo: [ file ]
2018-04-13 16:19:21.3655 Debug --- End of NLog configuration dump ---
2018-04-13 16:19:21.3655 Trace FindReachableObject<System.Object>:
2018-04-13 16:19:21.3655 Trace Scanning LoggingRule 'logNamePattern: (:All) levels: [ Debug Info Warn Error Fatal ] appendTo: [ file ]'
2018-04-13 16:19:21.3655 Trace  Scanning Property Targets 'System.Collections.Generic.List`1[NLog.Targets.Target]' System.Collections.Generic
2018-04-13 16:19:21.3655 Trace  Scanning FileTarget 'File Target[file]'
2018-04-13 16:19:21.3655 Trace   Scanning Property FileName ''${basedir}\log\${logger}.log'' NLog.Layouts
2018-04-13 16:19:21.3655 Trace   Scanning SimpleLayout ''${basedir}\log\${logger}.log''
2018-04-13 16:19:21.3655 Trace    Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel
2018-04-13 16:19:21.3655 Trace    Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}'
2018-04-13 16:19:21.3805 Trace    Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}'
2018-04-13 16:19:21.3805 Trace    Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}'
2018-04-13 16:19:21.3805 Trace   Scanning Property LineEnding 'Default' NLog.Targets
2018-04-13 16:19:21.3805 Trace   Scanning Property Encoding 'System.Text.UTF8Encoding' System.Text
2018-04-13 16:19:21.3805 Trace   Scanning Property ArchiveFileName ''${basedir}\log\${logger}\${logger}_{#}.log'' NLog.Layouts
2018-04-13 16:19:21.3805 Trace   Scanning SimpleLayout ''${basedir}\log\${logger}\${logger}_{#}.log''
2018-04-13 16:19:21.3805 Trace    Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel
2018-04-13 16:19:21.3805 Trace    Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}'
2018-04-13 16:19:21.3805 Trace    Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}'
2018-04-13 16:19:21.3805 Trace    Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}'
2018-04-13 16:19:21.3805 Trace    Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}'
2018-04-13 16:19:21.3805 Trace    Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}'
2018-04-13 16:19:21.3805 Trace   Scanning Property Layout ''${time} ${message}'' NLog.Layouts
2018-04-13 16:19:21.3805 Trace   Scanning SimpleLayout ''${time} ${message}''
2018-04-13 16:19:21.3805 Trace    Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel
2018-04-13 16:19:21.3805 Trace    Scanning TimeLayoutRenderer 'Layout Renderer: ${time}'
2018-04-13 16:19:21.3805 Trace    Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}'
2018-04-13 16:19:21.3955 Trace    Scanning MessageLayoutRenderer 'Layout Renderer: ${message}'
2018-04-13 16:19:21.3955 Trace  Scanning Property ChildRules 'System.Collections.Generic.List`1[NLog.Config.LoggingRule]' System.Collections.Generic
2018-04-13 16:19:21.3955 Trace  Scanning Property Filters 'System.Collections.Generic.List`1[NLog.Filters.Filter]' System.Collections.Generic
2018-04-13 16:19:21.3955 Trace  Scanning Property Levels 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LogLevel]' System.Collections.ObjectModel
2018-04-13 16:19:21.3955 Info Found 16 configuration items
2018-04-13 16:19:21.3955 Trace Initializing Layout Renderer: ${message}
2018-04-13 16:19:21.3955 Trace Initializing Layout Renderer: ${literal}
2018-04-13 16:19:21.3955 Trace Initializing Layout Renderer: ${time}
2018-04-13 16:19:21.3955 Trace Initializing '${time} ${message}'
2018-04-13 16:19:21.4105 Trace FindReachableObject<System.Object>:
2018-04-13 16:19:21.4105 Trace Scanning SimpleLayout ''${time} ${message}''
2018-04-13 16:19:21.4105 Trace  Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel
2018-04-13 16:19:21.4105 Trace  Scanning TimeLayoutRenderer 'Layout Renderer: ${time}'
2018-04-13 16:19:21.4105 Trace  Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}'
2018-04-13 16:19:21.4105 Trace  Scanning MessageLayoutRenderer 'Layout Renderer: ${message}'
2018-04-13 16:19:21.4105 Trace Initializing Layout Renderer: ${literal}
2018-04-13 16:19:21.4105 Trace Initializing Layout Renderer: ${logger}
2018-04-13 16:19:21.4105 Trace Initializing Layout Renderer: ${literal}
2018-04-13 16:19:21.4105 Trace Initializing Layout Renderer: ${logger}
2018-04-13 16:19:21.4105 Trace Initializing Layout Renderer: ${literal}
2018-04-13 16:19:21.4265 Trace Initializing '${basedir}\log\${logger}\${logger}_{#}.log'
2018-04-13 16:19:21.4265 Trace FindReachableObject<System.Object>:
2018-04-13 16:19:21.4265 Trace Scanning SimpleLayout ''${basedir}\log\${logger}\${logger}_{#}.log''
2018-04-13 16:19:21.4265 Trace  Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel
2018-04-13 16:19:21.4265 Trace  Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}'
2018-04-13 16:19:21.4265 Trace  Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}'
2018-04-13 16:19:21.4265 Trace  Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}'
2018-04-13 16:19:21.4265 Trace  Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}'
2018-04-13 16:19:21.4265 Trace  Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}'
2018-04-13 16:19:21.4265 Trace Initializing Layout Renderer: ${literal}
2018-04-13 16:19:21.4265 Trace Initializing Layout Renderer: ${logger}
2018-04-13 16:19:21.4265 Trace Initializing Layout Renderer: ${literal}
2018-04-13 16:19:21.4265 Trace Initializing '${basedir}\log\${logger}.log'
2018-04-13 16:19:21.4265 Trace FindReachableObject<System.Object>:
2018-04-13 16:19:21.4265 Trace Scanning SimpleLayout ''${basedir}\log\${logger}.log''
2018-04-13 16:19:21.4265 Trace  Scanning Property Renderers 'System.Collections.ObjectModel.ReadOnlyCollection`1[NLog.LayoutRenderers.LayoutRenderer]' System.Collections.ObjectModel
2018-04-13 16:19:21.4265 Trace  Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}'
2018-04-13 16:19:21.4265 Trace  Scanning LoggerNameLayoutRenderer 'Layout Renderer: ${logger}'
2018-04-13 16:19:21.4415 Trace  Scanning LiteralLayoutRenderer 'Layout Renderer: ${literal}'
2018-04-13 16:19:21.4415 Trace Initializing File Target[file]
2018-04-13 16:19:21.4415 Trace FindReachableObject<NLog.Layouts.Layout>:
2018-04-13 16:19:21.4415 Trace Scanning FileTarget 'File Target[file]'
2018-04-13 16:19:21.4415 Trace  Scanning Property FileName ''${basedir}\log\${logger}.log'' NLog.Layouts
2018-04-13 16:19:21.4415 Trace  Scanning SimpleLayout ''${basedir}\log\${logger}.log''
2018-04-13 16:19:21.4415 Trace  Scanning Property Layout ''${time} ${message}'' NLog.Layouts
2018-04-13 16:19:21.4415 Trace  Scanning SimpleLayout ''${time} ${message}''
2018-04-13 16:19:21.4415 Trace  Scanning Property ArchiveFileName ''${basedir}\log\${logger}\${logger}_{#}.log'' NLog.Layouts
2018-04-13 16:19:21.4415 Trace  Scanning SimpleLayout ''${basedir}\log\${logger}\${logger}_{#}.log''
2018-04-13 16:19:21.4415 Trace  Scanning Property LineEnding 'Default' NLog.Targets
2018-04-13 16:19:21.4415 Trace  Scanning Property Encoding 'System.Text.UTF8Encoding' System.Text
2018-04-13 16:19:21.4415 Trace File Target[file] has 3 layouts
2018-04-13 16:19:21.4415 Trace Using appenderFactory: NLog.Internal.FileAppenders.RetryingMultiProcessFileAppender+Factory
2018-04-13 16:19:21.4725 Debug Watching path 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug' filter 'NLog.config' for changes.
2018-04-13 16:19:21.4755 Info Configuration initialized.
2018-04-13 16:19:21.4755 Info NLog, Version=4.0.0.0, Culture=neutral, PublicKeyToken=5120e14c03d0593c. File version: 4.5.2.7435. Product version: 4.5.2.
2018-04-13 16:19:21.4755 Debug Targets for module1 by level:
2018-04-13 16:19:21.4755 Debug Trace =>
2018-04-13 16:19:21.4755 Debug Debug => file
2018-04-13 16:19:21.4755 Debug Info => file
2018-04-13 16:19:21.4755 Debug Warn => file
2018-04-13 16:19:21.4886 Debug Error => file
2018-04-13 16:19:21.4886 Debug Fatal => file
2018-04-13 16:19:21.5116 Debug FileTarget: process file 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module1.log' on startup
2018-04-13 16:19:21.5296 Trace FileTarget: Archive attempt for file 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module1.log'
2018-04-13 16:19:21.5296 Info FileTarget: Archive mutex not available: C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module1.log
2018-04-13 16:19:21.5296 Debug FileTarget: do archive file 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module1.log'
2018-04-13 16:19:21.5296 Trace FileTarget: archive pattern 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module1\module1_{#}.log'
2018-04-13 16:19:21.5376 Trace Calculating archive date. Last write time: 04/12/2018 16:18:27; Previous log event time: 
2018-04-13 16:19:21.5376 Trace Using last write time
2018-04-13 16:19:21.5786 Info Archiving C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module1.log to C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module1\module1_20180412.log
2018-04-13 16:19:21.5786 Debug Move file from 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module1.log' to 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module1\module1_20180412.log'
2018-04-13 16:19:21.5826 Debug FileTarget: process file 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module1.log' on startup
2018-04-13 16:19:21.5826 Debug Creating file appender: C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module1.log
2018-04-13 16:19:21.5826 Trace Opening C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module1.log with allowFileSharedWriting=False
2018-04-13 16:19:21.6036 Debug Targets for module2 by level:
2018-04-13 16:19:21.6036 Debug Trace =>
2018-04-13 16:19:21.6036 Debug Debug => file
2018-04-13 16:19:21.6036 Debug Info => file
2018-04-13 16:19:21.6036 Debug Warn => file
2018-04-13 16:19:21.6036 Debug Error => file
2018-04-13 16:19:21.6036 Debug Fatal => file
2018-04-13 16:19:21.6036 Debug FileTarget: process file 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module2.log' on startup
2018-04-13 16:19:21.6036 Trace FileTarget: Archive attempt for file 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module2.log'
2018-04-13 16:19:21.6036 Debug FileAppender Closing Invalidate - C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module1.log
2018-04-13 16:19:21.6136 Debug FileTarget: do archive file 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module2.log'
2018-04-13 16:19:21.6136 Trace FileTarget: archive pattern 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module2\module2_{#}.log'
2018-04-13 16:19:21.6136 Trace Calculating archive date. Last write time: 04/12/2018 16:18:27; Previous log event time: 04/13/2018 16:19:21
2018-04-13 16:19:21.6136 Trace Using previous log event time (is more recent)
2018-04-13 16:19:21.6136 Info Archiving C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module2.log to C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module2\module2_20180413.log
2018-04-13 16:19:21.6136 Debug Move file from 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module2.log' to 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module2\module2_20180413.log'
2018-04-13 16:19:21.6136 Debug FileTarget: process file 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module2.log' on startup
2018-04-13 16:19:21.6136 Debug Creating file appender: C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module2.log
2018-04-13 16:19:21.6136 Trace Opening C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module2.log with allowFileSharedWriting=False
2018-04-13 16:19:21.6306 Info Shutting down logging...
2018-04-13 16:19:21.6306 Debug Stopping file watching for path 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug' filter 'NLog.config'
2018-04-13 16:19:21.6306 Trace Flushing all targets...
2018-04-13 16:19:21.6306 Trace ForEachItemInParallel() 1 items
2018-04-13 16:19:21.6446 Trace FileTarget: FlushAsync
2018-04-13 16:19:21.6446 Trace Continuation invoked: 
2018-04-13 16:19:21.6446 Trace Parallel task completed. 0 items remaining
2018-04-13 16:19:21.6446 Trace FileTarget: FlushAsync Done
2018-04-13 16:19:21.6446 Debug Targets for module1 by level:
2018-04-13 16:19:21.6446 Debug Trace =>
2018-04-13 16:19:21.6446 Debug Debug =>
2018-04-13 16:19:21.6446 Debug Info =>
2018-04-13 16:19:21.6446 Debug Warn =>
2018-04-13 16:19:21.6446 Debug Error =>
2018-04-13 16:19:21.6446 Debug Fatal =>
2018-04-13 16:19:21.6446 Debug Targets for module2 by level:
2018-04-13 16:19:21.6446 Debug Trace =>
2018-04-13 16:19:21.6446 Debug Debug =>
2018-04-13 16:19:21.6446 Debug Info =>
2018-04-13 16:19:21.6446 Debug Warn =>
2018-04-13 16:19:21.6446 Debug Error =>
2018-04-13 16:19:21.6446 Debug Fatal =>
2018-04-13 16:19:21.6616 Debug Closing logging configuration...
2018-04-13 16:19:21.6616 Trace Closing File Target[file]
2018-04-13 16:19:21.6616 Debug Closing target 'File Target[file]'.
2018-04-13 16:19:21.6616 Trace FileTarget: FinalizeFile 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module1.log, isArchiving: False'
2018-04-13 16:19:21.6616 Trace FileTarget: FinalizeFile 'C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module2.log, isArchiving: False'
2018-04-13 16:19:21.6616 Debug FileAppender Closing Invalidate - C:\Users\Chaoyu\source\repos\ConsoleApp3\ConsoleApp3\bin\Debug\log\module2.log
2018-04-13 16:19:21.6616 Debug Closed target 'File Target[file]'.
2018-04-13 16:19:21.6616 Trace Closing '${basedir}\log\${logger}.log'
2018-04-13 16:19:21.6616 Trace Closing Layout Renderer: ${literal}
2018-04-13 16:19:21.6616 Trace Closing Layout Renderer: ${logger}
2018-04-13 16:19:21.6616 Trace Closing Layout Renderer: ${literal}
2018-04-13 16:19:21.6616 Trace Closing '${basedir}\log\${logger}\${logger}_{#}.log'
2018-04-13 16:19:21.6616 Trace Closing Layout Renderer: ${literal}
2018-04-13 16:19:21.6756 Trace Closing Layout Renderer: ${logger}
2018-04-13 16:19:21.6756 Trace Closing Layout Renderer: ${literal}
2018-04-13 16:19:21.6756 Trace Closing Layout Renderer: ${logger}
2018-04-13 16:19:21.6756 Trace Closing Layout Renderer: ${literal}
2018-04-13 16:19:21.6756 Trace Closing '${time} ${message}'
2018-04-13 16:19:21.6756 Trace Closing Layout Renderer: ${time}
2018-04-13 16:19:21.6756 Trace Closing Layout Renderer: ${literal}
2018-04-13 16:19:21.6756 Trace Closing Layout Renderer: ${message}
2018-04-13 16:19:21.6756 Debug Finished closing logging configuration.
2018-04-13 16:19:21.6756 Info Logger has been shut down.

[304NotModified]

This seems the issue:

2018-04-13 16:19:21.6136 Trace Calculating archive date. Last write time: 04/12/2018 16:18:27; Previous log event time: 04/13/2018 16:19:21
2018-04-13 16:19:21.6136 Trace Using previous log event time (is more recent)

[snakefoot]

Created PR #2662

[304NotModified]

@kinshines This is fixed in NLog 4.5.3 and is just released.

Thanks @snakefoot !

[kinshines]

It is resolved perfectly,thanks your efforts,NLog is becoming the most popular logger in .NET platform