Tagged: Logging

Aspect Oriented (AOP) Logging

Aspect Oriented ProgrammingLogging can be an aspect in your code that can be treated separately from you real business processing code. In most of the systems I worked on, we ended up putting logging code dispersed among our other code. This may not be a *very* bad practice but too many lines of repeat code ! Even if you have a nice logging framework where the mechanics of logging, its configuration, etc. are abstracted away, you still have to call your “Log” or “Trace” public methods to do the actual logging. Using AOP style of design, we can abstract away these aspects to a central place where individual developers need not worry about adding these to their code.
Logging and Exception Handling are 2 common aspects that can be handled in this manner for most of the systems, (there are many other aspects too depending on what you are building).

Read about Aspect Oriented Programming (AOP) here (Wiki article) and here (developer.com)

This is not that hard as you might think if you use some of the great frameworks like Castle Windsor or PostSharp. Ayende @ Rahien has a great blog (as always) explaining AOP way of logging using Castle Windsor IoC container. [Link] Simple and straight-forward and works great!

Another approach is to use PostSharp. It weaves aspect code at compile time. Its clean and simple to implement. Follow the steps below to setup some basic AOP logging using PostSharp. In my example, I have an MVC web application and want to trace all the controller methods,

We will create a new class first, call it TraceAspect, derive this class from PostSharp.Aspects.OnMethodBoundaryAspect. OnMethodBoundaryAspect is an abstract class with
4 virtual methods, OnEntry(), OnExit(), OnSucess() and OnException(). You can override these methods to get information about the logging context.

(Note: I am working with PostSharp 2.0, can be downloaded for a 45 day evaluation from here.)
Code:

    using System;
    using System.Diagnostics;
    using System.Text;
    using PostSharp.Aspects;

    [Serializable]
    public sealed class TraceAspect : OnMethodBoundaryAspect
    {


        private readonly string _controllerName;
        public TraceAspect(string controllerName)
        {
            this._controllerName = controllerName;
        }
        public string Category
        {
            get { return _controllerName; }
        }
        public override void OnEntry(MethodExecutionArgs args)
        {
            Trace.WriteLine(string.Format("Entering {0}.{1}.",args.Method.DeclaringType.Name, args.Method.Name), this._controllerName);
            if (args.Arguments != null)
            {
                StringBuilder sb = new StringBuilder();
                for (int i = 0; i < args.Arguments.Count; i++)
                {
                    sb.AppendFormat("{0}:'{1}'", args.Method.GetParameters()[i], Convert.ToString(args.Arguments.GetArgument(i)));
                }
                Trace.WriteLine(sb.ToString());
            }

        }
        public override void OnSuccess(MethodExecutionArgs args)
        {
            Trace.WriteLine(string.Format("Return Value = {0}",args.ReturnValue));
        }

        public override void OnException(MethodExecutionArgs args)
        {
            Trace.WriteLine(string.Format("Return Value = {0}", args.Exception.Message));
            args.FlowBehavior = FlowBehavior.Continue;   
        }

        public override void OnExit(MethodExecutionArgs args)
        {
            Trace.WriteLine(string.Format("Exiting {0}.{1}.",args.Method.DeclaringType.Name, args.Method.Name), this._controllerName);
            Trace.WriteLine(string.Format("Method returned {0}", args.ReturnValue));
        }
    }

If I was not using any AOP style logging, my controller will look like this,

        public JsonResult DoSomething(string inputParam)
        {
            Trace.WriteLine("Inside DoSomething()");
            try
            {
                //Call downstream method calls to do something
                //...
                Trace.WriteLine("Result :: " + DateTime.Now.ToShortTimeString());
                return Json(DateTime.Now.ToShortTimeString());
             
            }
            catch (Exception exception)
            {
                Trace.WriteLine(exception.Message); 
            }
            finally
            {
                Trace.WriteLine("Exiting DoSomething()");
            }
            return (null);
        }

and all those Trace calls can go away with one line of code (attribute decoration) to your method with PostSharp AOP logging!

        [TraceAspect("DoSomething")]
        public JsonResult DoSomething(string inputParam)
        {
           return Json(DateTime.Now.ToShortTimeString());

        }

Run your application and you will see trace like this:

============================================================
DoSomething: Entering ServiceController.DoSomething.
System.String p:'time'
Return Value = System.Web.Mvc.JsonResult
DoSomething: Exiting ServiceController.DoSomething.
Method returned System.Web.Mvc.JsonResult
============================================================

In my case, input I passed from my client code that is calling this controller was ‘time’, and since the result is a JsonResult, you will need to deserialize to see the actual result. If you are any scalar values you will be able to see that with ReturnValue property directly. If you are passing a custom object/DTO, may be you can override ToString() to print state of the object and that can be used to trace here, essentially many ways to do it! Also, in this example I am using Trace class to write the trace log, You can replace this with your enterprise logging library where you can turn ON and OFF and adjust your trace levels too.

Cheers!
Binu