Nlog: FileTarget not writing header when archiving is turned on

[MatthewRiggott]

Edit: Since this may be relevant. To test this behavior, I was running the program and changing the Date on my system clock / win 10. I can also provide a simplified console program if necessary

NLog version: (e.g. 4.4.13)

Platform: .Net45

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="true">
  <targets>
    <target name="console" xsi:type="Console" layout="${longdate} [${level}] ${callsite}: ${message}"/>
    <target name="eventlog"
            keepFileOpen="true"
            openFileCacheTimeout="15"
            concurrentWrites="true"
            archiveFileName="logs/archive-{#}.log"
            archiveNumbering="Date"
            archiveDateFormat="yyyy-MM-dd"
            maxArchiveFiles="30"
            archiveEvery="Day"
            xsi:type="File"
            fileName="logs/log-${shortdate}.log"
            layout="${longdate}: ${message}"/>
  </targets>

  <rules>
    <logger name="*" minlevel="Trace" writeTo="console" enabled="true"/>
    <logger name="eventlog" minlevel="Info" writeTo="eventlog" enabled="true"/>
  </rules>

</nlog>

I also manually configure the header via code

            var LogConfig = LogManager.Configuration;
            var Target = LogConfig.FindTargetByName("eventlog") as FileTarget;
            var CurrentDate = DateTime.Now;
            var BuildString = $@"----------------------------------------
-----------  Information ---------------
- Version: {Configuration.Version}
- Build: {Configuration.Build}
- Date: {Configuration.TimeStamp}
- Today: {CurrentDate}
----------------------------------------";

            _headerString = BuildString;
            Target.Layout = new LayoutWithHeaderAndFooter() { Header = BuildString, Layout = Target.Layout };

• What is the current result?
  I am using the FileTarget to log to a file with a filename based on the date. At the start of my application, I modify the Header layout with specific info and it works great for the first write. Once the first file is archived, no further files will render the header information.

• What is the expected result?
  I believe the header should be written first whenever a new file is created (daily in my case), even when archiving old files.

• Did you checked the Internal log?
  Yep, no errors. Behavior matches the code.

• Please post full exception details (message, stacktrace, inner exceptions)
  No exceptions, but upon cloning NLog, checking out 4.7.4 and stepping through I found that the FileTarget ProcessLogEvent method has the following happening ---

        private void ProcessLogEvent(LogEventInfo logEvent, string fileName, ArraySegment<byte> bytesToWrite)
        {
            // min value as expected
            DateTime previousLogEventTimestamp = InitializeFile(fileName, logEvent);

            // this is true as previousLogTimeStamp is DateTime.MinValue
            bool initializedNewFile = previousLogEventTimestamp == DateTime.MinValue;


            if (initializedNewFile && fileName == _previousLogFileName && _previousLogEventTimestamp.HasValue)
                previousLogEventTimestamp = _previousLogEventTimestamp.Value;

            // this is true, file gets archived
            bool archiveOccurred = TryArchiveFile(fileName, logEvent, bytesToWrite.Count, previousLogEventTimestamp, initializedNewFile);

            if (archiveOccurred)
                // this makes intializedNewFile to false, as initializeFile was already called and sets a DateTime to the  `initialized files` Dictionary
                initializedNewFile = InitializeFile(fileName, logEvent) == DateTime.MinValue;

            if (ReplaceFileContentsOnEachWrite)
            {
                ReplaceFileContent(fileName, bytesToWrite, true);
            }
            else
            {
                // write to header does not get called inside WriteToFile as initializedNewFile is false
                WriteToFile(fileName, bytesToWrite, initializedNewFile);
            }
            ....

• Are there any workarounds?
  Yes - disable archiving and the header will print to each newly created file.

• Is there a version in which it did work?
  I have only tried 4.7.4

• Can you help us by writing an unit test?
  Will follow up later, should be able to.

[welcome[bot]]

Hi! Thanks for opening your first issue here! Please make sure to follow the issue template - so we could help you better!

[snakefoot]

I can reproduce the issue, and I guess it is a bug. But bug is triggered by using "Dynamic FileName Archive Logic" together with "Static FileName Archive Logic".

• Dynamic FileName Archive Logic - Enabled by using fileName="${shortdate}.log". This means it will roll / archive dynamically because of the layout-renderer-logic.

• Static FileName Archive Logic - Enabled by using archiveEvery="Day" and archiveFileName="...". This means it will expect the FileName to be static (Ex. fileName="app.log").

See also https://github.com/NLog/NLog/issues/3807#issuecomment-587661413

Trying to think of a use-case that will trigger this issue, but without it being caused by mixing the 2 archive-modes.

[snakefoot]

Try doing this instead (Stop using static filename archive logic):

    <target name="eventlog"
            xsi:type="File"
            keepFileOpen="true"
            openFileCacheTimeout="15"
            concurrentWrites="true"
            maxArchiveFiles="30"
            fileName="logs/log-${shortdate}.log"
            layout="${longdate}: ${message}"/>

[snakefoot]

Funny that #1271 actually tries to make Dynamic FileName Archive Logic work together with Static FileName Archive Logic.

But the patch only works as long the application is not restarted. But it is actually that logic that kicks in. Can also see the patch-logic had several side-effects and have evolved a lot.

[snakefoot]

Created #4106 that extends the unit-test created for #1271 to verify that header is also correctly written.

Mixing Dynamic FileName Archive Logic with Static FileName Archive Logic still remains unsupported territory.

[MatthewRiggott]

Try doing this instead (Stop using static filename archive logic):

    <target name="eventlog"
            xsi:type="File"
            keepFileOpen="true"
            openFileCacheTimeout="15"
            concurrentWrites="true"
            maxArchiveFiles="30"
            fileName="logs/log-${shortdate}.log"
            layout="${longdate}: ${message}"/>

Works great, thank you kindly!

Issue 3807 gave me the understanding I was missing with Dynamic and Static file name logic.

[snakefoot]

Yes the archive-logic has grown organically in the NLog-project, where it initially had best support for static-filename-archive-logic. This also worked very well when using tail-applications, where it should just monitor a single static-filename. Lots of fancy features was implemented to support this mode.

Later users started to make use of the dynamic layout-renderers in the filename, and suddenly the dynamic-filename-archive-logic was born. When having ${shortdate} in the filename, then there was no need for file rename or move. But the logic to perform archive-file-cleanup suddenly had to be a little more clever / fuzzy, since the NLog-users could choose whatever FileName-format they preferred.

Maybe one day one will create a complete solution where dynamic filename-logic can do stuff like:

• Move old files to other folder / network-drive (in background)
• Compress old files (in background and continue on application restart)
• Avoid renaming files on archiveAboveSize (Since rename / moving the active file is a source of errors, requires extra file-system-permissions, file-access-conflicts with other applications.).

Since both static and dynamic-mode are useful, then I guess neither of them will disappear. But there is a lot of old guides that only introduces the static-filename-archive-logic. But many times NLog-users adjusts the config to enable dynamic-filename-archive-logic, and forgets to remove the stuff that is only intended for static-filename-archive-logic.

[snakefoot]

Notice that if you inject the application-static into GDC like this at startup:
```c#
NLog.GlobalDiagnosticsContext.Set("AppInfo_Version", Configuration.Version);
NLog.GlobalDiagnosticsContext.Set("AppInfo_Build", Configuration.Build);
NLog.GlobalDiagnosticsContext.Set("AppInfo_TimeStamp", Configuration.TimeStamp);
NLog.GlobalDiagnosticsContext.Set("AppInfo_CurrentDate", CurrentDate);

Then you can do this:

```xml
    <target name="eventlog"
            xsi:type="File"
            keepFileOpen="true"
            openFileCacheTimeout="15"
            concurrentWrites="true"
            maxArchiveFiles="30"
            fileName="logs/log-${shortdate}.log"
            layout="${longdate}: ${message}">
            <header><![CDATA[----------------------------------------
-----------  Information ---------------
- Version: ${gdc:AppInfo_Version}
- Build: ${gdc:AppInfo_Build}
- Date: ${gdc:AppInfo_TimeStamp}
- Today: ${gdc:AppInfo_CurrentDate}
----------------------------------------]]></header>
     </target>

And remove the logic with calling FindTargetByName("eventlog") and adjusting Header-property.

[snakefoot]

Resolved by #4106