Using Memory Appenders in Log4net (All your logging are belong to us)

I have always been a keen advocate of Trace logging as useful tool for tracking down bugs in Test and Production environments, those where it is not possible to hook up a debugger to the web service or windows service.

There is an important problem, though with trace logging as it's normally done in Production, and this is that it's not verbose enough. It is considered good practice to dial down the logging level so that only errors get logged  but this can be a big problem as all that gets logged is the exception, which sometimes is simply not enough to diagnose the problem.

I do believe that this is a good practice for various reasons (less load on the server, no need to worry about log size, etc..), but it is also true that a production system logging at its highest verbosity can be useless due to the amount of messages that get logged.

If an error happens that cannot be diagnosed from the limited logging; logging is normally set to 11 and it is hoped that the error happens again and can be diagnosed.

In an ideal world we would want to log everything leading up to an error and there is a nice way of doing this with the log4net library, as it provides a way to log to memory.

The idea is to log everything to a memory listener and only dump it to the final log (file/Event Log/DB) in case of an exception, or any other condition that might require writing to file/DB, e.g. auditing.

Memory usage would need to be monitored in a real application to see how much of an impact this has, but seeing as memory is cheap and developers are expensive, I think there is good case for having extra memory to accommodate this pattern.

Below is a PoC that I did to see if it would actually would work, I will try to implement this pattern next time I'm doing a web service/windows service from scratch.

From a new Console project in Visual Studio

1.      Add reference to log4net (Can be downloaded from here)
2.      Edit AssemblyInfo.cs
         Add the following to the end of the file
         [assembly: log4net.Config.XmlConfigurator(ConfigFile = "ConsoleApplication2.exe.config", Watch = false)]

Code:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using log4net;
using log4net.Repository.Hierarchy;
using log4net.Appender;

namespace ConsoleApplication2
{
  class Program
    {
        static void Main(string[] args)
        {
            ILog log = log4net.LogManager.GetLogger("PoC");
 
            Hierarchy hierarchy = LogManager.GetRepository() as Hierarchy;
            MemoryAppender mappender = hierarchy.Root.GetAppender("MemoryAppender") as MemoryAppender;
 
            ImportantDateCalculator(log, mappender, "first");
            System.Threading.Thread.Sleep(1000);
            ImportantDateCalculator(log, mappender, "second");
            Console.ReadKey();
        }
 
        private static void ImportantDateCalculator(ILog log, MemoryAppender mappender, string msg)
        {
            mappender.Clear();
 
            try
            {
                log.InfoFormat("{0}", msg);
                //loads of code here, calculating the meaning of life
                log.InfoFormat("{0}", new Random().Next(42, 42));
                //even more code here calculating the approximate date and time for the heat death of the universe.
                log.InfoFormat("{0}", DateTime.Now.ToString("s"));
 
                throw new Exception("oh noes");
            }
            catch (Exception ex)
            {
                StringBuilder message = new StringBuilder();
                mappender.GetEvents().ToList().ForEach(x => message.AppendLine(x.RenderedMessage));
                message.AppendLine(ex.ToString());
                log.ErrorFormat("{0}",message);                
            }
            
            mappender.Clear();
        }
    }
}

Config File

<?xml version="1.0"?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>   
  </configSections>
  <log4net>
    <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
      <file value="PoC.log"/>
      <threshold value="ERROR"/>
      <appendToFile value="true"/>
      <rollingStyle value="Size"/>
      <maxSizeRollBackups value="10"/>
      <maximumFileSize value="1000KB"/>
      <staticLogFileName value="true"/>
       <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger - %message%newline"/>
      </layout>
    </appender>
    <appender name="MemoryAppender" type="log4net.Appender.MemoryAppender">
    </appender>
    <root>
      <appender-ref ref="RollingFileAppender"/>
      <appender-ref ref="MemoryAppender"/>
    </root>
  </log4net>
<startup><supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.0"/></startup></configuration>