• AOP in the ASP.NET MVC way

    Published by on August 6th, 2008 10:54 pm under Uncategorized

    4 Comments

    DISCLAIMER. The following post applies to the Microsoft ASP.NET MVC Extensions (Preview 4) that have been published on July 16th to the ASP.NET Community Web Site at Codeplex.

    Last week I was discussing with Matías about the implementation of DFO (Design For Operations) for a system we are building at Southworks. Our discussion took us to an Ayende’s post that talks about Logging The AOP  Way for .NET. At that moment we thought that’s what we want.

    Later on, reading ScottGu’s blog, we realized that a filtering pipeline has been built for the ASP.NET MVC, so we thought about mixing what ScottGu’s blog says to achieve what Oren’s was posting on Logging the AOP Way.

    I have divided this post in two parts, the first is the conceptual part where I’m going to discuss a little bit about the Filtering model of ASP.NET MVC and then I’ll show a little how-to build a custom tracing filter.

    What are ASP.NET MVC Filter Interceptors?

    As described in ScottGu’s post Action Filter Attributes are declarative way to inject code that can be executed pre and post controller’s action execution. Also the same can be done for pre and post ActionResult conversion into an ASP.NET response. This enables another way to do AOP and achieve for example the logging described by Oren’s at his post.

    How do they work?

    In order to understand how do they work let’s analyze how does the ASP.NET MVC pipeline goes. Below is a diagram that demonstrates how does an action flows from the HttpRequest until the ActionResult gets executed.

    image

    Now, let’s go one by one the items diagrams and I’ll try to explain what’s happening on each part:

    1. The user makes a call using the browser.
    2. Given the URI of the request the ASP.NET MVC Handlers looks for the appropriated controller using the Routes configured on the Global.asax. Prior instantiating the controller a ControllerContext is created. It wraps ,among other things, the current HttpContext for a given request execution.
    3. The ASP.NET MVC engine, instantiates the appropriated controller passing the current context as a parameter.
    4. The controller executes the action that correspond to the current Route.
    5. As a result of the Action execution an ActionResult is returned to the context, given the ActionResult implementation type (must inherit from ActionResult) it might be turned into a View (ASPX Page) or JSON as an example.

    Now that the baseline execution context is a little bit dissected let’s explain where does the ActionFilter attributes hook to this model.

    image

    The items squared with black on the diagram above are the hooks that can be used to inject the code. Those are the interaction points where we can create our hooks and perform crosscutting operations like logging, tracing, error handling and even authZ and authN.

    • OnActionExecuting. The ActionExecuting contains all the data about the action that is going to be executed prior its execution.
    • OnActionExecuted. The ActionExecuted contains all the data gathered after the action execution.
    • OnResultExecuting. The ResultExecuting contains all the data about the ActionResult that is going to be executed. Two of the differences that you will find between this and the previous hook are:
      • If the Action execution ends in an exception you  might not reach this point.
      • If the user called for example "View()" which renders the default view for that action, in the previous one you don’t know the view name.
    • OnResultExecuted. The ResultExecuted contains all the data gathered while the ActionResult was turning into an ASP.NET Response.

    Up to now we understand how does this ActionFilter pipeline works and which data we can get from it. Now, you might be wondering how do you get this in your code. It’s just simple as decorating your Controller and/or Action with the desired Action Filter attribute.

    [TraceFilter]
    public ActionResult Index()
    {
        ViewData["Title"] = "Home Page";
        ViewData["Message"] = "Welcome to ASP.NET MVC!";
    
        return View();
    }

    In the example above I placed a custom attribute called TraceFilterAttribute that is a custom Filter I have created for demo purposes. Wondering how? Read below! :)

    Do it yourself, your own ActionFilterAttribute in 5 minutes.

    In this section we will discuss how to create a custom attribute. This attribute will trace the calls to the controller and log them like:

    image 

    The log entry above displays the Date Time the entry happend, the warn level [Debug ||  Fatal || Error || Information] and the parameters if they were any.

    Step by Step sample

    1. Open Visual Studio (ASP.NET MVC works on Web Express versions of VS2008).

    2. Create a new ASP.NET MVC Web Application and name it as you want.

    3. Using the Solution Explorer, create a folder on web site’s root and name it Filters.

      image

      (Figure 1. – Filters folder on Solution Explorer)

    4. Add a new Class file and name it TraceFilterAttribute.

    5. Delete the TraceFilterAttribute class declaration from the file.

    6. Inside the namespace declaration, use the attribute code snippet to create the attribute structure.

      image

      (Figure 2. Using the Attribute code snippet). 

    7. Name your attribute (using the snippet) TraceFilterAttribute and make it inherit from the ActionFilterAttribute.

      [AttributeUsage(AttributeTargets.All, Inherited = false, AllowMultiple = true)]
      public sealed class TraceFilterAttribute : ActionFilterAttribute
      {
      }

    8. Copy and paste the code below inside your class declaration
      public override void OnActionExecuting(ActionExecutingContext filterContext)
      {
              StringBuilder builder = new StringBuilder();
              filterContext.ActionParameters.ToList()
                                            .ForEach(a => builder.AppendFormat("{0}:{1}; ", 
                                                                               a.Key, 
                                                                               a.Value ?? "{empty}"));
              var parameters = builder.ToString();
      
              var message = string.Format(CultureInfo.InvariantCulture,
                  "{0} {1}.{2} => {3}",
                  filterContext.ActionMethod.ReturnType,
                  filterContext.Controller.GetType().Name,
                  filterContext.ActionMethod.ToString().Replace(filterContext.ActionMethod.ReturnType.ToString(), 
                                                                string.Empty)
                                                       .Trim(),
                  string.IsNullOrEmpty(parameters) ? "(void)" : parameters);
      
              this.logger.Debug(message);
      }

    9. The Logger used above is using Log4Net, which provides and easy and configurable way to do logging.

    10. In order to configure the logger (once you have added the reference to Log4Net) copy and paste the following to your section declaration in your web.config.

      <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" requirePermission="false"/>

       
    11. Now include this other chunk of XML before the </configuration> tag.
      <log4net>
        <!-- The DebugFileAppender writes all messages to a log file-->
        <appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
          <file value="logfile.txt" />
          <appendToFile value="true" />
          <rollingStyle value="Size" />
          <maxSizeRollBackups value="-1" />
          <maximumFileSize value="50GB" />
          <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="(%date) [%-5level] %message%newline" />
          </layout>
        </appender>
        <root>
          <!-- add other appenders here and the log messages will be sent to every listed appender -->
          <appender-ref ref="RollingLogFileAppender" />
        </root>
      </log4net>

       
    12. In order to consume the logger using Log4Net copy and paste the following code inside your class declaration

      private ILog logger;
      
      public TraceFilterAttribute()
      {
          XmlConfigurator.Configure();
          this.logger = LogManager.GetLogger(typeof(TraceFilterAttribute));
      }

       
    13. Now that we have built the attribute, let’s apply it to the Index() method on the HomeController.cs . Your code should look like this:
      [TraceFilter]
      public ActionResult Index()
      {
          ViewData["Title"] = "Home Page";
          ViewData["Message"] = "Welcome to ASP.NET MVC!";
      
          return View();
      }

    14. Press F5 and you will see the default MVC home page.

      image 

    15. Now go the web application project directory and look for the logfile.txt.

    16. Open the logfile.txt, it should look like this

      image 

    17. That’s it , you’ve built your own Action Filter Attribute.

    One more little  trick

    You might want to turn this sample into something for real, there’s a trick that will enable you do the tracing just if debug is enabled. All that you have to do is surround the OnActionExecuting method body with the code depicted below.

    if (filterContext.HttpContext.IsDebuggingEnabled)
    {
        // The method body goes here.
    }

    Now, your attribute will log data just if the Debug mode is enabled on the web.config of your application.

    <compilation debug="true">
     

    Conclusion

    We’ve learnt how to develop a custom Action Filter Attribute. This is a very powerful and cool feature of ASP.NET MVC. This enables you to do logging, tracing and exception handling. I love this approach of doing AOP with Interceptors and the most that I like that is built in to the technology. There’s unlimited power on this, but remember a great power also means a great responsibility.

    thanks,

    ~johnny

    Tags: , , , ,