由于FileSystemWatcher的原因，Log4net没有显示日志的正确顺序

本文关键字：日志 显示 顺序 Log4net FileSystemWatcher 由于 | 更新日期: 2023-09-27 18:15:24

我们的日志有这种奇怪的行为。我们正在使用log4net，下面是我们的配置:

<?xml version="1.0" encoding="utf-8"?>
  <configuration>
      <configSections>
        <section name="log4net" type="System.Configuration.IgnoreSectionHandler" />
      </configSections>
      <log4net>
        <appender name="LogAppenderinfo" type="log4net.Appender.RollingFileAppender">
          <file value="..'log'filename.log" />
          <appendToFile value="true" />
          <maxSizeRollBackups value="0" />
          <maximumFileSize value="10MB" />
          <rollingStyle value="Size" />
          <staticLogFileName value="true" />
          <lockingmodel type="log4net.Appender.FileAppender+MinimalLock"/>
          <layout type="log4net.Layout.PatternLayout">        
             <conversionPattern value="%date{MMM dd HH:mm:ss,fffffff}|: %message%newline%exception" />
          </layout>
        </appender>
      <root>
         <level value="ALL" />
      </root>
      <logger name = "filename.log">
         <level value="ALL" />
         <appender-ref ref="LogAppenderinfo" />
      </logger>
     </log4net>
 </configuration>

下面是我们如何在代码中使用它的示例:

internal static ILog logm = LogManager.GetLogger("filename.log");
public void WebServerFunction()        
{
    logm.DebugFormat("INFO   |Web server call WebServerFunction for: {0}", param);
    logm.DebugFormat("START  |      WebServerFunction started for: {0}", param);
    //some code here then another logging in the end of the function call
    logm.DebugFormat("FINISH |      WebServerFunction finished for: {0}", param);
}

现在这里是示例输出日志在filename.log:

Nov 22 17:31:25,6183343|: INFO   |Web server call WebServerFunction for: NET_10.10.11.0_24
Nov 22 17:31:25,6183343|: FINISH |      WebServerFunction finished for: NET_10.10.11.0_24
Nov 22 17:31:27,6331853|: INFO   |Web server call WebServerFunction for: NET_10.10.11.0_24
Nov 22 17:31:27,6488043|: START  |      WebServerFunction started for: NET_10.10.11.0_24
Nov 22 17:31:27,6488043|: FINISH |      WebServerFunction finished for: NET_10.10.11.0_24

从上面的前两行可以看到，在记录了INFO之后，下一行是FINISH，它跳过了START。然后对于接下来的行，START将以相应的顺序显示，但有时不会。INFO将始终显示，但START和FINISH有时将不显示与其相应的顺序。这其中的原因是什么呢?

这是基于Stefan回答的更新输出…

Nov 24 12:59:45,2113366|11   : INFO   |Web server call WebServerFunction() for: NET_10.191.20.0_24
Nov 24 12:59:45,2113366|11   : START  |      WebServerFunction started for: NET_10.191.20.0_24
Nov 24 12:59:45,2113366|11   : FINISH |      WebServerFunction finished for: NET_10.191.20.0_24
Nov 24 12:59:47,2268842|11   : INFO   |Web server call WebServerFunction() for: NET_10.191.20.0_24
Nov 24 12:59:47,2268842|11   : FINISH |      WebServerFunction finished for: NET_10.191.20.0_24
Nov 24 12:59:47,2425086|11   : INFO   |Web server call WebServerFunction() for: NET_10.191.20.0_24
Nov 24 12:59:47,2425086|11   : FINISH |      WebServerFunction finished for: NET_10.191.20.0_24
Nov 24 12:59:49,2580562|11   : INFO   |Web server call WebServerFunction() for: NET_10.191.20.0_24
Nov 24 12:59:49,2736806|11   : FINISH |      WebServerFunction finished for: NET_10.191.20.0_24

如你所见，只有一个线程在工作…仍然没有记录START，但INFO和FINISH一直被记录…顺便说一句，INFO和START只是相邻的语句，并且注意它们的时间，INFO和FINISH同时被记录，而START在那段时间没有被记录…
希望你能推荐更多关于这个的想法…

第二次更新:我们终于找到了这个问题的原因，一些日志没有被记录的原因是因为FileSystemWatcher只是在监听我们的web服务函数正在写入的日志…

代码如下:

watcher = new FileSystemWatcher(logDirectory, FileName)
                {
                    NotifyFilter = NotifyFilters.LastWrite /*| NotifyFilters.LastAccess | NotifyFilters.Size*/
                };
                watcher.Changed += OnFileSystemChanged;
                watcher.EnableRaisingEvents = true;

For OnFileSystemChanged:

private static void OnFileSystemChanged(object source, FileSystemEventArgs e)
{
    try
    {
        if (e.ChangeType == WatcherChangeTypes.Changed)
        {
            var data = ReadFromFileWithRetries(e.FullPath);
            if (data != null && data != _prevData)
            {
                if (data.Length > _prevData.Length)
                {
                    _prevData = data.Remove(0, _prevData.Length);
                }
                Console.WriteLine(_prevData);
                _prevData = data;
            }
        }
    }
    catch (Exception exception)
    {
        var msg = exception.Message;
    }
}

所以它基本上只是监听日志文件，然后将日志写入输出…是否有任何方法可以在没有FileSystemWatcher干预web服务日志记录的情况下有序地记录这些日志?

由于FileSystemWatcher的原因，Log4net没有显示日志的正确顺序

可能有超过1个线程在工作。将%thread添加到您的转换模式中，然后重试。如果您看到不同的线程id，那么您将知道发生了什么…

您正在作为web服务运行，可能在IIS下。这是一个Log4Net常见问题解答，基本答案是:

在开始尝试提供的任何替代方案之前，请先问自己是否真的需要将多个进程记录到同一个文件中，然后不要这样做;-)。

即使使用MinimalLock，也会有锁争用和消息丢失。

唉!我们已经准确地找到了间歇性日志记录的原因。其原因主要是每次有写入时文件的打开和关闭。谢谢大家的意见，对我们有很大帮助。

相关文章：