Ok, so I know I've said twice now that I was going to relay some real-life log4net experiences, but a few days ago Georg Jansen (author of the very kewl Log4Net Dashboard, which I plan to describe in a future post) demonstrated a feature of log4net I've never used before: lossy logging.  After using the feature for a few days, I'm completely sold on it and decided to write up another tutorial.

What is Lossy Logging?

Logging is a very useful tool, but it's not something you want to leave enabled in production if you don't need it.  Each log message take a few cycles away from your application, and the persistence of messages does consume system resources.  Of course you can configure log4net to disable logging, either by setting the root logger level to OFF or removing all appenders from the root logger.  The problem is that by disabling logging altogether, you won't get any juicy details if something goes awry in your application.

Lossy logging gives you a great compromise: under normal operation your application will not log any messages; however, if your application logs an error, a small batch of messages leading up to the error is placed into the log, giving you the error and a snapshot of system activity just before it happened.  How awesome it that?!

Lossy Logging Example

Open Visual Studio, create a new console project, and reference log4net.  Add the following code to the Program class:

namespace Tutorial8_LossyLog
{
    class Program
    {
        static void Main( string[] args )
        {
            log4net.Config.XmlConfigurator.Configure();
            static log4net.ILog Log = log4net.LogManager.GetLogger(
                System.Reflection.MethodBase.GetCurrentMethod().DeclaringType
            );
               
            for( int i = 0; i < 100; ++i )
            {
                Log.DebugFormat( "this is debug msg #{0}", i );
            }
               
            Log.Error( "error: an error occurred!" );           
            Log.Warn( "warning: you've been warned" );
        }
    }
}

The program outputs a series of 100 numbered debug log messages, followed by a single error message and a warning message.

Add an app.config to the project:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>
  </configSections>

  <log4net>
    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
      <layout type="log4net.Layout.SimpleLayout" />
    </appender>

    <appender name="LossyConsoleAppender" type="log4net.Appender.BufferingForwardingAppender">
      <bufferSize value="20" />
      <lossy value="true"/>
      <evaluator type="log4net.Core.LevelEvaluator">
        <threshold value="ERROR" />
      </evaluator>
      <appender-ref ref="ConsoleAppender" />
    </appender>

    <root>
      <level value="DEBUG" />
      <appender-ref ref="LossyConsoleAppender" />
    </root>
  </log4net>
</configuration>

The logging configuration defines two appenders, one very generic Console appender and a BufferingForwardingAppender.  As the name implies, the latter appender buffers log messages and forwards them in batches to one or more other appenders.  You can probably tell from the configuration XML that I've set this appender up with a 20-message buffer.  The lossy and evaluator parameters work together to define when the log message buffer is forwarded to the "base" appender.  More on that in a moment ....

Build and run; the command console will output the following:

DEBUG - this is debug msg #81
DEBUG - this is debug msg #82
DEBUG - this is debug msg #83
DEBUG - this is debug msg #84
DEBUG - this is debug msg #85
DEBUG - this is debug msg #86
DEBUG - this is debug msg #87
DEBUG - this is debug msg #88
DEBUG - this is debug msg #89
DEBUG - this is debug msg #90
DEBUG - this is debug msg #91
DEBUG - this is debug msg #92
DEBUG - this is debug msg #93
DEBUG - this is debug msg #94
DEBUG - this is debug msg #95
DEBUG - this is debug msg #96
DEBUG - this is debug msg #97
DEBUG - this is debug msg #98
DEBUG - this is debug msg #99
ERROR - error: an error occurred!

The program issues a total of 102 log messages (100 DEBUG, one ERROR, and one WARN), but the console only contains 20 messages (19 DEBUG and 1 ERROR).  So what happened to the other 82 DEBUG and WARN messages?

When the BufferingForwardingAppender's lossy property is enabled, the appender will buffer log messages without forwarding them.  If the buffer fills up, the oldest messages are dropped from the buffer to make room for the new messages.  

The evaluator property determines when the appender forwards the messages from the buffer to its base appenders.  There is only one evaluator defined in log4net - the LevelEvaluator.  The LevelEvaluator triggers the forward when a log message is received that meets or exceeds the configured threshold.  The example above is configured so that an ERROR message triggers the appender to forward its buffer to the ConsoleAppender.

Lossy Appender Types

Here is a list of appenders in the log4net distribution that can operate "lossy:"

log4net.Appender.AdoNetAppender
log4net.Appender.RemotingAppender
log4net.Appender.SmtpAppender
log4net.Appender.SmtpPickupDirAppender
log4net.Appender.BufferingForwardingAppender

Coming Up

Ok, seriously, next time it'll be all about log4net best practices, and I promise to show you how you can't live without it.  Really!