Click here to Skip to main content
15,867,594 members
Articles / MVC

MVC - log4net Controller Action Tracing Using Global Filters

Rate me:
Please Sign up or sign in to vote.
5.00/5 (1 vote)
10 Mar 2012CPOL2 min read 39.9K   7   2
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.

C#
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:

C#
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.

XML
<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)


Written By
Technical Lead
United Kingdom United Kingdom
This member has not yet provided a Biography. Assume it's interesting and varied, and probably something to do with programming.

Comments and Discussions

 
QuestionMiniProfiler + Log4Net Pin
Thang Believe4-Jun-14 12:56
Thang Believe4-Jun-14 12:56 
If you are still looking for a way to perform logging per user, check out this solution:

https://miniprofilerlog4net.codeplex.com/

It has user ID, timestamp and duration logged for each request.
QuestionHttpMessageHandler Pin
Craig G. Wilson11-Mar-12 8:25
Craig G. Wilson11-Mar-12 8:25 

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

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