Simplifying Logging In Your Application with PostSharp and AOP

Posted on July 20th, 2012 by Fernando Zamora

Currently we are looking for a way to implement logging into our current project. There have been several occasions when some issue occurs and we need to determine the location. Whenever it’s an exception the location of the exception may be clear, if the stack trace is revealed. Revealing the stack trace is not a good solution for various reasons. The main two reasons are that

1. It is not a friendly message
2. It could pose a security vulnerability

In other cases the issue may be a deadlock. This causes the system to hang for no apparent reason. Because we don’t have any way of tracing where the application hung, this can become a really frustrating issue to track. And in many cases it suffers from the WOMB factor (Works on my box).

To investigate these types of issues, in the past we’ve put logging code into the DLLs and then drop those DLLs into the system environment. We use that logging information to track down the particular issue. We repeat this process several times before we narrow it down completely (i.e. we keep adding additional logging code). Doing logging in this manner is quite obtrusive because we have to sprinkle logging code all over the suspected area. It is also tedious because we cannot turn on a switch in the environment where the bug was observed.

To illustrate this example say we have the following code

public class Doer
{
   void DoSomething()
   {
     int someValue = ComputeSomeValues(....);
     int sometherValue = ComputeSomeOtherValues(someValue);

     WriteSomeOtherValueToTheDatabase(someotherValue);
     SyncChanges();
  }

  int ComputeSomeValues(){....}
  int ComputeSomeOtherValues(int someValue){...}
  void WriteSomeOtherValueToTheDatabase(int someOtherValue){...}
  void SyncChanges();
}

Let’s assume that some issue is happening somewhere in this method. Let’s just say that, for example, the system is hanging up somewhere. We would like to trace where the application is hanging. Let’s assume we’ve tested locally in our boxes and have walked the code and still cannot figure out where the issue is occurring. Let’s also say that it works on our local box but it hangs in the test lab.

What we’ve done in the past is to add logging code to the method(s) and run the application to determine what last statement executed was.

Something like the following:

public class Doer
{
  void DoSomething()
  {
     Logger logger = new Logger("C:\\temp\\log.txt"); //write log to this file

     logger.Log("Calling ComputeSomeValues()");
     int someValue = ComputeSomeValues(....);

     logger.Log("Calling ComputeSomeOtherValues()");
     int sometherValue = ComputeSomeOtherValues(someValue);

     logger.Log("Calling WriteSomeOtherValueToTheDatabase()");
     WriteSomeOtherValueToTheDatabase(someotherValue);
     
     logger.Log("Calling SyncChanges()");
     SyncChanges();

  }

 int ComputeSomeValues(){....}
 int ComputeSomeOtherValues(int someValue){...}
 void WriteSomeOtherValueToTheDatabase(int someOtherValue){...}
 void SyncChanges();
}

The code above will then log each line to the file at the location on C:\Temp\log.txt. We can then inspect the log, which will reveal the last call. As you can already see, this can get quite messy. I’m not even showing you the logging code that is going on inside of those other methods in the class. As you can see we are littering code all over place. This will not only obscure the readability of the code, it also means that once we find the problem we have to remove the logging code, only to do it all over again when have another similar issue.

What if on the other hand we could log at will with a configuration setting and not scatter logging code all over the place. Well as it turns out, we can.

We can do this with a concept called Aspect Oriented Programming (AOP). At a high level AOP is simple. AOP provides the capability to inject code into our source code at run time. In our example AOP can handle all the logging before and after each method automagically. From a technical perspective AOP is not an easy thing to implement. There is a lot work that you have to do and frankly most of it has gone over my head each time I’ve looked into it. Feel free to look into implementing it if your dare. Thankfully now there are AOP frameworks that do all the heavy lifting for you. One such framework is PostSharp.

With PostSharp we can accomplish the same logging capabilities as the above example by simply adding an attribute decoration to our class, as seen below.

[Logger()]
public class Doer
{
  void DoSomething()
  {
     int someValue = ComputeSomeValues(....);
     int sometherValue = ComputeSomeOtherValues(someValue);

     WriteSomeOtherValueToTheDatabase(someotherValue);
     SyncChanges();
 }

 int ComputeSomeValues(){....}
 int ComputeSomeOtherValues(int someValue){...}
 void WriteSomeOtherValueToTheDatabase(int someOtherValue){...}
 void SyncChanges();

}

Nice right? Where does this mysterious Logger Attribute come from? Here is the sample implementation of the LoggerAttribute class. This is code that we can implement with the help of PostSharp.

    using PostSharp.Aspects;

    [Serializable]
    public class LoggerAttribute : OnMethodBoundaryAspect
    {
        Logger _logger = new Logger("somefileName");

        public override void OnEntry(MethodExecutionArgs args)
        {
            base.OnEntry(args);
            _logger.Log("Entered " args.Method.DeclaringType.Name, + "." + args.Method.Name);
        }

        public override void OnExit(MethodExecutionArgs args)
        {
            base.OnExit(args);

            CreateLogger();
            _logger.Log("Entered " args.Method.DeclaringType.Name, + "." + args.Method.Name);
        }
   }

The key thing about this is that it inherits from the OnMethodBoundaryAspect attribute which is part of PostSharp. We then override the OnEnter and OnExit methods of the OnMethodBoundaryAspect. After that, PostSharp handles the injection for us. With all of this in place we can simplly add the Logger attribute to any method or class that we want to implement logging on. We can re-use this functionality across any part of our application. As you can imagine you can do other things like implement security, or even role based security be leveraging AOP. There are many things that you can implement unobtrusively using PostSharp as an AOP tool, such as Exception Handling, pre and post functionality.

There is some overhead that we add by injecting code, but with some careful programming and configuration we can turn the AOP functionality off at will. Currently I don’t know if we can turn off the actual AOP calls but what you can do is examine some configuration value and skip the instructions whenever that particular functionality is turned off.

In the current proof of concept that I am working on, I think it would be sufficient to either turn logging on or off via a config file and have the OnEnter/OnExit methods return early whenever logging is off.

I have done some simple bench marks on this concept and it turns out that it adds about 15% overhead. I ran that experiment with a loop of ten thousand method calls. This is, of course, with an early return call. If the code actually does some real work you will significantly add overhead – many times more depending on what your pre and post condition code is actually doing. Here are the methods that I wrote for the experiment:

        public override void OnEntry(MethodExecutionArgs args)
        {
            if (!AppGlobals.LoggingIsOn)
                return;

            base.OnEntry(args);

            CreateLogger();
            _logger.Log("Entered " + ConvertMethodExecutionArgsToString(args));
        }


        public override void OnExit(MethodExecutionArgs args)
        {
            if (!AppGlobals.LoggingIsOn)
                return;

            base.OnExit(args);

            CreateLogger();
            _logger.Log(("Exited " + ConvertMethodExecutionArgsToString(args)));
        }

Currently I am looking into ways that we can incorporate this into our current product without making any significant changes to our code. Also this would be implemented in combination with existing .Net instrumentation.

As you can imagine, AOP has many uses to include Exception Handling, Logging, Security filters. We can also add it to decorate functionality. For example let’s say we have some methods that should only execute when the system is online.

[EnsureSystemIsOnLine]
void GetLinkedInContacts()
{

}

In this example we can actually force the code to interrupt execution of the code by returning early and informing the user that the system is not currently online. We can do this bye adding the line args.FlowBehavior = FlowBehavior.Return in our OnEntry method.

You can learn more about AOP and PostSharp from the following resources:

As you can see there are many uses to AOP. What will you be using AOP for?

One Response to Simplifying Logging In Your Application with PostSharp and AOP

  • Diego
    July 25, 2012

    Simple and well explained!

Leave a Reply




Post Comment

Connect With Us

Recent Posts

A Guide for Learning Design Patterns

July 28th 2016 by Fernando Zamora If you’ve been writing code for more than a year, you might have h...

Read More

Using UML to Analyze Legacy Code

June 30th 2016 by Fernando Zamora For every programmer out there creating brand new code and working...

Read More

Python vs. Other Languages

April 29th 2016 by Fernando Zamora For the last two months or so my fellow McLane Advanced Technolog...

Read More

Naming Your Adapter When Implementing the Adapter Pattern

October 19th 2015 by Fernando Zamora At some point in your project you may need to use a third party...

Read More

10 Methods to Help You Debug Legacy Code

September 24th 2015 by Fernando Zamora A large majority of the work we do in our project is to fix r...

Read More