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.

You must Sign In to use this message board.

FAQ    Noise Tolerance Very HighHighMediumLowVery Low   Layout Expand Posts & RepliesThread ViewNo JavascriptNo JS + Preview   Per page 102550

Msgs 1 to 16 of 16 (Total in Forum: 16) (Refresh) FirstPrevNext

Whats about newer version of PostSharp Imad El 1:34 10 Sep '08   Hello. Nice Wrok! But whats about a new version of PostSharp, your assembly depends on version 1.0.10.385, a newer version of PostSharp is installed and somthing go wrong. Exception tells that the type PostSharp.Extensibility.MulticastAttribute in not found (due to the different version number referenced by your assembly). Can you please post the source code or recompile the Log4PostSharp with the PostSharp.Public version 1.0.11.425. Thanks! Sign In·View Thread·PermaLink Re: Whats about newer version of PostSharp Michal Dabrowski 2:16 12 Sep '08   Hi, source code for the Log4PostSharp is available at http://code.google.com/p/postsharp-user-plugins/source/checkout[^]. I will update it to the latest version of PostSharp in few days. Michal Dabrowski http://herrmic-coding.blogspot.com/ Sign In·View Thread·PermaLink Re: Whats about newer version of PostSharp Michal Dabrowski 23:35 13 Sep '08   New version is available. Check here: http://herrmic-coding.blogspot.com/[^]. Michal Dabrowski http://herrmic-coding.blogspot.com/ Sign In·View Thread·PermaLink Re: Whats about newer version of PostSharp Imad El 5:59 15 Sep '08   Thank you! Sign In·View Thread·PermaLink Do you also have an "automatic" mode? BugByter 22:26 7 Sep '08   I have to audit an executable for work for which I don't have the source code available. My job is to find out where the action takes place, more exactly I have to pinpoint a specific function. Of course I can fire up Reflector and/or use Autodiagrammer but the view they provide is rather static. It would be great if I could attach Log4PostSharp to it, run the EXE and just have it log every function call. Is this possible with your solution and if yes, how? Thanks in advance, kind regards, Buggy Sign In·View Thread·PermaLink Re: Do you also have an "automatic" mode? Michal Dabrowski 1:05 9 Sep '08   Answering your question requires better knowledge of PostSharp (the tool that Log4PostSharp is plug-in for) than I have. I would recommend you posting the question at http://www.postsharp.org/forum/[^]. I can only tell that if PostSharp supports such scenario, then does Log4PostSharp. Michal Dabrowski http://herrmic-coding.blogspot.com/ Sign In·View Thread·PermaLink How about a version for TracerX? MarkLTX 9:25 15 Aug '08   This is great work and you get a 5 from me. I have a logger called TracerX, and I know of at least three products that have switched from Log4Net to TracerX. It has a feature for logging the entry and exit of method calls, but you must put a 'using' statement around the body of each method so Dispose() will log the method exit no matter what (I suppose it could also be done with a try...finally). The TracerX viewer increases the indentation according to the stack depth and allows you to collapse and expand the output of each method. Here's an article about TracerX[^] Anyway, it's a slight pain to wrap every method body with 'using {...}', so it would be great to have something like Log4PostSharp to use with TracerX. I considered modifying your code to do it, but when I looked at your code it was more complicated than I expected (hey, the story of my life). Also, I don't know how to deal with the license/copyright issue, so I figured I'd start by just asking you to make a modified version of Log4PostSharp that works with TracerX. I would of course help you in any way I can, including adding new interfaces to TracerX if needed. Please let me know what you think. Sign In·View Thread·PermaLink Re: How about a version for TracerX? Gael Fraiteur 9:45 15 Aug '08   I would suggest making abstracting the logging provider and making it pluggable. If we can map semantics of Log4Net to TracerX, it could be possible to weave instructions for both providers as two classes implementing the same interface. One could choose which provider the weaver should use. And this could of course be extended to other logging frameworks using this mechanism! -gael Gael Fraiteur Lead developer of PostSharp, a platform for AOP on .NET. Sign In·View Thread·PermaLink Re: How about a version for TracerX? MarkLTX 10:37 15 Aug '08   I don't think there is a direct mapping of Log4Net semantics to TracerX. As I understand it, the Log4Net methods you call to log the entrance and exit of a method are the same methods you would use to log, say, a variable value. That is, Logger.Info(), Logger.Debug(), etc. With TracerX, a different set of methods with names like Logger.InfoCall() and Logger.DebugCall() are used to log method calls. These methods log the method entrance and return an object whose IDispose.Dispose() method logs the exit. Also, the output is not the same as the output from "regular" log statements. It includes binary information that allows the viewer application to accurately track the stack depth, current method name, thread, etc. You can't simply log the strings "entering method x" and "exiting method x" and expect the viewer to work properly. Furthermore, if you log the entrance of a method, you MUST log the exit or the viewer will get confused. That's why TracerX requires the use of a 'using' statement (to guarantee Dispose() gets called on the object returned by Logger.InfoCall()). Your [Log] attribute allows the user to log one or the other (entrance or exit), which TracerX can't allow. Having said all that, maybe you can still devise a way to do what you suggest. I certainly understand not wanting to duplicate a bunch of code to support another logger, but it would seem the easiest way would be to just make a modified version of Log4PostSharp. Anyway that's how I would do it, because I only care about supporting TracerX, not everything else. If you're willing to do the work, however, I don't care how you do it as long as I can have a [Log] attribute for TracerX! A generalized, abstracted thing that supports other loggers would be fine. If you're not willing to do the work, just let me know and I will think further about doing it myself. I just think it would be a very easy thing for you to do. If you can't or won't, that's perfectly understandable. Either way, thanks for hearing me out! Sign In·View Thread·PermaLink Re: How about a version for TracerX? Michal Dabrowski 1:15 17 Aug '08   I've checked the TracerX and I must admit that it looks really interesting. It has some features (log browser, awareness of method enter/exit, etc) that I was missing in log4net. I'm seriously considering switching my projects over to it Answering your question - yes, I'm willing to do the TracerX and PostSharp integration. Thanks to Log4PostSharp I have some experience that will allow me completing this task in relatively short time. I was thinking about one, generic interface to loggers to make them pluggable. However, as you point out, semantics for TracerX are very different than for log4net. I had similar issue when I used Castle Logging - their generic logger interface reduced all loggers to the "least common denominator" (which meant for me that I could not use some log4net specific features). I think that specialized product for PostSharp-TracerX integration will make it possible to leverage all TracerX unique features. Michal Dabrowski http://herrmic-coding.blogspot.com/ Sign In·View Thread·PermaLink Re: How about a version for TracerX? MarkLTX 5:42 18 Aug '08   Thanks for the kind words about TracerX. I tried to make it easy to switch from Log4Net because I knew I would be switching my own projects. Using "find and replace in files" to change "using log4net" to "using TracerX" goes a long way. I vaguely remember tweaking the Logger declarations with find and replace as well. Initialization/configuration code will have to be rewritten if you decide to proceed, but that's usually pretty localized. Sign In·View Thread·PermaLink try..catch dvhemert 23:00 11 Aug '08   As I have allways understood, adding a try..catch should be done only when needed because it uses possibly unneeded resources. When using this technique which will add a try around every code block, will this influence performance (vs adding my own logic)? modified on Tuesday, August 12, 2008 9:23 AM Sign In·View Thread·PermaLink Re: try..catch Michal Dabrowski 20:19 12 Aug '08   From what I know, just putting try...catch has no performance cost - it's throwing an exception that may be (eventually) problem (if overused). Michal Dabrowski http://herrmic-coding.blogspot.com/ Sign In·View Thread·PermaLink Re: try..catch MarkLTX 8:55 15 Aug '08   That is my understanding as well. The performance impact is trivial unless an exception is actually thrown. Here's a CP article about an application to test the impact of exception handlers: http://www.codeproject.com/KB/exception/ExceptionPerformance.aspx[^] Sign In·View Thread·PermaLink thanks LiborB 3:01 7 Aug '08   only want to say thanks for all your hard work , finally I don't have to write the logging mechanism from scratch Sign In·View Thread·PermaLink Re: thanks Michal Dabrowski 20:20 12 Aug '08   Thank you. I'm glad that someone finds this tool useful Michal Dabrowski http://herrmic-coding.blogspot.com/ Sign In·View Thread·PermaLink 5.00/5 (1 vote)

Last Visit: 10:59 8 Nov '09     Last Update: 10:59 8 Nov '09 1