Log4net не показывает правильный порядок для журналов из-за FileSystemWatcher - PullRequest
0 голосов
/ 23 ноября 2011

У нас странное поведение в отношении наших логов.Мы используем 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 иногда не будут отображаться в соответствующем порядке.Так что может быть причиной этого?

Вот вывод ОБНОВЛЕНО, основанный на ответе Стефана ...

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 постоянно регистрируются ... BTW, INFO и START - это просто смежные операторы друг с другом, также отмечают их время, INFO и FINISH регистрируются одновременно, в то время как START не регистрировался во времяв этот раз ...
Надеюсь, что вы можете порекомендовать больше идей по этому вопросу ...

ВТОРОЕ ОБНОВЛЕНИЕ: Мы наконец-то определили причину этого, причина, по которой некоторые журналы не регистрируются, из-заFileSystemWatcher, который просто прослушивает тот же журнал, который пишет наша функция веб-службы ...

Вот код:

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

                watcher.Changed += OnFileSystemChanged;
                watcher.EnableRaisingEvents = true;

Для 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 вКак регистрировать веб-сервис?

Ответы [ 3 ]

0 голосов
/ 24 ноября 2011

Вы работаете как веб-сервис, вероятно, под IIS.Это Log4Net FAQ с базовым ответом:

Прежде чем вы даже начнете пробовать какую-либо из предложенных альтернатив, спросите себя, действительно ли вам нужно, чтобы несколько процессов регистрировались втот же файл, тогда не делайте этого; -).

Даже с MinimalLock у вас будет конфликт блокировки и потеря сообщений.Это просто менее вероятно, чем с ExclusiveLock.

0 голосов
/ 09 декабря 2011

Увы!Мы точно определили причину прерывистой регистрации.Причина в основном заключается в открытии и закрытии файла каждый раз, когда к нему пишут.Спасибо всем за ваши идеи, это нам немного помогло.

0 голосов
/ 23 ноября 2011

Возможно, работает более 1 потока. Добавьте %thread к вашему шаблону конвертации и попробуйте снова. Если вы увидите разные идентификаторы потоков, вы узнаете, что происходит ...

...