MVC - log4net Controller Action Tracing Using Global Filters

You may have a need in your MVC projects to perform some logic before or after a controller action executes. The ActionFilterAttribute is custom built for this purpose and you can derive your own classes to perform whatever operations you like.

In this example, we'll create a custom attribute that uses log4net and the StopWatch class to perform some diagnostics so we can determine how long our controller actions are taking.

NB: This is a simple example just to show what we can achieve with global filters, if you want some real application profiling, I suggest you take a look at the MVC mini profiler.

First, in your MVC project, you'd need to add a reference to the log4net assembly. You can download the binaries from the link in this page, or you can use NuGet to locate and add the reference. Once the reference is added, we can create our custom filter.

public class LoggingFilterAttribute : ActionFilterAttribute
{
    #region Logging
    /// <summary>
    /// Access to the log4Net logging object
    /// </summary>
    protected static readonly log4net.ILog log = 
      log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);
    private const string StopwatchKey = "DebugLoggingStopWatch";

    #endregion

    public override void OnActionExecuting(ActionExecutingContext filterContext)
    {
        if (log.IsDebugEnabled)
        {
            var loggingWatch = Stopwatch.StartNew();
            filterContext.HttpContext.Items.Add(StopwatchKey, loggingWatch);

            var message = new StringBuilder();
            message.Append(string.Format("Executing controller {0}, action {1}", 
                filterContext.ActionDescriptor.ControllerDescriptor.ControllerName, 
                filterContext.ActionDescriptor.ActionName));

            log.Debug(message);
        }
    }

    public override void OnActionExecuted(ActionExecutedContext filterContext)
    {
        if (log.IsDebugEnabled)
        {
            if (filterContext.HttpContext.Items[StopwatchKey] != null)
            {
                var loggingWatch = (Stopwatch)filterContext.HttpContext.Items[StopwatchKey];
                loggingWatch.Stop();

                long timeSpent = loggingWatch.ElapsedMilliseconds;

                var message = new StringBuilder();
                message.Append(string.Format("Finished executing controller {0}, 
                               action {1} - time spent {2}",
                    filterContext.ActionDescriptor.ControllerDescriptor.ControllerName,
                    filterContext.ActionDescriptor.ActionName,
                    timeSpent));

                log.Debug(message);
                filterContext.HttpContext.Items.Remove(StopwatchKey);
            }              
        }
    }
}

The class is pretty simple - if our log4net config is set to include DEBUG level information, then the filter will create a StopWatch before the action is executed and add it to HttpContext.Items. Once the code in your Action method has executed, the StopWatch is retrieved and the Elapsed time value recorded and dumped to the logger 'Debug' method.

You now need to register this Filter with MVC - in your Global.asax file. Find method RegisterGlobalFilters and add the following code:

public static void RegisterGlobalFilters(GlobalFilterCollection filters)
{
    filters.Add(new LoggingFilterAttribute());
    // Any other filters here...
}

The logging filter will now execute for every controller action in your project. You can control the information dumped to your log files by simply amending your configuration file. The DEBUG level is the lowest level of log4net so the following configuration would NOT record your diagnostic information - log.IsDebugEnabled would return false with this config.

<log4net>
<root>
  <level value="INFO" />
  <appender-ref ref="RollingLogFileAppender" />
</root>
<appender name="RollingLogFileAppender" 
type="log4net.Appender.RollingFileAppender">
  <file value=".\\Logs\\logfile.txt" />
  <appendToFile value="true" />
  <rollingStyle value="Size" />
  <datePattern value="yyyyMMdd" />
  <maxSizeRollBackups value="5" />
  <maximumFileSize value="100KB" />
  <staticLogFileName value="true" />
  <layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%date 
    [%thread] %-5level %logger - %message%newline" />
  </layout>
</appender>
</log4net>

However, we can switch on diagnostic by changing the above config level from INFO to DEBUG or ALL. With DEBUG messages enabled, you will see messages appearing in your log file that look similar to ...

2011-11-23 12:54:38,393 [4] DEBUG YouNamespace.LoggingFilterAttribute - Executing controller Home, 
                                                                        action Index
2011-11-23 12:54:38,846 [4] DEBUG YouNamespace.LoggingFilterAttribute - Finished executing controller 
                                                                    Home, action Index - time spent 462

By adding additional log4net appenders to your config file, you could send this information to whatever destination you required - such as a SQL server database.

Global filters are a simple yet powerful way to add application level behaviour to your MVC projects.