Click here to Skip to main content
Click here to Skip to main content

Tagged as

MVC - log4net Controller Action tracing using global filters

, 10 Mar 2012
Rate this:
Please Sign up or sign in to vote.
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 fiile 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.

License

This article, along with any associated source code and files, is licensed under The Code Project Open License (CPOL)

Share

About the Author

Dylan Morley
Technical Lead
United Kingdom United Kingdom
No Biography provided

Comments and Discussions

 
QuestionMiniProfiler + Log4Net PinmemberThang Believe4-Jun-14 12:56 
QuestionHttpMessageHandler PinmemberCraig G. Wilson11-Mar-12 8:25 
While an action filter is easy enough to do, it is requiring the use of HttpContext.Items to keep track of state.   In addition, it wouldn't get invoked when an action couldn't be resolved.
 
I believe an easier way (and better) to handle this is to use an HttpMessageHandler.   This way, closures will allow you to keep stopwatch time locally scoped.   In addition, it will also pick up 404's that never amounted to an action getting invoked.
 
Perhaps you could write another article demonstrating this technique.

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.

| Advertise | Privacy | Mobile
Web04 | 2.8.140827.1 | Last Updated 10 Mar 2012
Article Copyright 2012 by Dylan Morley
Everything else Copyright © CodeProject, 1999-2014
Terms of Service
Layout: fixed | fluid