Logging into single file from multi-process

Introduction

When you want to log from multisource into single log using log4net, the theory is using AdoNetAppender or EventLogAppender.

But if it's hard to use Databases , EventLog, syslog and so on. Here is the way to logging into single logfile from mutli-process runnning concurrently.

Problem

The problem of using Fileappender from processes runnning concurrently is file lock confilict.
When the first process gets write lock for logfile, any other process can't get write lock for logfile and can't write a LogEntry into logfile.

log4net has a solution for this problem, it's called MinimalLock locking model.
In this locking model, log4net gets write lock when the looger write LogEntry into logifile, and release lock once LogEntry is logged.
So this locking model holds lock for minimal time, it's reduce the conflicts but not eliminate.

I extends Minimallock and eliminate conflict.

Solution

The concept is,
1. Caching LogEntry into cache instead of writing into file directory.
2. Dequeue and writing into file in new thread.
3. When Confilict is detected, wait random time and retry.

public class ConcurrentMinimalLock : FileAppender.MinimalLock
 {
  private string m_filename;
  private bool m_append;
  private Stream m_stream=null;
  private ConcurrentStream c_stream = null;
  public override void OpenFile(string filename, bool append, Encoding encoding)
  {
   m_filename=filename;
   m_append=append;
  }
  public override void CloseFile()
  {
   // NOP
  }
  public override Stream AcquireLock()
  {
   if (m_stream==null)
   {
    try
    {
     using(CurrentAppender.SecurityContext.Impersonate(this))
     {
      string directoryFullName = Path.GetDirectoryName(m_filename);
      if (!Directory.Exists(directoryFullName))
      {
       Directory.CreateDirectory(directoryFullName);
      }
      
      if(c_stream == null)
      {
       c_stream = ConcurrentStream.GetInstance(m_filename, m_append, FileAccess.Write, FileShare.Read);
      }
      m_stream = c_stream;
      m_append=true;
     }
    }
    catch (Exception e1)
    {
     CurrentAppender.ErrorHandler.Error("Unable to acquire lock on file "+m_filename+". "+e1.Message);
    }
   }
   return m_stream;
  }
  public override void ReleaseLock()
  {
   using(CurrentAppender.SecurityContext.Impersonate(this))
   {
    m_stream.Close();
    m_stream=null;
   }
  }
 }

First, I extends MinimalLock Class and Replace stream with ConcurrentStream

public class ConcurrentStream : Stream
 {
  private string path;
  private bool append;
  private FileAccess access;
  private FileShare share;
  private QueueManager queueManager;
  private static ConcurrentStream instance;
  
  public static ConcurrentStream GetInstance(string path,
   bool append,
   FileAccess access,
   FileShare share)
  {
   if(instance == null)
   {
    instance = new ConcurrentStream(path,append,access,share);
   }
   return instance;
  }
  private ConcurrentStream (
   string path,
   bool append,
   FileAccess access,
   FileShare share
   )
  {
   this.path = path;
   this.append = append;
   this.access = access;
   this.share = share;
   this.queueManager = QueueManager.GetInstance(path,append,access,share);
  }

  public override void Write(byte[] buffer, int offset, int count)
  {
   CachedEntry entry = new CachedEntry(buffer,offset,count);
   queueManager.Enqueue(entry);
  }
 }

Next, Create ConcurrentStream Class extending Stream.
Write method doesn't write directly, instead write information into queue.

internal class QueueManager
 {
  
  private string path;
  private bool append;
  private FileAccess access;
  private FileShare share;
  
  private Queue syncQueue = Queue.Synchronized(new Queue());
  
  private bool running = false;
  private Random rnd = new Random();
  private DateTime retryTime = DateTime.MaxValue;
  
  private static TimeSpan RETRY_MAX_SPAN = TimeSpan.FromMinutes(1);
  private static QueueManager instance;
  private const int MAX_BATCH_SIZE = 100;
  
  
  public static QueueManager GetInstance(string path,
            bool append,
            FileAccess access,
            FileShare share)
  {
   if(instance == null)
   {
    instance = new QueueManager(path,append,access,share);
   }
   return instance;
  }
  private QueueManager(
   string path,
   bool append,
   FileAccess access,
   FileShare share)
  {
   this.path = path;
   this.append = append;
   this.access = access;
   this.share = share;
  }
  internal void Enqueue(CachedEntry entry)
  {
   syncQueue.Enqueue(entry);
   
   if(!running)
   {
    lock(this)
    {
     running = true;
     Thread th = new Thread(new ThreadStart(this.Dequeue));
     th.Start();
    }
   }
  }
  private void Dequeue()
  {
   CachedEntry entry =null;
   try
   {
    using(FileStream fs = new FileStream(path,FileMode.Append,access,share))
    {
     int processedCount = 0;
     while(true)
     {
      processedCount ++;
      if(syncQueue.Count == 0)
      { 
       //quit when queue is empty
       lock(this)
       {
        running = false;
        return;
       }
      }
      else
      {
       entry = (CachedEntry) syncQueue.Dequeue();
      }
  
      if(entry !=null )
      {
       Write(entry,fs);
      }
     }
    }
   }
   catch(IOException ioe)
   {
    if(DateTime.Now - retryTime > RETRY_MAX_SPAN)
    {
     lock(this)
     {
      running = false;
     }
     throw;
    }
    //When can't aquire lock
    //Wait random time then retry
    Thread.Sleep(rnd.Next(1000));
    Console.WriteLine("Retry:" + DateTime.Now);
    retryTime = DateTime.Now;
    Dequeue();
   }
  }
  private void Write(CachedEntry entry,FileStream fs)
  {
   fs.Write(entry.Buffer,entry.Offset,entry.Count);
   fs.Flush();
  }
 }

And above is the queue implementation.
When logentry is enqued, dequeue is runnnin on new thread.
When the conflict occurs, wait random and then retry.(like CSMA/CD)

Thus, we can make multi-process logging successsully.

internal class CachedEntry
 {
  private byte[] buffer;
  private int offset;
  private int count;
  internal byte[] Buffer
  {
   get{return buffer;}
  }
  internal int Offset
  {
   get {return offset;}
  }
  internal int Count
  {
   get {return count;}
  }
  internal CachedEntry(byte[] buffer, int offset, int count)
  {
   this.buffer = new byte[buffer.Length];
   buffer.CopyTo(this.buffer,0);
   this.offset = offset;
   this.count = count;
  }
 }

Finally, above is the entry queued.

And cofiguration file looks like below

<configuration>
 <configSections>
  <section name="log4net" type="System.Configuration.IgnoreSectionHandler" />
 </configSections>
 
 <log4net>
  <appender name="AppenderTest" type="log4net.Appender.FileAppender">
   <param name="File" value="C:\\temp\\logtest.txt" />
   <param name="AppendToFile" value="true" />
   
   <param name="LockingModel" type="ConcurrentLog.ConcurrentMinimalLock,ConcurrentLog"/>
   
   <layout type="log4net.Layout.PatternLayout">
    <param name="ConversionPattern" value="%d [%t] %-5p - %m%n" />
   </layout>
  </appender>
  
  
  <logger name="LoggerTest">
   <level value="DEBUG" />
   <appender-ref ref="AppenderTest" />
  </logger>
  
 </log4net>
</configuration>