Unexpected Archiving Behavior when ArchiveEvery="Day" and MaxArchiveFiles="1"

[meadjm]

NLog Unexpected Rolling\Archiving Behavior when ArchiveEvery="Day" and MaxArchiveFiles="1"

With our current NLog configuration, I would expect to have a log <dayNumber>_AppName.log (i.e. 07_AppName.log) for every day in the month. When the day log from the previous month exists, I would expect it to roll to the archive 00_AppName.0.log, truncate the existing day log for the new day (at or about 12:00:01 AM) and start logging again. The problem we are intermittently seeing is that the previous days log rolls to the archive file and its day log is either truncated or deleted. The current days day log is truncated as expected (but not archived). This effectively is giving us 2 logs for the entire month (if the files are deleted). The current day and previous day as the archive file or we get empty day logs if the files are truncated. We have several different applications using this configuration. The logging seems to work as expected for several days and then starts exhibiting this odd behavior. Another application we have consistently starts with this behavior immediately.

I recently updated the application from NLog 4.3.4 to 4.3.10 as it looks an archiving issue was resolved

Note: We really do not care about the archive file, but this was a work around for issue #1479. The archiving configuration forces the previous months log to be truncated. We are waiting for the fix that supports MaxArchiveFiles=0 to mean no archive files.

Any ideas what could be causing this?

Type Bug

NLog version: 4.3.10

Platform: .Net 4.0

Current NLog config:

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" autoReload="false">
    <variable name="logDirectory" value="D:\Logs"/>
    <variable name="logLayout" value="${longdate} | ${threadid:padding=-2} | ${level:padding=-5} ${callsite} | ${message} | ${onexception:EXCEPTION OCCURRED\:${Exception:format=type,message,method,stacktrace:maxInnerExceptionLevel=5}}"/>
    <targets>
        <default-target-parameters xsi:type="File" keepFileOpen="true" OpenFileCacheTimeout="5" ArchiveEvery="Day" ArchiveNumbering="Rolling" MaxArchiveFiles="1" />
        <target name="AppLog" xsi:type="File" fileName="${logDirectory}\${date:format=dd}_AppName.log" layout ="${logLayout}" />
    </targets>
    <rules>
        <logger name="*AppLog" minlevel="trace" writeTo="AppLog" />
    </rules>
</nlog>

[304NotModified]

I recently updated the application from NLog 4.3.4 to 4.3.10 as it looks an archiving issue was resolved

So there isn't an issue? I don't get it fully :(

[304NotModified]

Note: We really do not care about the archive file, but this was a work around for issue #1479. The archiving configuration forces the previous months log to be truncated. We are waiting for the fix that supports MaxArchiveFiles=0 to mean no archive files.

We don't support work around ;)

If you waiting for #1479, please give use feedback in that item.

[304NotModified]

Is this the issue that NLog is doing an append of the archive file?

(in internallog: "Already exists, append to ..)

[meadjm]

This is an issue when NLog's writing to an archive file. The behavior is inconsistent with identical configurations. We have hundreds of apps running using the configuration listed above. Sometimes it creates an archive file for the previous day and sometimes it does not. If I initially start with an empty log directory, NLog will intermittently create an archive for the previous day. I assume its renaming the file. Other times it will not create the archive leaving the previous days log naming convention as is.

I'm not sure what is going to happen at the end of the month when the directory is ether full with archive day files or no archives exist (only the original day logs exist). We have seen inconsistencies here as well. Sometimes NLog starts acting weird by creating 0 byte files for the current day log and we have to reset the application to resume normal logging. Our apps run for many months without resetting in a factory environment. Unfortunately I do not have an internallog that shows the issue. Our apps load the NLog configuration file from code so the AutoReload feature is not currently working (at this time) to enable the internallog when issue starts.

[304NotModified]

Without internal log this will be hard to fix. Unfortunately I don't know what's the cause of the problem.

Would be possible to write a test application to demonstrate the issue?

[snakefoot]

Just curious. Do you have multiple applications writing to the same file? (Since you have left the FileTarget.ConcurrentWrites to its default value = true)

[snakefoot]

Think a test application is needed. Have no issues when using the following nlog.config, together with the test-app from #1513 (NLog 4.4 RC1)

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" autoReload="false">
  <variable name="logDirectory" value="C:\Temp\nlog"/>
  <variable name="logLayout" value="${longdate} | ${threadid:padding=-2} | ${level:padding=-5} ${callsite} | ${message} | ${onexception:EXCEPTION OCCURRED\:${Exception:format=type,message,method,stacktrace:maxInnerExceptionLevel=5}}"/>
  <targets>
    <default-target-parameters xsi:type="File" keepFileOpen="true" OpenFileCacheTimeout="5" ArchiveEvery="Minute" ArchiveNumbering="Rolling" MaxArchiveFiles="1" />
    <target name="AppLog" xsi:type="File" fileName="${logDirectory}\${date:format=mm}_AppName.log" layout ="${logLayout}" />
  </targets>
  <rules>
    <logger name="**" minlevel="trace" writeTo="AppLog" />
  </rules>
</nlog>

[meadjm]

We do not have multiple applications writing to the same file so I believe the default value for ConcurrentWrites would be the correct setting.

[snakefoot]

FileTarget.ConcurrentWrites = true (The default when not configured), means multiple applications can perform concurrent writes to the same file (with help from a global mutex).