Log4Net
18/04/13 22:15
Setting up and using Log4Net
On a recent project, I had the opportunity to use log4net to log messages for an application. There is plenty of information on the use of log4net on the internet since log4net is a very popular logging tool. I thought I would document what I learned about how to setup and use log4net. Hopefully you will find it useful.
To demonstrate what I have learned I will create a console application and implement log4net taking a step by step approach. I have decide to be explicit with each step to create the project even though many of these steps are generic project setup tasks. This way you know exactly how I went about creating the solution.
Each item in this config file is important so let's make sure we understand what we are adding.
We don't want to have to stop and restart the application anytime changes are made to the config file. We want the console application to watch for changes to the log4net.config file and reload the file when needed. To do this, alI we need to add is the following to the AssemblyInfo.cs file of our console project.
[sourcecode language="xml"]
// Set the project to watch the log4net.config file and reload of the config changes when needed.
[assembly: log4net.Config.XmlConfigurator(ConfigFile = "log4net.config", Watch = true)]
[/sourcecode]
Next let's add some simple log statement to our console application and see them show up in the console. To do this, go into the Program.cs file. Add an instance variable for the logger that will be used by this class. For now, we will call the logger "Module1".
In the Program.Main() method, add the following code to create a log entry.
If you run the application, you will see the console window come up quickly and then go away because the application finished running. We want the application to stop before exiting so we can read everything written to the console. To do this, add the following code to the end of the Program.Main() method. This code causes the app to wait until any key is pressed.
Now run the application and you should see the log entry.
Tip: You will notice that for each logging statement we are first checking to see if logging for that level is enabled. If it is, then we perform the logging. The log method itself can figure out if it's supposed to log or not so we don't have to worry about that, but we don't want to pay for any expensive string concatenation in the log method only to have the logger determine that it doesn't need to log the requested level. This is one area where folks see performance issues and want to blame it on the logging framework when it's really the string manipulating that is happening. To avoid this, make it a habit to check the log level to see if it's enable before logging.
Now that we have everything set up and working, we can start to do more interesting things.
Every time you want to log something you need to create a logger. Each logger is named and can be found by its name. The standard convention is to name the logger after the class name. Like this:
This allows you to use your namespace hierarchy as your logging hierarchy.
For the purposes of this example I will use named loggers and use them across classes. This will simulate using a logger per module in an application. I already have one logger called "Module1" Let's create four new classes (Class1, Class2, Class3, Class4). Two of the classes will use our existing logger "Module1", and the other two classes will use a new logger called "Module2".
In Class1 and Class2 use logger "Module1"
In Class3, and Class4 add logger "Module2"
Add the following method to each class to perform logging at each logging level.
In Program.Main() add the following lines after the logging call added earlier. This will call CreateLogEntriesForEachLoggingLevel() method for each class.
Run the application and review all the log entries. You will see log entries for each log level from each of the four classes.
There are 6 levels for logging messages. In the config file you assign loggers a level. Levels have an order of precedence. Therefore, when setting a logger to a level, it will log that level and everything below it. The order of precedence is:
You can find this documented at : http://logging.apache.org/log4net/release/manual/introduction.html
Now that we have multiple loggers, let's have "Module1" log all log messages from DEBUG down, but "Module2" is working great, so let's have it log from WARN down. We don't need to change any code to do this, we just need to modify the log4net configuration to specify the logger and what level it should log. Add the following to the log4net.config file after the </root> tag.
If the config file doesn't explicitly specify a level for a logger in the config and the logger is not lower in the logger hierarchy log4net will log with the level set in the root tag. Remember, that the loggers are hierarchical. So if I added a logger called "Module1.SubModuleA", it will log with the setting specified for "Module1". Change the logger in Class1 to use the name "Module1.SubmoduleA" and then rerun the app. Log entries from Class1 should still log from WARN down.
Log4Net will not throw any exceptions that will cause you application problems. This is a great feature because you can use log4net without worrying that your app will starting behaving strangely if logging can't be performed. The problem is, if your logging isn't working and you are trying to figure out where the problem is, you don't have much to go on. That is unless you turn on internal log4net debugging. This is simple to do. Just add the debug="true" attribute to the <log4net> tag. Then rerun the application and notice all of the log4net info logged to the console. i.e.
This blog will get you started with log4net. Log4Net can do a lot once you understand how it works and how to control log4net from the config file. You can download the project I created below. Use the project as a test project for log4net so you can try out different adapters and configurations. Hope you find this helpful.
[wpdm_file id=1 title="true" desc="true" ]
To demonstrate what I have learned I will create a console application and implement log4net taking a step by step approach. I have decide to be explicit with each step to create the project even though many of these steps are generic project setup tasks. This way you know exactly how I went about creating the solution.
Creating the Project
- First we want to create a console project and solution. Lets name our solution Log4Net_Example_Solution and the project, lets name it Log4Net_Console.
- When creating the project make sure to create a "Console Application" project.
Setup Log4Net
- Now that we have a project we need to get log4net setup in the project. Download the latest log4net dlls from http://logging.apache.org/log4net/download_log4net.cgi.
- Once you unzip the downloaded file you will see in the bin directory many different log4net versions. You need to pick the right log4net.dll. If you pick the wrong one, you will experience problems. We are using the standard .Net libraries so we need to pick a log4net.dll built for the standard libraries. To know which one to pick, you can look at the project you just created and determine what .Net library you are using. In this project, we are using ".NET framework 4 Client Profile". So we need to pick the log4net.dll from the "log4net-1-1.2.11\bin\net-cp\4.0\release directory". net-cp stands for .NET Client Profile. I have seen cases where the project was using the ".Net 4.0 Framework" and then trying to use the log4net.dll for the client profile and they had all sorts of trouble until they figured out the mismatch. Not a big deal, but something to watch for when setting things up.
- Create a directory in the solution folder called lib and place the log4net.dll into the new directory.
- Now add a reference in the Log4Net_Console project to the log4net dll.
Add Log4Net Configuration
- Log4Net uses configuration to drive all of the logging. This is nice since you can change the configuration and get different logging results without having to recompile your application. We could put all of the log4net configuration into the app.config file but most folks, including myself, find that its best to keep the log4net configuration in a file of its own, so that is what we will do in the Log4Net_Console project.
- In order to do this we need another configuration file. Add a xml file to the project and name it log4net.config.
- This log4net.config file needs to be copied into the output dir so the app will have access to it. To get this file into the output directory we need to leverage the post build event of the project. In the project properties, "Build Event" tab enter "copy $(ProjectDir)\log4net.config $(TargetDir)\." into the "Post-build command line:".
- Now we need to add our log4net configuration into our new config file. Initially we just want to log to the console so we will be using the color console appender. You can get the needed configuration right from Apache's Log4Net site or you can use what I have here:
log4net.config
A few items in the log4net.config file explained
Each item in this config file is important so let's make sure we understand what we are adding.
- The <configSections> holds a <section> that allows us to specify the tag that we will be using for all the log4net configuration. In this case, we add the name "log4net". You will notice that the next xml tag is the <log4net> tag that contains our config.
- Inside the <log4net> tags we have two sections an <appender> tag and a <root> tag. We can configure multiple appenders in the file, but in this case we just want to use the ColoredConsoleAppender so that is all that is configured. Go to http://logging.apache.org/log4net/release/config-examples.html to see examples of different appenders you can use.
- The <root> section refers to the root or main logger. Loggers are hierarchical within Log4Net. In your application as you add loggers they are all under the "root" logger. In the config file we are setting up the root logger. Right now lets log everything. To do this, set the log level to "ALL". Specify what appender the root logger and all loggers below the root logger in the hierarchical should use. Since we have configured only one appender this choice is easy. Set the root logger to use the "ColoredConsoleAppender"
Make the application sense when the config file changes
We don't want to have to stop and restart the application anytime changes are made to the config file. We want the console application to watch for changes to the log4net.config file and reload the file when needed. To do this, alI we need to add is the following to the AssemblyInfo.cs file of our console project.
[sourcecode language="xml"]
// Set the project to watch the log4net.config file and reload of the config changes when needed.
[assembly: log4net.Config.XmlConfigurator(ConfigFile = "log4net.config", Watch = true)]
[/sourcecode]
Logging
Next let's add some simple log statement to our console application and see them show up in the console. To do this, go into the Program.cs file. Add an instance variable for the logger that will be used by this class. For now, we will call the logger "Module1".
[sourcecode language="csharp"]// Create the logger. I choose to use set the name of the logger to "Logger1"private static readonly ILog Log = LogManager.GetLogger("Module1");[/sourcecode]In the Program.Main() method, add the following code to create a log entry.
[sourcecode language="csharp"]Console.WriteLine("Welcome to the log4net console example.");Console.WriteLine("This example demonstrates the use of the color console appender. \r\n");// Create log entries for each of the different levelsif (Log.IsInfoEnabled) Log.Info("This is my first log entry");[/sourcecode]If you run the application, you will see the console window come up quickly and then go away because the application finished running. We want the application to stop before exiting so we can read everything written to the console. To do this, add the following code to the end of the Program.Main() method. This code causes the app to wait until any key is pressed.
[sourcecode language="csharp"]// Pause the applicationConsole.WriteLine("Hit any key to continue and end the application");Console.ReadKey();[/sourcecode]Now run the application and you should see the log entry.
Tip: You will notice that for each logging statement we are first checking to see if logging for that level is enabled. If it is, then we perform the logging. The log method itself can figure out if it's supposed to log or not so we don't have to worry about that, but we don't want to pay for any expensive string concatenation in the log method only to have the logger determine that it doesn't need to log the requested level. This is one area where folks see performance issues and want to blame it on the logging framework when it's really the string manipulating that is happening. To avoid this, make it a habit to check the log level to see if it's enable before logging.
Logging by Module
Now that we have everything set up and working, we can start to do more interesting things.
Every time you want to log something you need to create a logger. Each logger is named and can be found by its name. The standard convention is to name the logger after the class name. Like this:
[sourcecode language="csharp"]private static readonly ILog log = LogManager.GetLogger(typeof());[/sourcecode]This allows you to use your namespace hierarchy as your logging hierarchy.
For the purposes of this example I will use named loggers and use them across classes. This will simulate using a logger per module in an application. I already have one logger called "Module1" Let's create four new classes (Class1, Class2, Class3, Class4). Two of the classes will use our existing logger "Module1", and the other two classes will use a new logger called "Module2".
In Class1 and Class2 use logger "Module1"
[sourcecode language="csharp"]private static readonly ILog log = LogManager.GetLogger("Module1");[/sourcecode]In Class3, and Class4 add logger "Module2"
[sourcecode language="csharp"]private static readonly ILog log = LogManager.GetLogger("Module2");[/sourcecode]Add the following method to each class to perform logging at each logging level.
[sourcecode language="csharp"]public void CreateLogEntriesForEachLoggingLevel(){ // Create log entries for each of the different levels Console.WriteLine("\r\n******* Log Entries from class: {0} *******", this.GetType()); if (log.IsDebugEnabled) log.DebugFormat("Debug log entry from class: {0} using logger: {1}", this.GetType(), log.Logger.Name); if (log.IsInfoEnabled) log.InfoFormat("Info log entry from class: {0} using logger: {1}", this.GetType(), log.Logger.Name); if (log.IsWarnEnabled) log.WarnFormat("Warn log entry from class: {0} using logger: {1}", this.GetType(), log.Logger.Name); if (log.IsErrorEnabled) log.ErrorFormat("Error log entry from class: {0} using logger: {1}", this.GetType(), log.Logger.Name); if (log.IsFatalEnabled) log.FatalFormat("Fatal log entry from class: {0} using logger: {1}", this.GetType(), log.Logger.Name);}[/sourcecode]In Program.Main() add the following lines after the logging call added earlier. This will call CreateLogEntriesForEachLoggingLevel() method for each class.
[sourcecode language="csharp"]new Class1().CreateLogEntriesForEachLoggingLevel();new Class2().CreateLogEntriesForEachLoggingLevel();new Class3().CreateLogEntriesForEachLoggingLevel();new Class4().CreateLogEntriesForEachLoggingLevel();[/sourcecode]Run the application and review all the log entries. You will see log entries for each log level from each of the four classes.
Create multiple Loggers each logging at different levels
There are 6 levels for logging messages. In the config file you assign loggers a level. Levels have an order of precedence. Therefore, when setting a logger to a level, it will log that level and everything below it. The order of precedence is:
- ALL
- DEBUG
- INFO
- WARN
- ERROR
- FATAL
- OFF
You can find this documented at : http://logging.apache.org/log4net/release/manual/introduction.html
Now that we have multiple loggers, let's have "Module1" log all log messages from DEBUG down, but "Module2" is working great, so let's have it log from WARN down. We don't need to change any code to do this, we just need to modify the log4net configuration to specify the logger and what level it should log. Add the following to the log4net.config file after the </root> tag.
[sourcecode language="xml"] [/sourcecode]If the config file doesn't explicitly specify a level for a logger in the config and the logger is not lower in the logger hierarchy log4net will log with the level set in the root tag. Remember, that the loggers are hierarchical. So if I added a logger called "Module1.SubModuleA", it will log with the setting specified for "Module1". Change the logger in Class1 to use the name "Module1.SubmoduleA" and then rerun the app. Log entries from Class1 should still log from WARN down.
Turn on log4net debugging
Log4Net will not throw any exceptions that will cause you application problems. This is a great feature because you can use log4net without worrying that your app will starting behaving strangely if logging can't be performed. The problem is, if your logging isn't working and you are trying to figure out where the problem is, you don't have much to go on. That is unless you turn on internal log4net debugging. This is simple to do. Just add the debug="true" attribute to the <log4net> tag. Then rerun the application and notice all of the log4net info logged to the console. i.e.
[sourcecode language="xml"] [/sourcecode] This blog will get you started with log4net. Log4Net can do a lot once you understand how it works and how to control log4net from the config file. You can download the project I created below. Use the project as a test project for log4net so you can try out different adapters and configurations. Hope you find this helpful.
[wpdm_file id=1 title="true" desc="true" ]