A nice, basic log4net setup

In my current project I have need for quite a bit of logging. I’ve never used log4net before so I thought it was about time. Log4net has been around for ages, and is very well documented in the log4net documentation, and explained very nicely in e.g. Jim Christopher’s log4net tutorials. What I plan to show you here is my findings in setting up my logging solution. What I wanted was couple of different log files for different severity levels, and here’s my story how I did it. I’m sure you can do more clever tricks that what I’ve done here, please contact me or share your knowledge in the comments if you have tips or thoughts on improvements.

Summary

I used…

  • FileAppender+MinimalLock to be able to read the log file while the system is running
  • three Appenders one each for minimum LogLevel: debug, info and warning
  • one logger per class – gave me a readable “tag” on each log item, but filtering problems with nhibernate
  • an LoggerMatchFilter for nhibernate with AcceptOnMatch=false to reject messages

 

Getting started

To get any logging at all, you need to create a logger and configure it. The code for doing this and writing something to the log looks like this:

(Yes, it’s not a typo – the namespace is lowercase, I know it’s hard, by try to ignore that…)

Those few lines of course require configuration, the app/web.config is a good place for that so let’s go there now. The config needs three parts; a configSections entry, a log4net appender and a log4net root directive. See for yourself:

Appender

The appender entry represents a consumer of the logging information. Here I use a RollingFileAppender which rotates the log file periodically, as specified by the datePattern. MaximumFileSize is also honored and breaking that limit also rolls the log file over.

The logging in my project is done from a WCF service with HTTP endpoints. I have testing endpoints (e.g. /log/debug) that just shows the latest log file – very handy. To be able to read from the log file while the service is running, the lockingModel has to be set to FileAppender+MinimalLock which tells log4net to lock the log file as little as possible, instead of all the time which is the default. This will create a performance hit for the logging, but that’s ok for my setup. Specifying a staticLogFileName causes log4net to always log to a specific file, and then rename older log files according to date etc. This allows my hand coded log reader to always know where the latest log info is.

Root

The root section is what connects a log consumer (the appender) with a log producer (the ILog in the code). The root section can be replaced by specifying a specific logger (), and that would only process log data from that specific logger. Which logger to process data from brings us to the next topic – filtering.

Filtering (and getting rid of nhibernate output)

As you probably know, logs can either say to little, just about right, or WAY too much – that’s where the power of filtering comes in. LogLevel is the most natural and direct thing to filter on. In my service, I have three different log files all set to different levels; one for everything, one for at least Info and one for at least Warning. This is done by having three different appender entries and three appender rows in the root entry. This is where I started bumping into problems, read on…

One logger per class

I followed the advice from Jim’s log4net recommended practices to create one logger per class – not to use one logger for the entire application. The theory behind this is to have a tag on each log entry allowing you to have a log that “reads like a novel”. I like the idea and it’s very nice to always know what class issued the statement. Here’s an example of log output:

I made this happen by using a logFactory that I inject into each class, instead of a log. (I’m not using an IoC container, was overkill for this project). The web service class looks like this:

whilst one of the classes begins with this:

Using this technique, it would be very easy to temporarily add an appender for just a part of your system – giving you awesome control of the logging output.

nhibernate

NHibernate also uses log4net – and since I don’t have one logger but one per class, I have to use the “root” logger directive. The root logger funnel everything sent to the log4net system. This caused me to get all the nhibernate debug info in my logs. This was not what I wanted.

Inverted filtering

To get the kind of filtering output I wanted I had to use two kinds of filters; the LoggerMatchFilter and the LevelRangeFilter. Filtering in general in log4net works so that if you hit a filter that matches, it breaks the filtering chain and returns. This took me a while to figure out, I thought it just acted as a filter that could be chained, so that I could specify more and more filters to get more and more fine-grained output. But, back to the code:

As you can see, I use the LoggerMatchFilter inverted. So, when it hits an item that matches “NHibernate” it will immediately reject it. If it does not match, it will continue down the chain and check the level. I figured this out by reading Matthew Daugherty’s log4net tutorial, highly recommended.

This Post Has 9 Comments

  1. I would recommend against a filter setup. It is much more efficient to have a logger element for nHibernate and configure it to Warn level.
    With the filter approach all off nHibernate’s logging will be created and then rejected by your filter (bad for performance).
    With a logger config only the statements with warn or above will be generated by nHibernate.

  2. @Konstantin thank you for the tip! I haven’t really grasped the entire log4net system so this kind of input is perfect. But I need a “root” logger to get output from all my loggers right? With “

  3. sorry, the other reply got clipped (I wrote it on my cell phone).
    the last part of the comment:
    I need a root logger right? With a

    I have two appenders in my app.config for a .net C# application. One is for a database log and the other for a rolling file appender. I need to use these two appenders but with a different message parameter to each one. I therefore cannot just use one log.info call but I need to instantiate two ILog objects, each one connected to a different appender from my app.config. Is this possible?

    Thanks for any help you can offer.

  4. The RollingFileAppender code does not write to the file.

    1. Probably a flush thing with a newer version, check the docs.

  5. thanks for sharing your knowledge :)

Leave a Reply

Close Menu