Log4Net filtering by logger

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.