【问题标题】:NLog does not flush all log entries upon process exitNLog 不会在进程退出时刷新所有日志条目
【发布时间】:2020-01-16 15:49:03
【问题描述】:

在这个线程中 - Should NLog flush all queued messages in the AsyncTargetWrapper when Flush() is called? - 我读到“LogManager 在域卸载或进程退出时将配置设置为空”(请参阅​​第一个答案中的编辑部分)。据我了解,这应该会导致所有挂起的日志条目都写入已注册的目标。然而,在用FileTarget 包裹AsyncTargetWrapper 进行测试后,这并不成立。我在 GitHub 上创建了一个最小的 repro - https://github.com/PaloMraz/NLogMultiProcessTargetsSample,它的工作原理如下:

LogLib 是一个 .netstandard2.0 库,它引用 NLog 4.6.8 NuGet 包并公开一个 CompositeLogger 类,该类以编程方式配置 NLog 目标:

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 是一个 .NET Framework 4.8 控制台应用程序,它使用 LogLib.CompositeLogger 将指定数量的日志消息写入文件(指定为命令行参数),写入之间的延迟很短:

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);
    }
  }
}

最后,LogTest 是一个 XUnit 测试程序集,其中一个测试启动了十个写入同一日志文件的 LogConsoleRunner 实例:

[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);
}

最后一行的Assert.Equal 总是失败,因为目标文件写入的行数总是少于预期的计数,即 100。在我的机器上,每次运行它都会在 96 - 99 之间变化,但它从不包含全部 100 行。

我的问题:我应该如何配置NLog 以确保在所有进程退出后,所有待处理的日志条目都写入目标日志文件?

【问题讨论】:

    标签: c# .net logging multiprocessing nlog


    【解决方案1】:

    查看了您的示例代码,您有多个进程写入相同的文件名。

    认为您是性能和正确性之间妥协的受害者。

    当多个进程同时写入同一个文件时,需要一些锁定以进行协调。默认情况下,NLog 使用最兼容的模式 (KeepFileOpen=false),即来自操作系统的文件锁定(适用于大多数平台)。

    来自操作系统的文件锁定是不公平的,并且当超过 2 个进程写入同一个文件时无法扩展。当一个进程试图打开一个文件,而该文件当前正被另一个进程使用时,将会抛出异常。

    NLog 尝试通过重试错误 (concurrentWriteAttempts=10) 以及随机化在重试前等待多长时间来处理这些异常。这适用于 2 个进程,但当您开始增加进程数时,它会增加一个进程连续 10 次成为倒霉进程的机会。在最后一次重试之后,NLog 会丢弃 LogEvent(可能是您所看到的)。

    KeepFileOpen=false 很慢(300 次写入/秒),当与重试逻辑结合使用时,它变得非常慢。但是通过在允许批处理时使用 AsyncWrapper,它几乎可以消除性能损失。但是现在,当重试次数用完时,可能会丢失整批。

    您可以依赖 NLog 使用全局互斥锁进行进程间通信,而不是依赖操作系统文件锁。此模式通过KeepFileOpen=TrueConcurrentWrites=true 启用。而不是每秒 300 次写入,而是每秒写入 100.000 次,并且锁定机制更公平,因此无需重试。并非所有平台都支持此模式,但应该在 Windows 上的 .NET 4.8(和 Linux 上的 NetCore2)上运行良好。

    另请参阅:https://github.com/NLog/NLog/wiki/File-target#Multi-processes-writing-same-file

    【讨论】:

    • 非常感谢您的解释!事实上,推荐的FileTarget 设置解决了并发写入问题:KeepFileOpen = trueConcurrentWrites = true。我还更新了 GitHub 示例项目供其他人查看 f31dfc8ad63f3f857262cbccdd68f26f8459573a...
    【解决方案2】:

    只需拨打LogManager.Shutdown() 在您的Main 末尾。它将刷新所有待处理的日志事件。 Read more.

    旁注:如果您在刷新后需要 NLog,那么您可以使用 LogManager.Flush() 而不是关闭。

    【讨论】:

    猜你喜欢
    • 2023-03-05
    • 1970-01-01
    • 1970-01-01
    • 1970-01-01
    • 1970-01-01
    • 1970-01-01
    • 2020-02-20
    • 2016-05-22
    • 2013-06-18
    相关资源
    最近更新 更多