Automatic Logging with Policy Injection Application Block, Structure Map, and log4net

• Download demo source - 1.05 MB

Introduction

This article will discuss how the Policy Injection Application Block can work with an inversion of control container (such as Structure Map) to automatically log all methods in a project using a third-party logging tool (such as log4net).

By simply calling IoC.Resolve instead of ObjectFactory.GetInstance and adding a [Tag(Tags.Log)] tag to your classes, all methods in your project will automatically log when they are entered and exited and write logs like this:

10/10/10 10:10:10AM - Entering IMyBusinessLogic.GetMyBusinessLogic() 
Parameters: [[(Int64) id = '1234']]

10/10/10 10:10:11AM - Leaving IMyBusinessLogic.GetMyBusinessLogic() 
Return Value: [(LoggingDemo.Models.MyBusinessObject) 
Properties: [[(Int64) Id = '1234'], [(String) Name = 'My Name'], 
[(DateTime) Date = '4/21/2010 3:17:28 PM']]]

The heart of the auto-logging system is the Policy Injection Application Block which allows us to handle cross-cutting concerns such as logging. Using the Policy Injection Application Block along with Structure Map, we can easily log the entrance and exit of all methods in an application. Managing logging (such as turning logging on/off, throttling verbosity, etc.) is then handled by the log4net configuration section in the web.config. Verbose logging of method access is invaluable for debugging a problem in production as you can easily flip a switch in the web.config and instantly see what methods are getting called, when they are getting called, the order in which they are getting called, and how far they get before failing. Once the problem is replicated, verbose logging can be turned off, restoring performance to the production environment.

Background

There are articles out on the web on how to use the Policy Injection Application Block with the Enterprise Library’s Logging Block, but some work environments are already using log4net (for example, with NHibernate) and want to continue using that logging tool rather than manage two logging tools. This article assumes you already know how to use Structure Map and log4net (or can Google them for further instruction), so they will only be discussed briefly here.

Getting Started

You'll want to download and install the Enterprise Library 4.1 from Microsoft so you get their Enterprise Library Configuration editor to easily mod the web.config.

The article includes a quick MVC .NET demo project that includes DLLs from these open-source/free libraries:

• Enterprise Library 4.1 from Microsoft
• log4net 1.2.10.0
• Structure Map 2.5.3.0

In your own projects, be sure to add and reference these DLLs in your project:

• log4net.dll
• Microsoft.Practices.EnterpriseLibrary.Common.dll
• Microsoft.Practices.EnterpriseLibrary.Data.dll
• Microsoft.Practices.EnterpriseLibrary.PolicyInjection.dll
• Microsoft.Practices.ObjectBuilder2.dll
• Microsoft.Practices.Unity.dll
• Microsoft.Practices.Unity.Interception.dll
• StructureMap.AutoMocking.dll
• StructureMap.dll

This demo uses a custom controller factory called StructureMapControllerFactory that automagically fetches controller instances from Structure Map. It’s activated in the Application_Start method in the global.asax.

The Call Handler

The heart of the auto-logging system is the Policy Injection Application Block call handler and its configuration settings in the web.config.

First, create a new class that implements the ICallHandler interface. You'll see an example of this in the MethodLoggingCallHandler class in the demo source. You'll want to add the [ConfigurationElementType(typeof (CustomCallHandlerData))] decorator to the class so it shows up in the Microsoft Enterprise Library Configuration editor in the next step. You'll have to create a constructor overload that accepts a NameValueCollection as a parameter, but you don't have to use that parameter.

Next you'll need to implement the Invoke method required by the interface. This is the key method in the entire system as this method is called on every method in the project that is tagged for logging. In the Invoke method, we instantiate our third party logging tool (i.e. log4net), then write the method entrance log including the method name and input parameters.

public IMethodReturn Invoke(IMethodInvocation input, GetNextHandlerDelegate getNext)
{
   ILog log = LogManager.GetLogger("MyLog");
   log.Debug("Entering " + input.MethodBase.DeclaringType.FullName + 
	"." + input.MethodBase.Name + "() Parameters: [" + 
	GetParameters(input.Inputs) + "]");

Then call the actual method the policy is wrapping:

IMethodReturn result = getNext()(input, getNext);

Finally, we write the method exit log including the return value(s). The GetObjectPropertiesString method fetches the type, name, and value of every parameter. For primitive types, only the type and value are shown. For collections, only the name and type are written as we don't want to log every object in a collection containing possibly thousands of objects.

Configuring the Policy Injection Application Block

Using the Microsoft Enterprise Library Configuration editor, view the project’s web.config (the screen shot is from Enterprise Library 4.1, the editor looks different in 5.0 and later).

1. Right-click on the config file node and add a new Policy Injection Block to the web.config.

   

2. Add a new Policy to the Policies.
3. Add a new Tag Attribute Matching Rule to Matching Rules.
   1. In the matching rule’s properties, change the Match to “Log”.
   2. NOTE: Only use the Tag Attribute Matching Rule as there is a known bug in Enterprise Library 4.1 where the Custom Attribute Matching Rule calls every Invoke method twice.
4. Add a new Custom Handler to Handlers.
5. In the custom handler’s properties, change the Type to your MethodLoggingCallHandler.
   1. If you don't see it in the list, press the Load From File button and load your project’s DLL from your bin, then you will see your call handler in the list.

Wrapping your Class Instances with the Policy Injector

All classes that are going to implement the auto-logging system will need to be wrapped by the policy injector. This is easily done using a static class we'll call IoC. This class accepts a type parameter, fetches an instance using our inversion of control container (e.g. Structure Map) then returns that instance wrapped by the policy injector. In practice, you just use IoC.Resolve instead of ObjectFactory.GetInstance. Thanks to David Hayden at codebetter.com for this easy solution.

public static T Resolve<T>()
{
   // get from StructureMap
   T instance = ObjectFactory.GetInstance<T>();
   // wrap using Policy Injection Application Block
   return PolicyInjection.Wrap<T>(instance);
}

Since we also want to wrap existing instances (such as when dependency injection in class constructors and when logging child methods within a class), we want an overload that excepts the instance and returns the wrapped instance.

public static T Resolve<T>(T instance)
{
   // wrap using Policy Injection Application Block
   return PolicyInjection.Wrap<T>(instance);
}

Now all class instantiations that you want to be logged call IoC.Resolve as you can see in the Index action of the HomeController:

public ActionResult Index()
{
   ViewData["Message"] = "Welcome to ASP.NET MVC!";
   IMyBusinessLogic demo = IoC.Resolve<IMyBusinessLogic>();
   demo.GetMyBusinessLogic(1234);
   return View();
}

One Non-Intuitive Gotcha

There’s one feature in the Policy Injection Application Block that's a little non-intuitive that I wasn't able to iron out completely: The Policy Injection Application Block does not recursively log method calls. So if your method calls another method (even a public method in the same class), only the parent method gets logged. In order to log the child method, you don't want to call internal methods directly, you must use an instance of your class that is wrapped in IoC.Resolve and then call your method through the wrapped instance. For example, if the GetMyBusinessLogic method called GetMyOtherBusinessLogic, and we want to log both methods, we need to create a wrapped instance of IMyBusinessLogic and call GetMyOtherBusinessLogic through that. In other words, you can't just call GetMyOtherBusinessLogic from GetMyBusinessLogic if you want to log both methods, you'd have to expose any and all methods you want to log in the interface so IoC.Resolve can wrap them in the Policy Injection Application Block. The demo source code illustrates this:

public MyBusinessObject GetMyBusinessLogic(Int64 id)
        {
            // need to get a wrapped instance of this class 
            // so the child method is also logged
            IMyBusinessLogic myBusinessLogic = IoC.Resolve<imybusinesslogic>(this);
            return myBusinessLogic.GetMyOtherBusinessLogic(id);
        }

        public MyBusinessObject GetMyOtherBusinessLogic(Int64 id)
        {
            return new MyBusinessObject {Date = DateTime.Now, Id = id, Name = "My Name"};
        }

Tagging Your Classes or Methods for Logging

Since magic strings are evil, we create a static class called Tags that holds the tag name we specified in the policy config setting. Now we can easily change the log name without having to change possibly hundreds of files.

public static class Tags
{
   public const string Log = "Log";
}

Now for any method you want to log, simply add this decorator: [Tag(Tags.Log)]. If you want to automatically log all the methods in a class, just add the decorator to the class instead.

Try It Out

Go to the demo project’s home page, then you will see a new log file in the Logs folder for today’s date. It will list the date and time the method was entered/exited, the thread number used, and a brief message.

Summary

By calling IoC.Resolve instead of ObjectFactory.GetInstance and tagging your classes with [Tag(Tags.Log)], you automatically log the entrance and exit of all methods in your solution without code clutter. The solution includes the method name, parameters, and return values in the log and can be easily refactored in the future.