Nlog: Wrong filetarget archive date

[martys]

Type (choose one): Bug
NLog version: (e.g. 4.5.4)

Platform: .Net 4.6.2

I think this is in relation to #2224
I tried updating to the latest versions, but still getting similar results.

Expected behaviour would be to have this archive name be 2018-05-22
Interesting thing is - that it actually did that for the first file that it encountered.

Note - that the path is different. These are logs for separate devices where logs for each device is stored in different folder. From what I gather from Internal log and code, is that MAYBE the value for
previousLogEventTimestampis calculated overall, for the last event in the system, but not the last log event for the current file.

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

<?xml version="1.0" encoding="utf-8" ?>
<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="Error" internalLogFile="c:\temp\nlog-internal.log"

      >

  <!-- optional, add some variables
  https://github.com/nlog/NLog/wiki/Configuration-file#variables
  -->
  <variable name="basedir" value="${appsetting:name=HttpLoggingDirectory}" />
  <!--
  See https://github.com/nlog/nlog/wiki/Configuration-file
  for information on customizing logging rules and outputs.
   -->
  <targets >
    <target name="asyncFile" xsi:type="AsyncWrapper" overflowAction="Grow">
      <target name="file" xsi:type="File"
              fileName="${var:basedir}\${event-properties:item=serialNo}\log.txt"
              layout="${message}"
              archiveFileName=" ${var:basedir}\${event-properties:item=serialNo}\log.{#}.txt"
              archiveNumbering="DateAndSequence"
              archiveDateFormat="yyyy-MM-dd"
              archiveEvery="Day"
              maxArchiveFiles="14"
              concurrentWrites="true" />
    </target>
  </targets>
  <rules>
    <logger name="*" writeTo="asyncFile" />
  </rules>
</nlog>

Trace details from the internal Log
2018-05-22 23:59:59.8252 Trace Opening \srmwstblog1\HttpLogging\M91803ED2172log.txt with allowFileSharedWriting=False
2018-05-23 00:00:00.0752 Trace FileTarget(Name=file): Archive attempt for file '\srmwstblog1\HttpLogging\M91803ED2172log.txt'
2018-05-23 00:00:00.0752 Debug FileAppender Closing Invalidate - \srmwstblog1\HttpLogging\M91803ED2172log.txt
2018-05-23 00:00:00.0752 Debug FileTarget(Name=file): Do archive file: '\srmwstblog1\HttpLogging\M91803ED2172log.txt'
2018-05-23 00:00:00.0752 Trace FileTarget(Name=file): Archive pattern '\srmwstblog1\HttpLogging\M91803ED2172\log.{#}.txt'
2018-05-23 00:00:00.1377 Trace FileTarget: parsed date '2018-05-22' from file-template 'log.{#}.txt'
2018-05-23 00:00:00.1377 Trace FileTarget(Name=file): Calculating archive date. File-LastModifiedUtc: 05/22/2018 20:59:59; Previous LogEvent-TimeStamp: 05/22/2018 23:59:59
2018-05-23 00:00:00.1377 Trace FileTarget(Name=file): Using last write time
2018-05-23 00:00:00.1377 Trace FileTarget(Name=file): FinalizeFile '\srmwstblog1\HttpLogging\M91803ED2172log.txt, isArchiving: True'
2018-05-23 00:00:00.1377 Info FileTarget(Name=file): Archiving \srmwstblog1\HttpLogging\M91803ED2172log.txt to \srmwstblog1\HttpLogging\M91803ED2172\log.2018-05-22.1.txt
2018-05-23 00:00:00.1377 Debug FileTarget(Name=file): Move file from '\srmwstblog1\HttpLogging\M91803ED2172log.txt' to '\srmwstblog1\HttpLogging\M91803ED2172\log.2018-05-22.1.txt'
2018-05-23 00:00:00.1534 Debug FileTarget(Name=file): Process file '\srmwstblog1\HttpLogging\M91803ED2172log.txt' on startup
2018-05-23 00:00:00.1534 Debug Creating file appender: \srmwstblog1\HttpLogging\M91803ED2172log.txt
2018-05-23 00:00:00.1534 Trace Opening \srmwstblog1\HttpLogging\M91803ED2172log.txt with allowFileSharedWriting=False
2018-05-23 00:00:00.4659 Trace FileTarget(Name=file): Archive attempt for file '\srmwstblog1\HttpLogging\M91803ED2137log.txt'
2018-05-23 00:00:00.4659 Debug FileAppender Closing Invalidate - \srmwstblog1\HttpLogging\M91803ED2172log.txt
2018-05-23 00:00:00.4659 Debug FileTarget(Name=file): Do archive file: '\srmwstblog1\HttpLogging\M91803ED2137log.txt'
2018-05-23 00:00:00.4659 Trace FileTarget(Name=file): Archive pattern '\srmwstblog1\HttpLogging\M91803ED2137\log.{#}.txt'
2018-05-23 00:00:00.5127 Trace FileTarget: parsed date '2018-05-22' from file-template 'log.{#}.txt'
2018-05-23 00:00:00.5127 Trace FileTarget(Name=file): Calculating archive date. File-LastModifiedUtc: 05/22/2018 20:59:56; Previous LogEvent-TimeStamp: 05/23/2018 00:00:00
2018-05-23 00:00:00.5127 Trace FileTarget(Name=file): Using previous log event time (is more recent)
2018-05-23 00:00:00.5127 Trace FileTarget(Name=file): FinalizeFile '\srmwstblog1\HttpLogging\M91803ED2137log.txt, isArchiving: True'
2018-05-23 00:00:00.5127 Info FileTarget(Name=file): Archiving \srmwstblog1\HttpLogging\M91803ED2137log.txt to \srmwstblog1\HttpLogging\M91803ED2137\log.2018-05-23.0.txt
2018-05-23 00:00:00.5127 Debug FileTarget(Name=file): Move file from '\srmwstblog1\HttpLogging\M91803ED2137log.txt' to '\srmwstblog1\HttpLogging\M91803ED2137\log.2018-05-23.0.txt'
2018-05-23 00:00:00.5127 Debug FileTarget(Name=file): Process file '\srmwstblog1\HttpLogging\M91803ED2137log.txt' on startup
2018-05-23 00:00:00.5127 Debug Creating file appender: \srmwstblog1\HttpLogging\M91803ED2137log.txt
2018-05-23 00:00:00.5127 Trace Opening \srmwstblog1\HttpLogging\M91803ED2137log.txt with allowFileSharedWriting=False
2018-05-23 00:00:00.5752 Trace FileTarget(Name=file): Archive attempt for file '\srmwstblog1\HttpLogging\M91803ED2628log.txt'
2018-05-23 00:00:00.5752 Debug FileAppender Closing Invalidate - \srmwstblog1\HttpLogging\M91803ED2628log.txt
2018-05-23 00:00:00.5752 Debug FileAppender Closing Invalidate - \srmwstblog1\HttpLogging\M91803ED2137log.txt
2018-05-23 00:00:00.5752 Debug FileTarget(Name=file): Do archive file: '\srmwstblog1\HttpLogging\M91803ED2628log.txt'
2018-05-23 00:00:00.5752 Trace FileTarget(Name=file): Archive pattern '\srmwstblog1\HttpLogging\M91803ED2628\log.{#}.txt'
2018-05-23 00:00:00.6221 Trace FileTarget: parsed date '2018-05-22' from file-template 'log.{#}.txt'
2018-05-23 00:00:00.6221 Trace FileTarget(Name=file): Calculating archive date. File-LastModifiedUtc: 05/22/2018 20:59:58; Previous LogEvent-TimeStamp: 05/23/2018 00:00:00
2018-05-23 00:00:00.6221 Trace FileTarget(Name=file): Using previous log event time (is more recent)
2018-05-23 00:00:00.6221 Trace FileTarget(Name=file): FinalizeFile '\srmwstblog1\HttpLogging\M91803ED2628log.txt, isArchiving: True'
2018-05-23 00:00:00.6221 Info FileTarget(Name=file): Archiving \srmwstblog1\HttpLogging\M91803ED2628log.txt to \srmwstblog1\HttpLogging\M91803ED2628\log.2018-05-23.0.txt
2018-05-23 00:00:00.6221 Debug FileTarget(Name=file): Move file from '\srmwstblog1\HttpLogging\M91803ED2628log.txt' to '\srmwstblog1\HttpLogging\M91803ED2628\log.2018-05-23.0.txt'
2018-05-23 00:00:00.6221 Debug FileTarget(Name=file): Process file '\srmwstblog1\HttpLogging\M91803ED2628log.txt' on startup
2018-05-23 00:00:00.6221 Debug Creating file appender: \srmwstblog1\HttpLogging\M91803ED2628log.txt
2018-05-23 00:00:00.6221 Trace Opening \srmwstblog1\HttpLogging\M91803ED2628log.txt with allowFileSharedWriting=False
2018-05-23 00:00:01.1065 Trace FileTarget(Name=file): Archive attempt for file '\srmwstblog1\HttpLogging\M91803ED2102log.txt'
2018-05-23 00:00:01.1065 Debug FileAppender Closing Invalidate - \srmwstblog1\HttpLogging\M91803ED2628log.txt
2018-05-23 00:00:01.1065 Debug FileTarget(Name=file): Do archive file: '\srmwstblog1\HttpLogging\M91803ED2102log.txt'
2018-05-23 00:00:01.1065 Trace FileTarget(Name=file): Archive pattern '\srmwstblog1\HttpLogging\M91803ED2102\log.{#}.txt'
2018-05-23 00:00:01.1221 Trace FileTarget: parsed date '2018-05-22' from file-template 'log.{#}.txt'
2018-05-23 00:00:01.1221 Trace FileTarget(Name=file): Calculating archive date. File-LastModifiedUtc: 05/22/2018 20:59:17; Previous LogEvent-TimeStamp: 05/23/2018 00:00:01
2018-05-23 00:00:01.1221 Trace FileTarget(Name=file): Using previous log event time (is more recent)
2018-05-23 00:00:01.1221 Trace FileTarget(Name=file): FinalizeFile '\srmwstblog1\HttpLogging\M91803ED2102log.txt, isArchiving: True'
2018-05-23 00:00:01.1221 Info FileTarget(Name=file): Archiving \srmwstblog1\HttpLogging\M91803ED2102log.txt to \srmwstblog1\HttpLogging\M91803ED2102\log.2018-05-23.0.txt
2018-05-23 00:00:01.1221 Debug FileTarget(Name=file): Move file from '\srmwstblog1\HttpLogging\M91803ED2102log.txt' to '\srmwstblog1\HttpLogging\M91803ED2102\log.2018-05-23.0.txt'
2018-05-23 00:00:01.1221 Debug FileTarget(Name=file): Process file '\srmwstblog1\HttpLogging\M91803ED2102log.txt' on startup
2018-05-23 00:00:01.1221 Debug Creating file appender: \srmwstblog1\HttpLogging\M91803ED2102log.txt
2018-05-23 00:00:01.1221 Trace Opening \srmwstblog1\HttpLogging\M91803ED2102log.txt with allowFileSharedWriting=False
2018-05-23 00:00:01.3721 Trace FileTarget(Name=file): Archive attempt for file '\srmwstblog1\HttpLogging\M91803ED2751log.txt'
2018-05-23 00:00:01.3721 Debug FileAppender Closing Invalidate - \srmwstblog1\HttpLogging\M91803ED2102log.txt
2018-05-23 00:00:01.3721 Debug FileTarget(Name=file): Do archive file: '\srmwstblog1\HttpLogging\M91803ED2751log.txt'
2018-05-23 00:00:01.3721 Trace FileTarget(Name=file): Archive pattern '\srmwstblog1\HttpLogging\M91803ED2751\log.{#}.txt'
2018-05-23 00:00:01.4971 Trace FileTarget: parsed date '2018-05-22' from file-template 'log.{#}.txt'
2018-05-23 00:00:01.4971 Trace FileTarget(Name=file): Calculating archive date. File-LastModifiedUtc: 05/22/2018 20:58:50; Previous LogEvent-TimeStamp: 05/23/2018 00:00:01
2018-05-23 00:00:01.4971 Trace FileTarget(Name=file): Using previous log event time (is more recent)
2018-05-23 00:00:01.4971 Trace FileTarget(Name=file): FinalizeFile '\srmwstblog1\HttpLogging\M91803ED2751log.txt, isArchiving: True'
2018-05-23 00:00:01.4971 Info FileTarget(Name=file): Archiving \srmwstblog1\HttpLogging\M91803ED2751log.txt to \srmwstblog1\HttpLogging\M91803ED2751\log.2018-05-23.0.txt
2018-05-23 00:00:01.4971 Debug FileTarget(Name=file): Move file from '\srmwstblog1\HttpLogging\M91803ED2751log.txt' to '\srmwstblog1\HttpLogging\M91803ED2751\log.2018-05-23.0.txt'
2018-05-23 00:00:01.4971 Debug FileTarget(Name=file): Process file '\srmwstblog1\HttpLogging\M91803ED2751log.txt' on startup
2018-05-23 00:00:01.4971 Debug Creating file appender: \srmwstblog1\HttpLogging\M91803ED2751log.txt
2018-05-23 00:00:01.4971 Trace Opening \srmwstblog1\HttpLogging\M91803ED2751log.txt with allowFileSharedWriting=False
2018-05-23 00:00:01.8409 Trace FileTarget(Name=file): Archive attempt for file '\srmwstblog1\HttpLogging\M91803ED2109log.txt'
2018-05-23 00:00:01.8409 Debug FileAppender Closing Invalidate - \srmwstblog1\HttpLogging\M91803ED2751log.txt
2018-05-23 00:00:01.8409 Debug FileTarget(Name=file): Do archive file: '\srmwstblog1\HttpLogging\M91803ED2109log.txt'
2018-05-23 00:00:01.8409 Trace FileTarget(Name=file): Archive pattern '\srmwstblog1\HttpLogging\M91803ED2109\log.{#}.txt'
2018-05-23 00:00:01.9503 Trace FileTarget: parsed date '2018-05-22' from file-template 'log.{#}.txt'
2018-05-23 00:00:01.9503 Trace FileTarget(Name=file): Calculating archive date. File-LastModifiedUtc: 05/22/2018 20:59:57; Previous LogEvent-TimeStamp: 05/23/2018 00:00:01
2018-05-23 00:00:01.9503 Trace FileTarget(Name=file): Using previous log event time (is more recent)
2018-05-23 00:00:01.9503 Trace FileTarget(Name=file): FinalizeFile '\srmwstblog1\HttpLogging\M91803ED2109log.txt, isArchiving: True'
2018-05-23 00:00:01.9503 Info FileTarget(Name=file): Archiving \srmwstblog1\HttpLogging\M91803ED2109log.txt to \srmwstblog1\HttpLogging\M91803ED2109\log.2018-05-23.0.txt
2018-05-23 00:00:01.9503 Debug FileTarget(Name=file): Move file from '\srmwstblog1\HttpLogging\M91803ED2109log.txt' to '\srmwstblog1\HttpLogging\M91803ED2109\log.2018-05-23.0.txt'
2018-05-23 00:00:01.9503 Debug FileTarget(Name=file): Process file '\srmwstblog1\HttpLogging\M91803ED2109log.txt' on startup
2018-05-23 00:00:01.9503 Debug Creating file appender: \srmwstblog1\HttpLogging\M91803ED2109log.txt

[snakefoot]

I can see now that my attempt to use _initializedFiles when _previousLogEventTimestamp belongs to a different filename is not working.

The problem is that _initializedFiles is updated before doing the archive operation. So when doing fallback to _initializedFiles then it actually finds the timestamp of the current LogEvent.

The _previousLogEventTimestamp is an optimization to avoid lookup in _initializedFiles for every LogEvent written.

Need to ponder a little on how to fix this.

[304NotModified]

The problem is that _initializedFiles is updated before doing the archive operation. So when doing fallback to _initializedFiles then it actually finds the timestamp of the current LogEvent.

Mabye we could copy (shallow clone I think)?) the old _initializedFiles for this case? Or would that too expensive?

[snakefoot]

Created a PR with a unit-test and a fix: #2736

[304NotModified]

\0/

[snakefoot]

@martys NLog 4.5.5 is now available: https://www.nuget.org/packages/NLog/4.5.5