ASP.NET MVC: Using a ActionFilter for logging

The "pre-" preview 3 of the MVC Framework (see here for more information) introduced new features for the ActionFilter.

The "FilterExecutingContext" (using in the OnActionExecuted method) and "FilterExecutedContext" (using in the OnActionExecuting method) are now called "ActionEx...Context".

This is the complete method list from an ActionFilter in this pre-preview:

        public override void OnActionExecuting(ActionExecutingContext filterContext)
        {
            ActionExecutingContext contect = filterContext;
            string test = contect.ActionMethod.ToString();
        }

        public override void OnActionExecuted(ActionExecutedContext filterContext)
        {
            ActionExecutedContext context = filterContext;
            string test = context.ActionMethod.ToString();
        }

        public override void OnResultExecuting(ResultExecutingContext filterContext)
        {
            ResultExecutingContext context = filterContext;
            string test = context.ToString();
        }


        public override void OnResultExecuted(ResultExecutedContext filterContext)
        {
            ResultExecutedContext context = filterContext;
            string test = context.ToString();
        }

A great new feature: You have access to the viewdata form the...

ResultExecutedContext
ResultExecutingContext
ActionExecutedContext Yeah!

With this feature we can now build a very smart logger: Get all ViewData typ information recursive and save this by using Log4Net.

I use this "DumpObject Code" and configure Log4Net like this guy.

The "simple log FilterAction":

namespace Mvc2.Filters
{
    public class LogAttribute : ActionFilterAttribute
    {
        private static readonly ILog log = LogManager.GetLogger(typeof(LogAttribute).Name);

        public override void OnActionExecuted(ActionExecutedContext filterContext)
        {
            ActionExecutedContext context = filterContext;
            
            StringBuilder logMessage = new StringBuilder();
            logMessage.AppendLine(context.ActionMethod.Name);
            
            if(context.Result.GetType() == typeof(RenderViewResult))
            {
                RenderViewResult viewResult = context.Result as RenderViewResult;
                logMessage.AppendLine("ActionResult: RenderViewResult");
                logMessage.AppendLine();
                logMessage.AppendLine(Dumper.DumpObject(viewResult.ViewData, 5));
            }
            logMessage.AppendLine();
            log.Info(logMessage.ToString());
        }

    }
}

And now just add the attribute above the Controller:

[Log]
public class EntryController : Controller
{...}

The result in the log.txt:

2008-04-17 20:41:02,204 [10] INFO  LogAttribute [(null)] - List
ActionResult: RenderViewResult

[ObjectToDump] AS Mvc2.Views.Entry.ListViewData = Mvc2.Views.Entry.ListViewData
+<EntryList>k__BackingField AS Mvc2.Helpers.PagedList`1[[Mvc2.Models.DataObjects.Entry, Mvc2, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]] = Mvc2.Helpers.PagedList`1[Mvc2.Models.DataObjects.Entry]
|+<TotalPages>k__BackingField AS System.Int32 = 2
|+<TotalCount>k__BackingField AS System.Int32 = 17
|+<PageIndex>k__BackingField AS System.Int32 = 1
|+<PageSize>k__BackingField AS System.Int32 = 10
+(System.Collections.Generic.List`1[[Mvc2.Models.DataObjects.Entry, Mvc2, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]])
|+_items AS Mvc2.Models.DataObjects.Entry[] = Mvc2.Models.DataObjects.Entry[]
||+[0] AS Mvc2.Models.DataObjects.Entry = Mvc2.Models.DataObjects.Entry
|||+_Id AS System.Guid = 797c70f0-f571-4969-80e8-d4a085445b6d
|||+_Title AS System.String = test
|||+_Url AS System.String = test
|||+_UserId AS System.Guid = cf2e5ccc-bd32-405d-bd54-eda112ebe06c
|||+_Link AS System.String = http...
|||+_Description AS System.String = tealkjdlsakj
|||+_CategoryId AS System.Guid = 7bd8028e-02c1-45f4-a0a6-403f5bf0ff0c
|||+_Date AS System.DateTime = 17.04.2008 15:48:53
|||+_EntryTags AS System.Data.Linq.EntitySet`1[[Mvc2.Models.DataObjects.EntryTag, Mvc2, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]] = System.Data.Linq.EntitySet`1[Mvc2.Models.DataObjects.EntryTag]
|||+_Category AS System.Data.Linq.EntityRef`1[[Mvc2.Models.DataObjects.Category, Mvc2, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]] = System.Data.Linq.EntityRef`1[Mvc2.Models.DataObjects.Category]
|||+PropertyChanging AS System.ComponentModel.PropertyChangingEventHandler = System.ComponentModel.PropertyChangingEventHandler
|||+(System.MulticastDelegate)
|||+(System.Delegate)
||+[1] AS Mvc2.Models.DataObjects.Entry = Mvc2.Models.DataObjects.Entry
|||+_Id AS System.Guid = 8e1554c1-47fa-4db5-af41-91c3fcf92fb3
|||+_Title AS System.String = EntryTitle
|||+_Url AS System.String = EntryTitle_13
|||+_UserId AS System.Guid = cf2e5ccc-bd32-405d-bd54-eda112ebe06c
|||+_Link AS System.String = http://.../
|||+_Description AS System.String = Blabla
|||+_CategoryId AS System.Guid = 16d09b0a-2157-43b7-a881-b536e90f7fbf
...

This is not the perfect solution - but it should show the "power" of the new ActionFilters.

I will try to create a better (and more readable) version in the next days - with the RouteData/submitted parameters and so on :)

ASP.NET MVC: Using a ActionFilter for logging

Written by Robert Muehsig