NLog does not flush all log entries upon process exit

Question

In this thread - Should NLog flush all queued messages in the AsyncTargetWrapper when Flush() is called? - I am reading that „LogManager sets the config to null on domain unload or process exit“ (see the Edit section in the 1st answer). In my understanding, this should cause all the pending log entries be written to registered targets. However, after testing with FileTarget wrapped with AsyncTargetWrapper, this does not hold true. I have created a minimal repro on GitHub - https://github.com/PaloMraz/NLogMultiProcessTargetsSample, which works as follows:

LogLib is a .netstandard2.0 library referencing NLog 4.6.8 NuGet package and exposing a CompositeLogger class which programmatically configures the NLog targets:

public class CompositeLogger
{
  private readonly ILogger _logger;

  public CompositeLogger(string logFilePath)
  {
    var fileTarget = new FileTarget("file")
    {
      FileName = logFilePath,
      AutoFlush = true
    };
    var asyncTargetWrapper = new AsyncTargetWrapper("async", fileTarget)
    {
      OverflowAction = AsyncTargetWrapperOverflowAction.Discard
    };

    var config = new LoggingConfiguration();
    config.AddTarget(asyncTargetWrapper);
    config.AddRuleForAllLevels(asyncTargetWrapper);
    LogManager.Configuration = config;

    this._logger = LogManager.GetLogger("Default");
  }

  public void Log(string message) => this._logger.Trace(message);
}

LogConsoleRunner is a .NET Framework 4.8 console app that uses LogLib.CompositeLogger to write specified number of log messages to a file (specified as a command line argument) with a short delay between writes:

public static class Program
{
  public const int LogWritesCount = 10;
  public static readonly TimeSpan DelayBetweenLogWrites = TimeSpan.FromMilliseconds(25);

  static async Task Main(string[] args)
  {
    string logFilePath = args.FirstOrDefault();
    if (string.IsNullOrWhiteSpace(logFilePath))
    {
      throw new InvalidOperationException("Must specify logging file path as an argument.");
    }

    logFilePath = Path.GetFullPath(logFilePath);
    Process currentProcess = Process.GetCurrentProcess();
    var logger = new CompositeLogger(logFilePath);
    for(int i = 0; i < LogWritesCount; i++)
    {
      logger.Log($"Message from {currentProcess.ProcessName}#{currentProcess.Id} at {DateTimeOffset.Now:O}");
      await Task.Delay(DelayBetweenLogWrites);
    }
  }
}

Finally, LogTest is a XUnit test assembly with one test launching ten LogConsoleRunner instances writing to the same log file:

[Fact]
public async Task LaunchMultipleRunners()
{
  string logFilePath = Path.GetTempFileName();
  using var ensureLogFileDisposed = new Nito.Disposables.AnonymousDisposable(() => File.Delete(logFilePath));

  string logConsoleRunnerAppExePath = Path.GetFullPath(
    Path.Combine(
      Path.GetDirectoryName(this.GetType().Assembly.Location),
      @"..\..\..\..\LogConsoleRunner\bin\Debug\LogConsoleRunner.exe"));      
  var startInfo = new ProcessStartInfo(logConsoleRunnerAppExePath)
  {
    Arguments = logFilePath,
    UseShellExecute = false
  };
  const int LaunchProcessCount = 10;
  Process[] processes = Enumerable
    .Range(0, LaunchProcessCount)
    .Select(i => Process.Start(startInfo))
    .ToArray();
  while (!processes.All(p => p.HasExited))
  {
    await Task.Delay(LogConsoleRunner.Program.DelayBetweenLogWrites);
  }

  string[] lines = File.ReadAllLines(logFilePath);
  Assert.Equal(LaunchProcessCount * LogConsoleRunner.Program.LogWritesCount, lines.Length);
}

The Assert.Equal on the last line always fails, because the target file has always less lines written than the expected count, which is 100. On my machine, it varies with each run between 96 – 99, but it never contains all 100 lines.

My question: how should I configure NLog to make sure that after all processes exit, all pending log entries are written to the target log file?

Answer 1

Just call LogManager.Shutdown() at the end of your Main. It will do a flush of all pending logevents. Read more.

Side note: If you need NLog after flush, then instead of shutdown you could use LogManager.Flush().

Answer 2

Have looked at your example code, and you have multiple processes writing to the same filename.

Think you are the victim of the compromise between performance and correctness.

When multiple processes are concurrently writing to the same file, then some locking for coordination is needed. By default NLog use the most compatible mode (KeepFileOpen=false), which is file locks from the operating system (works for most platforms).

File locking from operating system are not fair and doesn't scale when having more than 2 processes writing to the same file. Exceptions will be thrown when one process tries to open a file, that is currently in use by another process.

NLog tries to handle these exception by retrying on error (concurrentWriteAttempts=10) together with randomizing how long to wait before retry. This works okay for 2 processes, but when you start to increase the number of processes, then it increases the chance that one process is the unlucky one 10 times in a row. After the last retry then NLog discards the LogEvent (probably what you are seeing).

KeepFileOpen=false is slow (300 writes/sec), and when combined with retry-logic then it becomes extremely slow. But by using the AsyncWrapper when you allow batching, and it pretty much removes the performance hit. But now a whole batch can be lost when retry count has been used up.

Instead of relying on the operating system file-locks, then you can instead rely on NLog doing inter-process communication using global mutex. This mode is enabled with KeepFileOpen=True and ConcurrentWrites=true. Instead of 300 writes/sec then it becomes 100.000 writes/sec and the locking mechanism is more fair, so no need for retries. Not all platforms support this mode, but should work great on .NET 4.8 on Windows (And NetCore2 on Linux).

See also: https://github.com/NLog/NLog/wiki/File-target#Multi-processes-writing-same-file