Dynamic log level with log4net

Out of all the features of log4net, the most useful and the least known at the same time is the possibility for the logger to dynamically change the logging level based on future events. Yes, future! Nothing like a little clairvoyance to produce clean and usable log files.

log4net can buffer incoming events and, when an error occurs, write out the sequence of actions that lead to it - and if nothing wrong happens, then the excessive messages are dropped. The class that allows for that is BufferingForwardingAppender. It wraps around another log appender (e.g. file or console or smtp or database or eventlog or whatever else you would like log4net to write to) and uses an evaluator to decide when to flush buffered data. Let's have a look at a sample configuration (app.config file):

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
  </configSections>
  <log4net>
    <!-- see http://logging.apache.org/log4net/release/config-examples.html for more examples -->
    <appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
      <threshold value="WARN" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%-4timestamp [%thread] %-5level %logger %ndc - %message%newline" />
      </layout>
    </appender>
    <!-- you should use a RollingFileAppender instead in most cases -->
    <appender name="FileAppender" type="log4net.Appender.FileAppender">
      <file value="my_application.log" />
      <!-- pattern is required or nothing will be logged -->
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%-4timestamp [%thread] %-5level %logger %ndc - %message%newline" />
      </layout>
    </appender>
    <appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender" >
      <evaluator type="log4net.Core.LevelEvaluator">
        <threshold value="ERROR" />
      </evaluator>
      <bufferSize value="50" />
      <lossy value="true" />
      <appender-ref ref="FileAppender" />
    </appender>
    <!-- root is the main logger -->
    <root>
      <!-- default is INFO, this performs initial filtering -->
      <level value="DEBUG"/>
      <!-- messages are sent to every appender listed here -->
      <appender-ref ref="BufferingForwardingAppender"/>
      <appender-ref ref="ConsoleAppender" />
    </root>
  </log4net>
</configuration>

Now this is a wall of text. What is going on here?

• configSections is a standard .NET configuration section declaration
• then we declare a ConsoleAppender that will print everything of level WARN or above to console - you can configure a ColoredConsoleAppender instead to have prettier output
• following that is a FileAppender, which simply outputs everything to a file
• next one is the magical BufferingForwardingAppender, containing an evaluator that triggers for every message of level ERROR or above, a lossy buffer of size 50 (that means that when more messages are buffered, the first ones are being discarded) and a target appender that will receive messages when they are flushed
• last element is the root logger, which is the default sink for all the messages - it contains referenced to our appenders and will feed messages to them

So far so good. log4net now needs to be instructed to parse this configuration - my preferred way is with an assembly attribute:

[assembly: log4net.Config.XmlConfigurator (Watch = true)]

You can specify a file path in this attribute if you don't want to store your configuration inside app.config. A simple way to create a logger is just

private static readonly log4net.ILog log = log4net.LogManager.GetLogger ( System.Reflection.MethodBase.GetCurrentMethod ().DeclaringType );

and we're good to go. Now all that remains is dumping some log messages into our log.

for (int i = 0; i < 1025; i++)
{
  log.DebugFormat("I'm just being chatty, {0}", i);
  if(i%2 ==0)
    log.InfoFormat("I'm just being informative, {0}", i);
  if(i%20 == 0)
    log.WarnFormat("This is a warning, {0}", i);
  if(i%512==0)
    log.ErrorFormat("Error! Error! {0}", i);
}

When you execute this sample code you will see every warning and error printed to console. Contents of my_application.log, however, will look differently: they will contain only errors and 50 messages that were logged before the error. Now that's much easier to debug, isn't it?

Please also take a look at how I include parameters in the logging calls: using the DebugFormat() form overloads means that the strings are not formatted until this is necessary - so if a log message is suppressed, no new string will be allocated and no ToString() will be called. This might not change your applications performance a lot, but it's a good practice that is worth following. And one last thing to remember: log4net, by default, does not do anything. In order to get any output, you need to explicitly request it - most likely through configuration.