Introduction
Log files are crucial when it comes to troubleshooting an application or finding exact source of a bug. Unfortunately, the more information the application logs, the more its code gets cluttered with logging statements. Readability of source code decreases and, in a team of developers, it may be hard to keep consistency of logged data.If these problems sound familiar to you, Log4PostSharp is for you. It inserts logging statements without touching your source code. It injects calls to log4net methods into the DLL and EXE files automatically right after they are compiled. This guarantees consistency of log files and allows you forgetting about logging at all.
Quick comparison
To illustrate the difference Log4PostSharp makes, this section compares two snippets of code.In the first snippet, the logging has been added in the traditional way:
public void Save()
{
try
{
if (log.IsDebugEnabled)
{
log.Debug("Saving file.");
}
Configuration.Save();
if (log.IsDebugEnabled)
{
log.Debug("File has been saved.");
}
}
catch (Exception ex)
{
if (log.IsErrorEnabled)
{
log.Error("Failed to save file.", ex);
}
throw;
}
}
Note that, out of the total 10 lines of code (not counting lines containing only braces), only 1 line has any business value (the one in bold). Remaining 9 lines are there only to ensure that the progress of the method execution gets logged. And this is only single method, real-life applications consist of thousands of them. That means a lot of lines which introduce no business value and make the code harder to read.
This is where Log4PostSharp comes to rescue. Check the second snippet; it shows method that performs exactly same business action as the first one, but relies on Log4PostSharp to do the logging:
[Log]
public void Save()
{
Configuration.Save();
}
It does not contain even a single logging statement but still produces log output which is very similar to the first version of the method. And as the latter part of this article will show, even the Log attribute that the method is decorated with can be removed.
Demo
If you want to quickly see some sample application that uses Log4PostSharp, you can download the demo project from http://code.google.com/p/postsharp-user-plugins/downloads/list. Remember to download and install the latest version of PostSharp first from http://www.postsharp.org/.How does it work?
To achieve its goal, Log4PostSharp uses PostSharp, an excellent tool that allows injecting code into .NET assemblies. Normally the injection occurs automatically after the project is compiled (PostSharp installer configures .NET build process to make this possible, for more details please visit http://www.postsharp.org/).To see how the injection works, please first see the ReadNumber method in the demo project:
[Log(EntryLevel = LogLevel.Debug, ExitLevel = LogLevel.Debug, ExceptionLevel = LogLevel.Fatal)]
private static int ReadNumber() {
// Display prompt.
Console.Write("Please enter a number: ");
// Read the line from the console.
string line = Console.ReadLine();
// Convert the data into the integer.
return int.Parse(line, CultureInfo.CurrentCulture);
}
It does not contain any logging statements – just three lines of code and the Log attribute. Now compile the demo application and open the resulting executable inside Lutz Roeder’s Reflector. Decompile the ReadNumber method back to C#. This is what you will see:
private static int ReadNumber()
{
int ~returnValue~2;
try
{
if (~log4PostSharp~isDebugEnabled)
{
~log4PostSharp~log.Debug("Entering method: Int32 ReadNumber().");
}
Console.Write("Please enter a number: ");
int CS$1$0000 = int.Parse(Console.ReadLine(), CultureInfo.CurrentCulture);
~returnValue~2 = CS$1$0000;
if (~log4PostSharp~isDebugEnabled)
{
~log4PostSharp~log.Debug("Exiting method: Int32 ReadNumber().");
}
}
catch (Exception ~ex~3)
{
if (~log4PostSharp~isFatalEnabled)
{
~log4PostSharp~log.Fatal("Exception thrown from method: Int32 ReadNumber().", ~ex~3);
}
throw;
}
return ~returnValue~2;
}
Note that the Log attribute has been removed and the new code has been added to the method body. You may also note that the class has new six static fields and the static constructor that initializes them. Injected logging code reads the fields instead of invoking some log4net methods to improve logging performance.
Code that gets injected follows the log4net recommendations and is optimized to achieve the best performance. In the static constructor, the logger is created for every class as:
~log4PostSharp~log = LogManager.GetLogger(typeof(Program));
This means that logger name is same as class name (including namespace).
Log4PostSharp does not interfere with any manually added logging code and requires that developer configures log4net the usual way.
NOTE: Remember that Log4PostSharp caches some information (like indications whether loggers are enabled). If you configure the log4net by placing "
[assembly: XmlConfigurator(Watch = true)]" line somewhere in the AssemblyInfo.cs file and then enable/disable loggers while the application is already running, these changes will have no effect.Customization
The Log attribute exposes few properties that allows you customizing the code that gets injected.EntryLevel, ExitLevel, ExceptionLevel
Values of these properties are of LogLevel type and determine what log4net method is used to write the message to the log. Names of values specified in the LogLevel enumeration correspond to names of respective log4net logging methods. The only exception is the LogLevel.None which indicates that no code is injected at all.EntryText, ExitText, ExceptionText
Determines the text that gets logged. It can contain placeholders which then get replaced with actual values:{signature}– replaced with the signature of the method [weave-time],{@parameter_name}– replaced with the value of the specified parameter [run-time],{paramvalues}– replaced with the comma-separated list of values of all method parameters [run-time],{returnvalue}– replaced with the value that the method is about to return [run-time].
Note that placeholders are marked as being either weave-time or run-time. Values of the weave-time placeholders are determined when the code is being injected. Hence, performance of the generated code is exactly same as if the placeholders were not used (build may take little longer though). On the other hand, values of the run-time ones cannot be determined until the method gets called (and may vary between two different method calls). Therefore, if run-time placeholders are specified, code generated by Log4PostSharp needs to find proper values and then put them into the message. Such code looks like:
if (log.IsDebugEnabled)
{
object[] args = new object[] { left, top, width, height };
log.DebugFormat(CultureInfo.InvariantCulture, "Drawing box: '{0}', '{1}', '{2}', '{3}'.", args);
}
Examples of messages using placeholders:
- ...
EntryText = "Entering method: {signature}."... - ...
EntryText = "Authenticating user: {@userName}."... - ...
EntryText = "Drawing box: {paramvalues}."... - ...
ExitText = "Exiting method: {signature}."... - ...
ExitText = "Authentication result for {@userName} is {returnvalue}."... - ...
ExceptionText = "Exception has been thrown from the method: {signature}."...
Notes and limitations:
- Value of the ExceptionText property can contain only weave-time placeholders.
- Output parameters and return value can be referenced only in the ExitText.
- If a method returns no value (void), the {returnvalue} placeholder still can be used and its value is assumed to be null.
Multicast
Adding the attribute to every method separately would be not only tedious but would also defeat one of the biggest benefits of the library: automatization. Fortunately PostSharp features custom attribute multicasting, which allows applying any attribute to multiple methods at once. You can use the feature by dropping the following line into the AssemblyInfo.cs file:[assembly: Log(AttributeTargetTypes = "*", EntryLevel = LogLevel.Debug, ExitLevel = LogLevel.Debug, ExceptionLevel = LogLevel.Error, AttributePriority = 1)]
The line adds the attribute to every single method in the assembly. This also includes property setters and getters and event addition and removal handlers. To exclude them, add the following lines:
[assembly: Log(AttributeTargetTypes = "*", AttributeTargetMembers = "get_*", AttributeExclude = true, AttributePriority = 2)]
[assembly: Log(AttributeTargetTypes = "*", AttributeTargetMembers = "add_*", AttributeExclude = true, AttributePriority = 2)]
[assembly: Log(AttributeTargetTypes = "*", AttributeTargetMembers = "remove_*", AttributeExclude = true, AttributePriority = 2)]
The lines prevent the attribute from being added to property getters and event addition and removal handlers respectively. Note the AttributePriority property, which is the only way that you can order your attibutes (order in which they appear in the file is irrelevant). Exclusion must always occur after inclusion to make it work. For information on more multicast features see PostSharp documentation.
Multicast attributes can be customized just like the ordinary ones.
How to use it in own projects
If you have a project where you want to use the automated logging, you have to follow few simple steps.Get libraries
Download PostSharp from http://www.postsharp.org/ and install it.Download Log4PostSharp from http://code.google.com/p/postsharp-user-plugins/downloads/list and copy Log4PostSharp.Weaver.dll and Log4PostSharp.psplugin files into the Plugins directory under your PostSharp installation folder. Copy the Log4PostSharp.dll into the directory where you store other libraries for your project.
