Logging, to me, is a basic requirement of any code I write. There's nothing more useful to track down an odd bug than being able to turn on debug logging in production, potentially filter it down to the area of interest and get some real live data. When that code is causing trouble at a customer location, this capability becomes worth its weight in gold.

And while I am a big Interface abstraction and IoC nut, logging is so fundamental to me that I do use a static logger instance in every class and just have a hard requirement for log4net. I just want this to work and not have people worry about having to inject an ILog into my classes, forcing them to think about a concern of mine. It's far less obtrusive this way, imho.

But it does mean that no matter how small and compact my code is, i suddenly tack on a ~240KB dll requirement, often several times larger than my own code. And there goes my "i don't want them to worry about a concern of mine" out the window.

Depending on log4net only when it's there

That got me thinking about how I can avoid this dependency. I knew that if my code path doesn't hit a code in a referenced DLL, the absense of the DLL does not cause a problem. Of course that means i can't even reference their interfaces.

Instead I had to create a duplicate of the log4net ILog interface and proxy my calls to it. The result is a single file, Logger.cs with the following wire-up:

internal static class Logger {

  private static readonly bool _loggingIsOff = true;

  static Logger() {
    try {
        Assembly.Load("log4net");
        _loggingIsOff = false;
    } catch {}
  }

  public static ILog CreateLog() {
    var frame = new System.Diagnostics.StackFrame(1, false);
    var type = frame.GetMethod().DeclaringType;
    return _loggingIsOff ? (ILog)new NoLog() : new Log4NetLogger(type);
  }
  ...
}

(Full code is here)

Because it's not supposed to create a dependency, it's marked internal. Yes, that means that every assembly has a copy of it, but that's really not significant in the grand scheme of things. In returns for a couple of redundant bytes, I can now do add a logger to every class simply with:

private static readonly Logger.ILog _log = Logger.CreateLog();

And if log4net is present and configured, commence the flow of debug statements. Meanwhile I can ship my code without the log4net DLL.

Since i keep overwriting my App.Config with revision control configs and promptly forgetting how to set up filters, I figured i might was well write a brief article on filters here, so i have a place to look it up next time

My basic tenet with logging is that lots of debug statements is good. Now some may say that it just gets too noisy after a while, so don’t put them in unless you need to debug. The problem is that you usually don’t know when you’ll need to debug, and if the code is deployed on a server or worse with a customer, generating a new release so they can run the debug is a burden you shouldn’t have to shoulder. And commenting out log statements (or even conditional compiles) are a code smell reeking of Console.Writeline debugging

But it does get noisy! And noisy also means slow! However with log4net, noisy and performance degradation are non-arguments, since aside from levels, it has excellent filtering, which not only reduces the noise, but also cuts out 99% of the logging overhead. Worst case debugging example I’ve had was tracking down behavior in the motion control software for Full Motion Racing. The physics calculations in this software ran between 60Hz and 100Hz. When i added debug logging in that physics loop, the rate dropped down to about 20Hz because of I/O overhead, and this was with either RollingFile or Udp appenders. Needless to say, motion became jerky and unusable for a rider. But I got the debug data i needed. Disabling those logging statements with filters rather than removing left no appreciable degradation in the performance of the physics loop.

So, again, lots of debug logging == good. Because when you need that data, you need that data. But you may want to ship your code with a log4net configuration that pre-filters the loggers you know to be noisy, so that a user turning on debug logging doesn’t overwhelm them.

How to filter

The basic deal with log4net filters is that they are applied in order and the first filter that matches short-circuits the matching logger. I.e. if the first filter is a DenyAllFilter, nothing else will even be considered, since it matches all loggers. That means there are generally two approaches to filtering, whitelisting and blacklisting. It also means that if you match a logger and a subsequent filter would remove that logger, the subsequent filter is never reached, since consideration of the filter chain stops at the first match

Whitelisting by logger

<filter type="log4net.Filter.LoggerMatchFilter">
  <loggerToMatch value="Only.Logger.To.Match" />
</filter>
<filter type="log4net.Filter.DenyAllFilter" />

LoggerMatchFilter filters default to acceptOnMatch being true, i.e. if omitted, the filter is a accepts (includes in logging) on match. The above will only emit logging statements for the Only.Logger.To.Match logger, since all others will hit the DenyAllFilter and be excluded.

Blacklisting by logger

<filter type="log4net.Filter.LoggerMatchFilter">
  <loggerToMatch value="Logger.To.Filter.Out" />
  <acceptOnMatch value="false" />
</filter>

This filter will show all logging statements except those for Logger.To.Filter.Out.

LoggerMatchFilter also matches on partial namespaces, which is very useful when you have a noisy namespace, but one logger in that namespace that you do want in your logs such as:

<filter type="log4net.Filter.LoggerMatchFilter">
  <loggerToMatch value="Noisy.Namespace.But.Important" />
</filter>
<filter type="log4net.Filter.LoggerMatchFilter">
  <loggerToMatch value="Noisy.Namespace" />
  <acceptOnMatch value="false" />
</filter>

With these filters, all of Noisy.Namespace.* will be filtered out, except for Noisy.Namespace.But.Important.

Filters are your friend

So, don’t get locked into thinking that your choice for verbosity lies only in log levels and once committed to a level it’s either all the noise or none of it. But to keep things sane, pre-populate your config with filters, because you are the one that knows best which loggers are of general use and which are special case only.

I use log4net for most of my apps. I did similar things in all the languages i’ve worked with. I just like having a way to verbosely spew information into the ether so that i could use for analysing code when something gest wonky without having to step through the code or go uncommenting loads of Console.Writeline() calls.

On unix, i just always have a terminal open for tailing the log files and while i often do the same under Windows, using a Cygwin bash shell, i’ve started putting debug windows into my Windows.Forms apps, just because it’s nice and convenient. To make this work, you simply use the log4net MemoryAppender. For display purposed, I use a TextBox, but do some legwork to limit the size of the text logged and to make sure it stays scrolled at the bottom.

public class FormX : System.Windows.Forms.Form
{
    #region Static Members ####################################################
    private static readonly ILog log = LogManager.GetLogger(typeof(FormX));
    #endregion

    #region Members Variables #################################################
    private bool logWatching = true;
    private log4net.Appender.MemoryAppender logger;
    private Thread logWatcher;
    /// <summary>
    /// The TextBox for our logging messages
    /// </summary>
    private System.Windows.Forms.TextBox mLog;
    /// <summary>
    /// Required designer variable.
    /// </summary>
    private System.ComponentModel.Container components = null;
    #endregion

    #region Constructors #################################################
    public FormX()
    {
        //
        // Required for Windows Form Designer support
        //
        InitializeComponent();

        this.Closing += new CancelEventHandler(FormX_Closing);
        logger = new log4net.Appender.MemoryAppender();

        // Could use a fancier Configurator if you don't want to catch every message
        log4net.Config.BasicConfigurator.Configure(logger);

        // Since there are no events to catch on logging, we dedicate
        // a thread to watching for logging events
        logWatcher = new Thread(new ThreadStart(LogWatcher));
        logWatcher.Start();
    }
    #endregion

    // [...]

    private void FormX_Closing(object sender, CancelEventArgs e)
    {
        // Gotta stop our logging thread
        logWatching = false;
        logWatcher.Join();
    }

    private void LogWatcher()
    {
        // we loop until the Form is closed
        while(logWatching)
        {
            LoggingEvent[] events = logger.Events;
            if( events != null && events.Length > 0 )
            {
                // if there are events, we clear them from the logger,
                // since we're done with them
                logger.Clear();
                foreach( LoggingEvent ev in events )
                {
                    StringBuilder builder;
                    // the line we want to log
                    string line = ev.LoggerName + ": " + ev.RenderedMessage+"\r\n";
                    // don't want to grow this log indefinetly, so limit to 100 lines
                    if( mLog.Lines.Length > 99 )
                    {
                        builder = new StringBuilder(mLog.Text);
                        // strip out a nice chunk from the beginning
                        builder.Remove(0,mLog.Text.IndexOf('\r',3000)+2);
                        builder.Append(line);
                        mLog.Clear();
                        // using AppendText since that makes sure the TextBox stays
                        // scrolled at the bottom
                        mLog.AppendText(builder.ToString());
                    }
                    else
                    {
                        mLog.AppendText(line);
                    }
                }
            }
            // nap for a while, don't need the events on the millisecond.
            Thread.Sleep(500);
        }
    }
}

Just a note of something simple and silly enough that I shouldn’t forget it again: Filepaths in log4net configurations still have to escape the DOS separator backslash. I know it should be obvious, you use \ in a text file, you escape it.

Well, i was too used to the @”c:\foo\bar.txt” syntax from C# that when i took the path out of the code and into the log4net XML config, i left it in the c:\foo\bar.txt format. I wasn’t able to wrap a debugger around the deployed code and couldn’t figure out why my logger wasn’t writing. I figured out how to get to the currently available appenders at runtime and wrote that to the web page trace and seeing that there was no filename for the RollingFile appender, smacked me in the head with the “escape the backslash, stupid”.

The silly part out of the way, this did give me some useful insight into log4net internals. So to get at the configured appenders you can do this:

// Just grabbing the first logger, since we want to use it to grab it's parent,
// the root logger
log4net.Repository.Hierarchy.Logger logger
    = (log4net.Repository.Hierarchy.Logger)log.Logger.Repository.GetCurrentLoggers()[0];
Console.WriteLine("Logger: {0}",logger.Name);
//
foreach( log4net.Appender.IAppender appender in logger.Parent.Appenders )
{
    Console.WriteLine("  Appender: {0}",appender.Name);
    // just checking for RollingFile here, but could just as well check for all other appenders
    if(appender.GetType() == typeof(log4net.Appender.RollingFileAppender))
    {
        log4net.Appender.RollingFileAppender rolling
            = (log4net.Appender.RollingFileAppender)appender;
        Console.WriteLine("    Rolling File: {0}",rolling.File);
    }

Mind you this is just a place to get started from. It does make a number of assumptions you shouldn’t make in production code. It is good enough though to help you debug log4net behavior.