Log4net doesn't show the right order for Logs because of FileSystemWatcher

Question

We're having this weird behavior regarding our logs. We're using log4net and here is our configuration:

<?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> 

Here is our sample of how we used it in our code:

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

Now here is the sample output log inside 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

As you can observe above from the first two lines, after INFO was logged the next line was FINISH, it skipped START. Then for the next lines START will show up with their corresponding order but sometimes it won't. INFO will always show up but START and FINISH sometimes will not show with their corresponding order. So what could be the reason for this?

Here is the UPDATED output based on what Stefan replied...

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

As you can see, there is only one thread working...Still START wasn't logged but INFO and FINISH is consistently been logged...BTW, INFO and START are just adjacent statements with each other also note their time, INFO and FINISH are logged at the same time while START was not logged during that time...
Hope you can recommend more ideas on this one...

SECOND UPDATE: We have finally pinpointed the cause for this one, the cause why some logs are not logged is because of the FileSystemWatcher that is just listening to the same log our web service function is writing...

Here is the code:

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

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

For the 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;
    }
}

So what it basically does is just listening to the log file then write the logs to the output... Is there any way that these logs will be recorded orderly without FileSystemWatcher intervening the logging of the web service?

Answer 1

Alas! We've pinpointed it accurately the cause for intermittent logging. The reason mainly is the opening and closing of file everytime there is wriiten to it. Thank you everyone for your ideas it helped us a bit.