Sunday, February 22, 2015

A .Net Guide to Logging with Log4Net

Overview
Logging is one of those things that I never saw the value of until I had to support code in production. I immediately saw the value of logging, since you cannot just attach a break point and view the state of your application. Logging is really the only option. This post will cover the basics of logging with Log4Net and Common.Logging, and some nifty advanced things you can do with the tools.

Log4net
There are a few important features that log4net providers. It has a variety of appender's that you can write your logs to. It allows for hierarchical logging that allows you to set different log levels in different parts of the application. Lastly, it allows for logging levels to be adjusted on the fly as the application is running.

Common.Logging
Is a wrapper for several different logging frameworks in .net. You don't have to use it, I just haven't use log4net without it, so my examples will be focused on it.<br />

Setup
You will need to do a few things to get logging working. I have created a sample console hello world application here The basic steps are as follows
  1.  Install the Common.Logging.Log4net package
  2. Add the correct configuration to the app.config or web.config of your project
  3. Add a second XML file that contains the configuration for log4net
  4. Add XmlConfigurator.ConfigureAndWatch() to your application's startup routines
  5. Profit
Putting the log4net configuration allows for the logging to be adjusted on the fly. You can put your log files directly in the web or app config if you don't need to adjust them while the application is running.

Logging Levels
Log4Net has 6 different levels of logging

  • All
  • Trace
  • Debug
  • Info
  • Warn
  • Error
  • Fatal
The logging levels build on each other. For example, setting your logging level to Warn, will capture everything in Error and Fatal. The most important thing to know about logging levels is that before you add any logging to your application you must decide on what information should go in which logging level. You want your entire application to have consistent logging levels, and this requires some careful thought and consideration.

Log4net also has the ability to check that a log level is enabled before logging. This is useful when you need to log something that could be a performance issue, such as serializing data. There are two methods you can use.

Lamda

logger.Debug(() => { //Expensive Logging Goes Here });

If Statement

if (logger.IsDebugEnabled)
{
      //Expensive Logging Goes Here
}

Hierarchical Logging
You should be defining your logging with the full namespace of the class that the logger is in. You should also define a logger per class, so you know where the log is coming from. This is important when setting up your logger. If you give all of your loggers in code the same name, you cannot take advantage of Hierarchical logging. For example if I have the following namespace in my application

Application.Service.BusinessLogic

If I define my logger in configuration as "Application" It will log everything in the Application Namespace. If I define my logger in configuration as "BusinessLogic" I will only get logging from the BusinessLogic namespace. Consistent application of logging names will make it easy to target specific information as you need it. I will use a statement like this to define my logger.

 private static readonly ILog _logger = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);

Also if you have defined multiple loggers, such as a logger in both Application and BusinessLogic, you will get the logs in two places if they point to different appenders. You can set a property on the logger called "additivity" that prevents this. See the examples here under the appenders section for more information.

Appenders
There are many appenders you can log to from file to email to telnet. The RollingFileAppender is one of the most common appenders, and allows you to log to rolling files. I also like to setup the DebugAppender so I can see logging message in my development environment as I am debugging. The ConsoleAppender is another useful appender if you plan on writing a console application and want your logs to show up in the console.

Logging Layout
You may want to control how the log file actually looks. You can do so by specifying a layout in the configuration. The layout looks like this:

 <conversionPattern value="%message * %date * %thread * %-5level * %logger * %newline" />

In my example project, this would write the following log to file.

Hello World * 2015-02-21 18:51:51,265 * 8 * INFO  * Log4NetDemo.Program * 

Log4net has some default values that you can use.  See the documentation here on all of the different built in information you can add to your logs.

Custom Properties
If the default properties are not enough, you can also add custom properties to your logs. This allows you to add common information to your logs without having to add that information to every log statement.

// Thread properties
log4net.LogicalThreadContext.Properties["CustomColumn"] = "Custom value";
log.Info("Message");

//Global properties
log4net.GlobalContext.Properties["CustomColumn"] = "Custom value";

You can insert custom properties on both the current thread, and globally. You can reference the properties in you log file by using %properties{CustomColumn} in the conversionPattern section.
 
What should I Log?
When you first start adding logs to your application, you may not know exactly what to log. When writing new code, or fixing bugs in existing code, think about how you would troubleshoot this in a production environment if there wasn't an exception with a stack trace. Depending on the method you may want to capture parameters and objects to ensure the correct data is being passed around. You may want to log points where you make a decision in your application so you can trace the flow of logic. Every time you work on a difficult to troubleshoot problem, think about how additional logging would have made that problem easier to fix. 

Additional Tools
Here are a few tools that I have found useful when working with logs

BareTail A very nifty log viewer. Allows you to highlight logs based on keywords. Monitors logs in real time. This has replaced notepad++ for me as a general log viewer, especially when logging a lot of data.

Log Parser Lizard This is another really useful tool. It allows you to write SQL style statements against a log file. How awesome is that? Scott Hanselman has a good blog post about it here .