Log4PostSharp - AOP and logging

• Download source code - 14.9 KB
• Download demo - 111 KB
• Download latest versions

Introduction

Log files are crucial when it comes to troubleshooting an application or finding the 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 to forget 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 the lines containing only braces), only 1 line has any business value (the one in bold). The remaining 9 lines are there only to ensure that the progress of the method execution gets logged. And, this is only a 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 the 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 here. Remember to download and install the latest version of PostSharp first, from here.

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 (the PostSharp installer configures a .NET build process to make this possible; for more details, please visit this website).

To see how the injection works, 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 six new static fields and the static constructor that initializes them. The injected logging code reads the fields instead of invoking some log4net methods to improve logging performance.

The 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 the logger name is the same as the class name (including namespace).

Log4PostSharp does not interfere with any manually added logging code, and requires that the developer configures log4net the usual way.

Note: Remember that Log4PostSharp caches some information (like indications whether loggers are enabled). If you configure log4net by placing the "[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 a few properties that allow you to customize 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 [runtime],
• {paramvalues} – replaced with the comma-separated list of values of all method parameters [runtime],
• {returnvalue} – replaced with the value that the method is about to return [runtime].

Note that placeholders are marked as being either weave-time or runtime. Values of the weave-time placeholders are determined when the code is being injected. Hence, the performance of the generated code is exactly the same as if the placeholders were not used (build may take a little longer though). On the other hand, values of the runtime ones cannot be determined until the method gets called (and may vary between two different method calls). Therefore, if runtime placeholders are specified, the 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:

• The value of the ExceptionText property can contain only weave-time placeholders.
• Output parameters and the 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 not only be 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 attributes (the 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 the 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 automated logging, you have to follow a few simple steps.

Get libraries

Download PostSharp from here and install it.

Download Log4PostSharp from here and copy the 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.

Add references

In the project, add references to the Log4PostSharp.dll and PostSharp.Public.dll (you can find this library on the ".NET" tab of the "Add reference..." dialog). Remember that these DLL files are required only by the compiler and the weaver. You do not need to deploy them with your application or library.

Decorate methods with attribute

Decorate the desired methods with the Log attribute, or just add the attribute to all the methods using the multicast feature. Compile and run the application to see that it works. From this moment, you can start removing old logging code (or just stop adding new logging code).

Other options

If you do not want to install Log4PostSharp into the PostSharp Plugins folder, you will need to provide a .psproj file for your project. For more details, please refer to the PostSharp documentation.

Final words

The Log4PostSharp is published under the BSD license which allows using it freely even in commercial products.