Introduction
This article presents two detailed examples showing how filters may be used to implement global exception handling and global trace logging in an MVC application.
Background
The object oriented paradigm excels in breaking a complex system down into components and describing the system through these components. Object-oriented programming enables Separation of Concerns (SoC) by encapsulating information inside sections of code ("classes") that have a well-defined interface. Layered design patterns in information systems (eg. separation of a program into presentation, business logic, data access and persistence layers, and architectural patterns such as Model-View-Controller, Model-View-ViewModel, and Model-View-Presenter) enable higher levels of SoC.
Although the object oriented paradigm has proven highly effective in organizing and making manageable a program's business-specific concerns, it has proven somewhat less effective when dealing with so-called cross-cutting concerns. Cross-cutting concerns are concerns that affect multiple components of a system. Traditionally, the implementation of non-business-specific concerns such as performance instrumentation, caching, security, logging and exception handling have required repetition of boilerplate code in multiple components.
Cross-cutting concerns must be dealt with at a different logical level than application classes. To address these issues, Xerox PARC Laboratories, in the 1990s, introduced a new and distinct programming paradigm known as Aspect-Oriented Programming (AOP), which forms part of an emerging software development technology known as Aspect-Oriented Software development.
Prior to the introduction of the MVC framework, features of AOP were available to the .NET developer only through the use of third party frameworks such as PostSharp, although because of the relationship between AOP and dependency injection, Spring.NET, Castle Windsor, Ninject and Microsoft Unity can also be considered to have provided some AOP functionality. Those familiar with the interceptor design pattern should also be familiar with an important aspect of AOP.
With the introduction of MVC, Microsoft has provided native support for a significant sampling of AOP capabilities. The MVC framework includes extensible templates for defining authorization, action, result and exception filters that can be used to inject custom processing logic into one's controller code.
Code Project has published a number of good introductory articles on MVC Filters. Familiarity with this introductory material is considered a prerequisite for the rest of this article:
Articles focusing on filters for specific purposes include:
The example code snippets presented in the above articles have tended to fall short of what would be usable in a full production environment. The intention of this article is to provide fully functional examples of global exception logging and trace logging filters, based on actual production code, that require only minor customization before they may be used in a real project.
A global exception handling filter
An unhandled exception occurring on a development workstation generally results in a special view being sent to the user, a "yellow screen of death" (HTTP 500 - internal server error) with stack trace information that should never be revealed to an end user. On a remote machine, the default action in response to an unhandled exception is to send the user a sanitized version of the YSOD that supplies little information other than the fact that a runtime error has occurred. In either event, the default screen is ugly and intimidating.
In designing an alternative to the YSOD, the developer must take into account a number of considerations:
- Should the user be directed to another screen, or should the error information be presented to the user while on the current screen?
- How much technical information about the exception should be presented to the user? In an externally-facing application, it is probably best to reveal nothing at all about the exception other than that a runtime error has occurred. One should give hackers as little as possible to work with. For an intranet application, it is probably safe to reveal whatever default message has been provided by the exception object. Revealing this limited amount of information can make for good public relations, since it shows that IT believes in the intelligence of their internal customers.
- The user should be provided not just a succinct explanation of what went wrong, but should also be provided a log reference number and/or a timestamp which will aid IT Support Members in diagnosing the issue.
In addition to the above considerations, there are technical differences between handling exceptions resulting from full postbacks versus those resulting from partial page updates (i.e. Ajax). This article deals only with the full postback case. For example strategies on how to deal with exceptions resulting from partial page updates, the reader is referred to my previous article:
In the following code snippet, the decision has been made that the user should be directed to a new view called "Exception", and it has been decided (perhaps not wisely) that the user can be trusted with the information provided by the default message reported by the exception object. The id of the log entry in the database is provided to facilitate investigations by the IT staff.
public class GeneralExceptionHandlerAttribute : FilterAttribute, IExceptionFilter
{
public void OnException(ExceptionContext filterContext)
{
if (!filterContext.ExceptionHandled)
{
var msg = new string[2];
msg[0] = filterContext.Exception.Message;
var logRepository = new LoggingRepository();
var logID = logRepository.LogException(filterContext.Exception);
HttpContext.Current.Session["CustomErrorMessage"] = msg[0];
msg[1] = logID.ToString();
var repository = new LoggingRepository();
repository.LogException(filterContext.Exception);
filterContext.Result = new ViewResult
{
ViewName = "Exception",
ViewData = new ViewDataDictionary<string[]>(msg)
};
filterContext.ExceptionHandled = true;
}
}
}
The LogException() method of the LoggingRepository writes out the name of the application, the sessionID, the log type ("Exception"), the exception message, stack trace, and (if present) the message and stack trace of the inner exception, and the current datetime:
public class LoggingRepository
{
MusicStoreEntities storeDB = new MusicStoreEntities();
const string APPLICATION = "Music Store";
public long LogException(Exception ex)
{
var sb = new StringBuilder();
var exceptionType = ex.GetType().ToString();
var exceptionTypeSplit = exceptionType.Split('.');
exceptionType = exceptionTypeSplit[exceptionTypeSplit.Length - 1];
sb.Append(exceptionType).Append(": ").Append(ex.Message);
sb.Append(ex.StackTrace);
var innerException = ex.InnerException;
if (innerException != null)
{
var innerExType = innerException.GetType().ToString();
var innerExTypeTypeSplit = innerExType.Split('.');
innerExType = innerExTypeTypeSplit[innerExTypeTypeSplit.Length - 1];
sb.Append("\r\nINNER EXCEPTION: ").Append(innerExType).Append(": ")
.Append(innerException.Message).Append(innerException.StackTrace);
}
var context = System.Web.HttpContext.Current;
var logEntity = new Logging()
{
Application = APPLICATION + " " + context.Session.SessionID,
LogType = "Exception",
Message = sb.ToString(),
UserId = string.IsNullOrEmpty(context.User.Identity.Name)
? "" : context.User.Identity.Name,
CreatedDate = DateTime.Now,
};
try
{
storeDB.Loggings.Add(logEntity);
storeDB.SaveChanges();
return logEntity.LogId;
}
catch
{
}
return -1;
}
}
Note on the use of session variables. ASP.NET generates a random SessionID which is stored in a non-expiring session cookie on the browser. A new SessionID is created for each page request until the first time that the session object is accessed, after which the SessionID becomes static. A session remains active as long as the browser continues to make requests with the same SessionID value within a specified timeout.
To ensure the existence of a static SessionID for logging purposes, it is necessary, early in the session life cycle, to access the session object at least once. We do this by implementing the Session_Start() method in Global.asax and storing data in the session object, as shown below:
void Session_Start(object sender, EventArgs e)
{
var context = System.Web.HttpContext.Current;
context.Session["MakeSessionIDStaticForEntireSession"] = "";
}
In the RegisterGlobalFilters() method in Global.asax, we replace the default HandleErrorAttribute with the GeneralExceptionHandlerAttribute that we have written:
public static void RegisterGlobalFilters(GlobalFilterCollection filters)
{
filters.Add(new GeneralExceptionHandlerAttribute());
filters.Add(new LogActionRequestAttribute());
}
In the attached sample application, I have written test code that will throw an exception if the former disco hit "MacArthur Park Suite" is added to the shopping cart. Upon throwing an exception, the code redirects to the following screen, and an exception log entry is written to the database:
A global trace logging filter
Exception messages and stack traces are sometimes difficult to interpret in the absence of knowledge of what was happening at the time of the exception. It is often very helpful to know what the user was doing at the time of the exception and what the values of the input parameters were that the exceptioning method was working with.
In writing a generic logger, we are confronted with a problem, in that the input parameters to different action methods will be of diverse types: the parameters may be strings, numeric values, form collection objects, or model objects associated with strongly typed views.
The results returned by an action method are even more heterogeneous: they may be ViewResults, PartialViewResults, JsonResults, user-defined ContentResults, and so forth. In general, the results returned by an action method are not as useful as input parameters in diagnosing the root cause of an exception, because ActionResults are only returned if no exception has occurred to interrupt their generation. Nevertheless, being able to monitor action method results can provide useful insight as to what a user was doing in the moments before an exception.
The following action filter uses reflection and a recursive parser to interpret input parameters and output ActionResults. Several "TODOs" have been left for the reader.
- If there is risk that a user password may be logged in plain text, the code should mask the password.
- Some means of administratively controlling the level of logging needs to be provided. TRACE_LEVEL_ENTRY and TRACE_LEVEL_EXIT control the maximum depth of recursion allowed in the DiscoverObjectProperties( ) method to parse input parameters and output ActionResults.
public class LogActionRequestAttribute : ActionFilterAttribute, IActionFilter
{
private int MAX_STRING_LEN = 500;
private int MAX_RECORD_LEN = 2000;
private string PASSWORD_STRING = "PASSWORD";
private int TRACE_LEVEL_ENTRY = 2;
private int TRACE_LEVEL_EXIT = 2;
void IActionFilter.OnActionExecuting(ActionExecutingContext filterContext)
{
if (TRACE_LEVEL_ENTRY < 1) return;
var sb = new StringBuilder();
sb.Append("Enter: ");
sb.Append("ActionName:")
.Append(filterContext.ActionDescriptor.ActionName).Append("; ");
sb.Append("ControllerName:")
.Append(filterContext.ActionDescriptor.ControllerDescriptor.ControllerName)
.Append("; ");
sb.Append("ActionParameters:{");
var keys = filterContext.ActionParameters.Keys.ToArray();
for (int i = 0; i < keys.Count(); i++)
{
sb.Append(keys[i]).Append(":");
var value = filterContext.ActionParameters[keys[i]];
if (keys[i].ToUpper().Contains(PASSWORD_STRING))
{
sb.Append("xxxxxxxx");
}
else
{
ParseParameterProperties(sb, value, TRACE_LEVEL_ENTRY);
}
if (i + 1 < keys.Count()) sb.Append("; ");
}
sb.Append("} ");
var message = sb.ToString();
var repository = new LoggingRepository();
repository.LogTrace(message);
}
void IActionFilter.OnActionExecuted(ActionExecutedContext filterContext)
{
if (TRACE_LEVEL_EXIT < 1) return;
var sb = new StringBuilder();
sb.Append("Exit: ");
DiscoverObjectProperties(sb, filterContext.Result, TRACE_LEVEL_EXIT);
var message = sb.ToString().Trunc(MAX_RECORD_LEN);
var repository = new LoggingRepository();
repository.LogTrace(message);
}
private void ParseParameterProperties(StringBuilder sb, Object obj, int recurse)
{
if (obj == null) return;
var type = obj.GetType();
if (type == typeof(System.String))
{
sb.Append(obj.ToString()).Append("; ");
}
else if (type == typeof(System.Int16) || type == typeof(System.Int32)
|| type == typeof(System.Int64) || type == typeof(System.UInt16)
|| type == typeof(System.UInt32) || type == typeof(System.UInt64)
|| type == typeof(System.Byte) || type == typeof(System.SByte)
|| type == typeof(System.Enum) || type == typeof(System.Single)
|| type == typeof(System.Double) || type == typeof(System.DateTime)
|| type == typeof(System.Decimal) || type == typeof(System.Char)
|| type == typeof(System.Guid) || type == typeof(System.DateTime)
|| type == typeof(System.TimeSpan) || type == typeof(System.Boolean))
{
sb.Append(obj.ToString()).Append("; ");
}
else if (type == typeof(System.Web.Mvc.FormCollection))
{
var formCollection = (FormCollection)obj;
var keys = formCollection.AllKeys;
sb.Append("{");
foreach (var key in keys)
{
if (key.ToUpper().Contains(PASSWORD_STRING))
{
sb.Append(key).Append(":xxxxxxxx; ");
}
else
{
var value = formCollection.GetValue(key);
sb.Append(key).Append(":").Append(value.AttemptedValue).Append("; ");
}
}
sb.Append("}; ");
}
else
{
DiscoverObjectProperties(sb, obj, recurse - 1);
}
}
private void DiscoverObjectProperties(StringBuilder sb, Object obj, int recurse)
{
if (recurse <= 0) return;
if (obj == null) return;
var shortName = ShortName(obj);
if (shortName == "TempDataDictionary"
|| shortName == "DynamicViewDataDictionary" || shortName == "ViewDataDictionary"
|| shortName == "ViewEngineCollection" || shortName == "RouteValueDictionary")
{
return;
}
sb.Append(shortName).Append(":{");
if (obj as ICollection != null)
{
var count = (obj as ICollection).Count;
for (int i = 0; i < count; i++)
{
var en = (obj as ICollection).GetEnumerator();
while (en.MoveNext())
{
DiscoverObjectProperties(sb, en.Current, recurse - 1);
}
}
sb.Append("}; ");
return;
}
var properties = obj.GetType().GetProperties();
foreach (var info in properties)
{
if (info.CanRead)
{
if (info.GetIndexParameters().Length > 0)
{
bool isIndexed = false;
foreach (var prop in properties)
{
if (prop.Name == "Count")
{
isIndexed = true;
break;
}
}
if (isIndexed)
{
for (int i = 0; i < info.GetIndexParameters().Length; i++)
{
var item = info.GetValue(obj, new Object[] { i });
DiscoverObjectProperties(sb, item, recurse - 1);
}
}
continue;
}
Object o = info.GetValue(obj, null);
Type type = (o == null) ? null : o.GetType();
if (o == null)
{
sb.Append(info.Name).Append(":; ");
}
else if (type == typeof(System.String))
{
if (info.Name.ToUpper().Contains(PASSWORD_STRING))
{
sb.Append(info.Name).Append(":xxxxxxxx; ");
}
else
{
sb.Append(info.Name).Append(":")
.Append((o == null) ? "" : o.ToString()
.Trunc(MAX_STRING_LEN)).Append("; ");
}
}
else if (type == typeof(System.String[]))
{
sb.Append(info.Name).Append(":");
var oArray = o as String[];
var oLength = oArray.Length;
var sc = new StringBuilder();
for (int i = 0; i < oLength; i++)
{
sc.Append(oArray[i]);
if (i < oLength - 1) sc.Append("|");
}
sb.Append(sc.ToString().Trunc(MAX_STRING_LEN)).Append("; ");
}
else if (type == typeof(System.Int16) || type == typeof(System.Int32)
|| type == typeof(System.Int64) || type == typeof(System.UInt16)
|| type == typeof(System.UInt32) || type == typeof(System.UInt64)
|| type == typeof(System.Byte) || type == typeof(System.SByte)
|| type == typeof(System.Enum) || type == typeof(System.Single)
|| type == typeof(System.Double) || type == typeof(System.DateTime)
|| type == typeof(System.Decimal) || type == typeof(System.Char)
|| type == typeof(System.Guid) || type == typeof(System.DateTime)
|| type == typeof(System.TimeSpan) || type == typeof(System.Boolean))
{
sb.Append(info.Name).Append(":").Append(o.ToString()).Append("; ");
}
else if (type == typeof(System.Exception))
{
sb.Append(info.Name).Append(":")
.Append((o == null) ? "" : ((Exception)o).Message).Append("; ");
}
else
{
DiscoverObjectProperties(sb, o, recurse - 1);
}
}
}
sb.Append("}; ");
}
private string ShortName(Object obj)
{
var longName = obj.GetType().ToString();
var longNameArray = longName.Split('.');
return longNameArray[longNameArray.Length - 1];
}
}
A string extension method keeps the output from growing too verbose:
public static class StringHelper
{
public static string Trunc(this string str, int maxLength)
{
return str.Substring(0, Math.Min(str.Length, maxLength)) +
(str.Length > maxLength ? " ... " : "");
}
}
The trace log method is straightforward:
public long LogTrace(string message)
{
var context = System.Web.HttpContext.Current;
var logEntity = new Logging()
{
Application = APPLICATION + " " + context.Session.SessionID,
LogType = "Trace",
Message = message,
UserId = string.IsNullOrEmpty(context.User.Identity.Name)
? "" : context.User.Identity.Name,
CreatedDate = DateTime.Now,
};
try
{
storeDB.Loggings.Add(logEntity);
storeDB.SaveChanges();
return logEntity.LogId;
}
catch
{
}
return -1;
}
The parsing routine is not perfect. As pointed out by Renaud Bompuis, although reflection is a powerful tool, certain scenarios involving indexers are not automatically resolvable by any reflection-based parser. Reflection and recursion are also very slow. For general logging, I would consider leaving TRACE_LEVEL_EXIT set to zero, and would set TRACE_LEVEL_ENTRY to a fairly low number, certainly no higher than three.
The amount of trace detail logged at any particular setting of TRACE_LEVEL_ENTRY and TRACE_LEVEL_EXIT depends on design choices made by the MVC developer. I have tested the trace logging and exception logging filters presented here on a variety of online demonstration MVC programs as well as actual production code. The demo programs tested include the MVC Music Store developed by Jon Galloway, the MVC Sports Store developed by Adam Freeman and Steven Sanderson, and my own JQGrid Demo. The following illustration shows that at a logging level of 1, Music Store provided a substantial degree of input parameter logging which was only matched by Sports Store at a logging level of 2. Not shown are images from JQGridDemo tests demonstrating the ability of the trace filter to parse JsonResults at a logging level of 4.
The following illustrates a commented session where former President John Adams attempts to order a copy of "MacArthur Park Suite," only to encounter an exception. Both entry and exit trace levels were set to 2. The SessionID, which is only partially visible in the Application column, uniquely identify the sessions, which in a real situation would likely have created interspersed records. It should be evident that the Exit traces, while interesting, were not really necessary to understand the events leading up to the excetion.
Using the code
- I have attached to this article my modified version of the MVC Music Store, which includes exception and trace logging filters.
- NuGet is configured so that at build time, it will download the required packages listed in the packages.config file.
- Edit the connection strings in the Web.config file so that they point to the correct database server and are capable of logging in to the server.
- Entity framework code first will create the MusicStore database and will populate the MusicStore tables with sample data at run time.
- You must manually create an empty MusicStoreSecurity database.
- From the Visual Studio command prompt, run aspnet_regsql, following the instructions to populate the MusicStoreSecurity database with the necessary tables for login, security and account management.
- Note in the Web.config file, that adding "LocalSqlServer" is preceded by removing the default reference from the Machine.config file.
History
2014-10-17 Initial submission
2014-10-25 Added a sample log
