Producing readable log4net output

As a follow up to log4net configuration made easy, a common question people ask is what tool to use for reading log4net output.

Unless you're using an AdoNetAppender, there aren't many popular choices for combing through log4net file output.  This really should be as simple as setting fixed width columns or column delimiters into our FileAppender's layout pattern, but unfortunately it isn't that simple: log4net's base appender (AppenderSkeleton) outputs Exceptions over multiple lines making it unsuitable for delimited output.

Here are a few options for producing friendly log4net output that can be easily imported or understood by common tools, such as Excel, LogParser, etc.

Format Exceptions using an IObjectRenderer

log4net is just so darn extensible!  Object renderers are one of those great hidden gems in log4net that allow you to log an object and leave the formatting to log4net configuration.  Any object reference pushed through log4net (including derived classes) will use the supplied object render to customize the output. 

public class ExceptionRenderer : IObjectRenderer
{
        public void RenderObject(RendererMap rendererMap, object obj, TextWriter writer)
        {
            Exception ex = obj as Exception;
            if (ex != null)
            {
                // format exception to taste
                writer.Write(ex.StackTrace);
            }
        }
}

The object renderer appears in your config thusly:

<log4net>
    <!-- appenders -->
    <appender ... />
    <root ... />
    <renderer 
	renderingClass="MyNamespace.ExceptionRenderer,MyAssembly"
	renderedClass= "System.Exception" />
</log4net>

This option can be combined with the other approaches defined below, or on it's own.

try
{
    // perform work
}
catch(Exception ex)
{
    // format using IObjectRenderer
    log.Warn(ex);
}

By logging just the Exception object, the IObjectRenderer will do its formatting. Coincidentally, because the exception is the message it isn't subject to the same delimited friendly problems, though this may not be a suitable solution for you if it means having to rewrite all of your exception blocks.

Redirect Exceptions using a Custom Appender

As previously mentioned, the culprit behind our messy exceptions is the AppenderSkeleton.  Technically, it's how the RollingFileAppender leverages the AppenderSkeleton RenderLoggingEvent method: it appends content to the log based on our LayoutPattern, and then dumps the Exception stack trace as its own line.  We can correct this behaviour by creating a new appender that handles our exception details before it gets rendered into the logger as an exception.

public class CustomRollingFileAppender : RollingFileAppender
{
    public override Append(LoggingEvent loggingEvent)
    {
        string exceptionString = loggingEvent.GetExceptionString();
            
        if (String.IsNullOrEmpty(exceptionString))
        {
            // business as usual
            base.Append(loggingEvent);
        }
        else
        {
            // move our formatted exception details into the message
            LoggingEventData data = loggingEvent.GetLoggingEventData(FixFlags.All);
            data.ExceptionString = null;
            data.Message = String.Format("{0}:{1}", data.Message, exceptionString);

            LoggingEvent newLoggingEvent = new LoggingEvent(data);

            base.Append(newLoggingEvent);
        }
    }
}

The key advantage to this approach is that you won't have to change your existing logging code.

Move Exception details to a Custom Property

Though the previous approach solves our problem, we're coupling our message to our exception.  There may be some cases where you would want to separate exception details, such as importing into a database where the message is limited and the stack trace is a blob.  To accommodate, we can write our exceptionString to a custom property, which can be further customized using our layout configuration.

This code example shows the exception being logged to a custom property:

   LoggingEventData data = loggingEvent.GetLoggingEventData(FixFlags.All);
   data.ExceptionString = null;
   data.Properties["exception"] = exceptionString;

And our configuration:

<appender name="RollingLogFileAppender" type="log4net.Appender.CustomAppender">
  <file value="..\logs\log.txt" />
  <layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%date %-5level [%t] - %message %property{exception} %newline" />
  </layout>
</appender>

Putting it all together

The final piece is defining our layout of file so that it can be consumed by Excel or Log Parser. In the example below, I've customized my Header and Conversion pattern to use a pipe-delimited format, perfect for importing into Excel or a database table.

<log4net>
    <appender type="Example.CustomAppender,Example" name="CustomAppender">
        <!-- derived from Rolling File Appender -->
        <file value="..\logs\log.txt" />
        <appendtofile value="false" />
              <layout type="log4net.Layout.PatternLayout">
                <header value="Date|Level|Thread|Logger|Message|Exception&#13;&#10;" />
                <conversionpattern value="%date|%-5level|%t|%logger|%message|%property{exception}%newline" />
              </layout>
    </appender>
    <renderer renderedclass="System.Exception" renderingclass="Example.ExceptionRenderer,Example" />
    </appender>
        <root>
        <level value="DEBUG" />
        <appender-ref ref="CustomAppender" />
    </root>
</log4net>

Here's a Log Parser query that uses pipe-delimited format (we use a Tab delimited format with a pipe as the delimiter):

logparser.exe -i:TSV -iSeparator:"|" "select Level, count(*) as Count from log.txt group by Level"

log4net Configuration made simple through Attributes

I'm sure this is well documented, but for my own reference and your convenience, here's one from my list of favorite log4net tips and tricks: how to instrument your code so that log4net automatically picks up your configuration.

On average, I've been so happy with how well log4net has fit my application logging needs that most of my projects end up using it: console apps, web applications, class libraries. Needless to say I use it a lot, and I get tired of writing the same configuration code over and over:

private static void Main()
{
    string basePath = AppDomain.CurrentDomain.BaseDirectory;
    string filePath = Path.Combine(basePath, "FileName.log4net");
    XmlConfigurator.ConfigureAndWatch(new FileInfo(filePath));
}

log4net documentation refers to a Configuration Attribute (XmlConfiguratorAttribute), but it can be frustrating to use if you're not sure how to set it up. The trick is how you name your configuration file and where you put it. I'll walk through how I set it up...

log4net using XmlConfiguratorAttribute Walkthrough

1. Add an Assembly Configuration Attribute: log4net will look for this configuration attribute the first time you make a call to a logger. I typically give my configuration file a "log4net" extension. Place the following configuration attribute in the AssemblyInfo.cs file in the assembly that contains the main entry point for the application.
   
   [assembly: log4net.Config.XmlConfigurator(ConfigFileExtension = "log4net",Watch = true)]
   
   
2. Create your configuration file: As mentioned previously, the name of the configuration file is important as is where you put it. In general, the name of the configuration file should follow the convention: full-assembly-name.extension.log4net. The file needs to be at the base folder of the application, so for WinForms and Console applications it resides in the same folder as the main executable, for ASP.NET applications it's the root of the web-site along side the web.config file.
   
   

   Project Type	Project Output	log4net file name	Location
   WinForm App	Program.exe	Program.exe.log4net	with exe
   Console App	Console.exe	Console.exe.log4net	with exe
   Class Library	Library.dll	N/A
   ASP.NET	/bin/Web.dll	/Web.dll.log4net	Web root (/)

   
   
3. Define your Configuration Settings: Copy and paste the following sample into a new file. I'm using the Rolling Appender as this creates a new log file every time the app is restarted.

   
   <?xml version="1.0" encoding="utf-8" ?>
   <configuration>
   
       <configSections>
           <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
       </configSections>
   
       <log4net>
           <!-- Define output appenders -->
           <appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
               <file value="log.txt" />
               <appendToFile value="true" />
               <rollingStyle value="Once" /> <!-- new log file on restart -->
               <maxSizeRollBackups value="10"/> <!-- renames rolled files on startup 1-10, no more than 10 -->
               <datePattern value="yyyyMMdd" />
               <layout type="log4net.Layout.PatternLayout">
                   <param name="Header" value="[START LOG]&#13;&#10;" />
                   <param name="Footer" value="[END LOG]&#13;&#10;" />
                   <conversionPattern value="%d [%t] %-5p %c [%x] - %m%n" />
               </layout>
           </appender>
   
           <!-- Setup the root category, add the appenders and set the default level -->
           <root>
               <level value="DEBUG" />
               <appender-ref ref="RollingLogFileAppender" />
           </root>
   
       </log4net>
   </configuration>
   

4. Make a logging call as early as possible: In order for the configuration attribute to be invoked, you need to make a logging call in the assembly that contains that attribute. Note I declare the logger as static readonly as a JIT optimization.

   
   namespace example
   {
       public class Global : System.Web.HttpApplication
       {
           private static readonly ILog log = LogManager.GetLogger(typeof(Global));
       
           protected void Application_Start(object sender, EventArgs e)
           {
               log.Info("Web Application Start.");
           }
       }
   }

Cheers.

Redirect Standard Output of a Service to log4net

I recently wrote a simple windows service that hosted batch files and other applications within a service process. I found some great stuff located here, which really helped me along.

Like many other developers, I quickly discovered that debugging and diagnosing issues wasn't particularily easy. On my machine, it was fairly simple to set a break point and manually attach to the service, but diagnosing issues on other machines lacked detail in the Event Log. What I needed was a way to capture the output of my hosted application.

As I was already using log4net to trace through application flow, I used the following approach to redirect the output of my hosted application into my logger.

using System.Diagnostics;
using log4net;

public class MyService : ServiceBase
{
    private static readonly ILog log = LogManager.GetLogger(typeof(MyService));

    private Process process;

    public override void OnStart(string[] args)
    {
        process = new Process();
        
        ProcessStartInfo info = new ProcessStartInfo();

        // configure the command-line app.
        info.FileName = "java.exe"
        info.WorkingDirectory = "c:\program files\Selenium\RemoteControlServer"
        info.Arguments = "-jar selenium-server.jar"

        // configure runtime specifics
        info.UseShellExecute = false; // needed to redirect output
        info.RedirectStandardOutput = true;
        info.RedirectErrorOutput = true;

        process.StartInfo = info;
        
        // setup event handlers
        process.EnableRaisingEvents = true;
        process.ErrorDataReceived += new DataReceivedEventHandler(process_ErrorDataReceived);
        process.OutputDataReceived += new DataReceivedEventHandler(process_OutputDataReceived);
        
        
        process.Start();

        // notify process about asynchronous reads
        process.BeginErrorReadLine();
        process.BeginOutputReadLine();
        
    }

    // fires whenever errors output is produced
    private static void process_ErrorDataReceived(object sender, DataReceivedEventArgs e)
    {
        try
        {
            if (!String.IsNullOrEmpty(e.Data))
            {
                log.Warn(e.Data);
            }
        }
        catch(Exception ex)
        {
            log.Error("Error occurred while trying to log console errors.", ex)
        }
    }
    
    // fires whenever standard output is produced
    private static void process_OutputDataReceived(object sender, DataReceivedEventArgs e)
    {
        try
        {
            if (!String.IsNullOrEmpty(e.Data)
            {
                log.Debug(e.Data);
            }
        }
        catch(Exception ex)
        {
            log.Error("Error occurred while trying to log console output.", ex);
        }
    }
}