Writing to the same file from multiple processes does not function when concurrentWrites="true" and keepFileOpen="true"

[jonreis]

NLog version 4.2

Behavior seen: I have an application that spawns child process. Each child process writes to the same NLog log file. We have noticed that some child processes fail to write to the log, particularly when there is a roll-over of the log file, but also sometimes at startup.

Behavior expected: It must be expensive to have to open and close the file, so I would expect the keepFileOpen to work for a concurrent process scenario.

Work Around: It seems if keepFileOpen is set to false instead of true, then things work as expected.

I will paste in a test application that demonstrates this. If you would like a ready to run application, let me know and I will email it to you out of band.

To run the code:

1. tart the application. This will start up 5 processes
2. Verify the log file contains entries for all 5
3. Advance the date on your computer by 1 day
4. Verify the log file contains entries for all 5. In most cases it will not.

[jonreis]

using System;
using System.Diagnostics;
using System.Reflection;
using System.Threading;
using NLog;

namespace ConcurrentFileTargetTest
{
  class Program
  {
    private static readonly ILogger Logger = LogManager.GetCurrentClassLogger();
    static void Main(string[] args)
    {
      string processName;
      if (args.Length == 0)
      {
        processName = "0";
        for (int i = 1; i < 5; ++ i)
        {
          Process.Start(Assembly.GetEntryAssembly().Location, i.ToString());
        }
      }
      else
      {
        processName = args[0];
      }

      bool running = true;
      Console.CancelKeyPress += (sender, eventArgs) => running = false; // shutdown on Control-C
      while (running)
      {
        Logger.Debug("{0} - Happily Running Still", processName);
        Thread.Sleep(1000);
      }
    }
  }
}

[jonreis]

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog" />
  </configSections>

  <startup> 
        <supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.5" />
    </startup>

  <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" autoReload="true" internalLogFile="c:\temp\log.txt" internalLogLevel="Debug">
    <extensions>
      <add prefix="share" assembly="Connexion.Share" />
    </extensions>
    <targets>
       <target name="FileLogger" xsi:type="File" header = "------ Connexion v${assembly-version} ------" layout="${longdate} (${threadid}) ${level} [${logger}] ${message} ${exception:format=tostring}" fileName="${basedir}\logs\ConcurrentFileTargetTest.txt" archiveNumbering="Date" archiveEvery="Day" archiveDateFormat="yyyyMMdd" maxArchiveFiles="10" enableArchiveFileCompression="false" concurrentWrites="true" keepFileOpen="true" />
      <target name="ColoredConsole" xsi:type= "ColoredConsole" layout="${longdate} (${threadid}) ${level} [${logger}] ${message} ${exception:format=tostring}" />
    </targets>
    <rules>
      <logger name="*" minlevel="Debug" writeTo="FileLogger" />
      <logger name="*" minlevel="Debug" writeTo="ColoredConsole" />
    </rules>
  </nlog>
</configuration>

[304NotModified]

Thanks for this nice report. Also this will be checked, probably before Monday.

[304NotModified]

If you like, it would be helpful if you change above code into an unit test and send a PR.

[304NotModified]

Ow unit test will be difficult because of
#1022

[jonreis]

Yes, I looked at doing a unit test, but didn't know how to trick NLog into thinking the current datetime had changed. Also, I would have to spin up multiple processes which would mean I would have to check in my .exe from the test application I wrote.

[304NotModified]

I was thinking about this. Could this even work? If someone keeps it open, how could others write to it?

Why not keepFileOpen=false?

[jonreis]

I was thinking about this. Could this even work? If someone keeps it open, how could others write to it?

That is why Windows and other OS's have Share.ReadWrite | Share.Delete. Also, a process mutex is taking out for writing to the file. I'm not sure why FileLocks are not used, but I'm sure there is a reason.

Why not keepFileOpen=false?

Have you seen how this is implemented? It would be very poor performance. Each Logger loops until the file is available for writing. I would switch to another logging implementation before I would use this option.

The documentation sounds like it is meant to force keepFileOpen=true if concurrentWrites=true. So I'm sure it is supposed to work.

"concurrentWrites - Indicates whether concurrent writes to the log file by multiple processes on the same host. Boolean Default: True
This makes multi-process logging possible. NLog uses a special technique that lets it keep the files open for writing.
NOTE: are ignored unless keepFileOpen are set to true."

[304NotModified]

Have you seen how this is implemented?

Not in details, yet. I first try to get all the input from an issue, and then check the code.

It would be very poor performance. Each Logger loops until the file is available for writing. I would switch to another logging implementation before I would use this option.

Well I don't have that experience (and we use it form an application which spans a lot of threads and async tasks). If way more faster then just writing to file with standard .Net stuff (e.g. WriteLine to filestream)

[jonreis]

Well I don't have that experience (and we use it form an application which spans a lot of threads and async tasks). If way more faster then just writing to file with standard .Net stuff (e.g. WriteLine to filestream)

It is certainly great with multiple threads and async tasks. The issue here is the performance when you have multiple processes writing to the same log file. Here is the loop that is run for every message that is logged when you have concurrentWrites = "False". If multiple processes are writing to the same file, it has to open the file exclusively (because Share.None is used). If it fails to do so because another process is currently writing, it loops (as below) with a sleep until the file is available, or until the ConcurrentWriteAttempts has been reached. So there is no guarantee the message will actually be logged.

       protected FileStream CreateFileStream(bool allowFileSharedWriting)
        {
            int currentDelay = this.CreateFileParameters.ConcurrentWriteAttemptDelay;

            InternalLogger.Trace("Opening {0} with allowFileSharedWriting={1}", this.FileName, allowFileSharedWriting);
            for (int i = 0; i < this.CreateFileParameters.ConcurrentWriteAttempts; ++i)
            {
                try
                {
                    try
                    {
                        return this.TryCreateFileStream(allowFileSharedWriting);

So I think the original intent of using file sharing for writing to a single log file from multiple processes is valid and worthwhile fixing.

At any rate, Julian thank you for your time and effort on this.

[304NotModified]

Yes, I looked at doing a unit test, but didn't know how to trick NLog into thinking the current datetime had changed. Also, I would have to spin up multiple processes which would mean I would have to check in my .exe from the test application I wrote.

If we just span a lot of threads, isn't that enough? Then I will fix setting the datetime on the filetarget (#1022)

[jonreis]

Hi Julian, it is not a threading issue. It is a multi-process issue. Spinning up threads will not test this functionality. You need to spin up processes.

[304NotModified]

I can reproduce it:

archived log file:

new log file after archive:

[304NotModified]

I did some research into the filetarget recently. Will look at this soon.

[304NotModified]

notes:

• when keepFileOpen="true" => MutexMultiProcessFileAppender.TheFactory
• when keepFileOpen="false" => RetryingMultiProcessFileAppender.TheFactory

[304NotModified]

File "unknown" in process which isn't writing anymore: always that.

note:

• no exceptions founds
• It does do the this.file.Write, but sometimes it doens't work.. SafeFileHandle.IsInvalid = false, also SafeFileHandle.IsClosed = false

[304NotModified]

not sure where the problem lies. No exceptions, and just this.file.write/flush (filestream) is called (so no lock issues), but it won't write! Anyone an idea?

[s-sreenath]

Not Sure if this will be useful or you have seen this already.
http://stackoverflow.com/questions/18690537/multi-processes-readwrite-one-file
http://stackoverflow.com/questions/640122/is-there-a-global-named-reader-writer-lock?answertab=active#tab-top

[304NotModified]

Thanks for the info!

I will those in detail. Anyway good to know:

• We use the Mutex approach
• and this seems to work really good, but not after archive (File.Move).

[bhaeussermann]

This issue seems to be fixed with the latest build.

[304NotModified]

That would be great news! I will validate this (as I reproduced the issue before)

[304NotModified]

Confirmed :)

Tested it with branch https://github.com/NLog/NLog/tree/1029-Writing-to-the-same-file-from-multiple-processes

before merge the issue was again reproducible, after the merge it all works.

Thanks @bhaeussermann !

So fixed with release 4.3

[bhaeussermann]

I have done a deeper investigation of this issue.

The issue happens because of a rather strange anomaly involving file handles. The MutexMultiProcessFileAppender works using a FileStream that is constructed from a file handle with shared-writing access. When the log file is archived, it is moved to its new file path. This does not physically move the file, but merely makes an update in the file system's allocation table. This means that the file handle of the MutexMultiProcessFileAppender is still pointing to the same file which is now archived.

So with the current release of NLog, the following happens:

1. The first process to log after changing the date, archives the current log file, and its appender is invalidated. A new appender is created for the new log file.
2. This causes the last-write-time of the archived file to be updated.
3. The second process still has a handle to the now-archived file. It reads the updated last-write-time and concludes that the file must not be archived. It continues logging to that archived file.

The reason this issue no longer seems to be occuring in the new build is because we have changed the archiving-criteria to be based on the created-date of the file instead of the last-write-time. When the log file is moved to its archive file path, the created-date stays the same, so the second process will try to archive the file again. This does not succeed as the archive file already exists, but the file appender is nevertheless invalidated. Therefore a new file appender is created and the file handle is updated to point to the new log file.

When the archiving fails in the second process, it fails with an exception causing the log message to get lost. I have made a pull request that fixes this. This pull request also adds a test that tests against the situation described above so that we won't regress in the future (we emulate separate processes by configuring two different file targets that log the same file).

The new test still fails under Mono and I shall look into that.

[304NotModified]

Great work!

[jonreis]

Great job bhaeussermann!