MVC 异常和跟踪日志记录的全局过滤器
4.87/5 (9投票s)
如何使用全局 MVC 过滤器实现异常日志记录和跟踪日志记录
引言
本文提供了两个详细示例，展示了如何在 MVC 应用程序中使用过滤器来实现全局异常处理和全局跟踪日志。
背景
面向对象范式擅长将复杂系统分解为组件并通过这些组件描述系统。面向对象编程通过将信息封装在具有明确接口的代码段（“类”）中，从而实现关注点分离（SoC）。信息系统中的分层设计模式（例如，将程序分为表示层、业务逻辑层、数据访问层和持久层，以及模型-视图-控制器、模型-视图-视图模型和模型-视图-表示器等架构模式）实现了更高层次的 SoC。
尽管面向对象范式在组织和管理程序的业务特定关注点方面已被证明非常有效，但在处理所谓的横切关注点时却不那么有效。横切关注点是影响系统多个组件的关注点。传统上，诸如性能检测、缓存、安全、日志记录和异常处理等非业务特定关注点的实现需要在多个组件中重复样板代码。
横切关注点必须在与应用程序类不同的逻辑级别上处理。为了解决这些问题，施乐帕洛阿尔托研究中心实验室在 20 世纪 90 年代引入了一种新的独特编程范式，称为面向切面编程（AOP），它构成了新兴软件开发技术面向切面软件开发的一部分。
在 MVC 框架引入之前，.NET 开发人员只能通过使用第三方框架（如 PostSharp）来使用 AOP 功能，尽管由于 AOP 和依赖注入之间的关系，Spring.NET、Castle Windsor、Ninject 和 Microsoft Unity 也可以被认为提供了一些 AOP 功能。熟悉拦截器设计模式的人也应该熟悉 AOP 的一个重要方面。
随着 MVC 的引入，Microsoft 提供了对大量 AOP 功能的原生支持。MVC 框架包含可扩展的模板，用于定义授权、操作、结果和异常过滤器，可用于将自定义处理逻辑注入到控制器代码中。
Code Project 发表了许多关于 MVC 过滤器的优秀入门文章。熟悉这些入门材料被认为是本文其余部分的先决条件。
侧重于特定用途的过滤器文章包括
上述文章中提供的示例代码片段往往达不到在完整生产环境中可用的程度。本文的目的是提供基于实际生产代码的全局异常日志和跟踪日志过滤器的完整功能示例，这些示例只需稍作自定义即可用于实际项目。
一个全局异常处理过滤器
在开发工作站上发生的未处理异常通常会导致向用户发送一个特殊视图，即“死亡黄屏”（HTTP 500 - 内部服务器错误），其中包含不应向最终用户透露的堆栈跟踪信息。在远程机器上，未处理异常的默认响应是向用户发送 YSOD 的清理版本，除了发生运行时错误这一事实之外，几乎没有提供任何信息。无论哪种情况，默认屏幕都很难看且令人望而生畏。
在设计替代 YSOD 的方案时，开发人员必须考虑许多因素
- 用户应该被导向另一个屏幕，还是在当前屏幕上向用户显示错误信息？
- 应该向用户显示多少关于异常的技术信息？在面向外部的应用程序中，最好除了发生运行时错误之外，什么都不透露。应该尽可能少地给黑客提供可利用的信息。对于内部网应用程序，透露异常对象提供的任何默认消息可能是安全的。透露这些有限的信息可以建立良好的公共关系，因为它表明 IT 部门相信其内部客户的智力。
- 除了对发生错误情况的简洁解释之外，还应向用户提供一个日志引用号和/或时间戳，这将有助于 IT 支持人员诊断问题。
除了上述考虑之外，处理由完整回发引起的异常和由部分页面更新（即 Ajax）引起的异常之间存在技术差异。本文仅讨论完整回发的情况。有关如何处理由部分页面更新引起的异常的示例策略，请读者参考我的上一篇文章。
在以下代码片段中，已决定将用户定向到一个名为“Exception”的新视图，并且已决定（可能不明智）可以信任用户，让他们查看异常对象报告的默认消息所提供的信息。提供数据库中日志条目的 ID 以方便 IT 人员进行调查。
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;
}
}
}
LoggingRepository 的 LogException() 方法写入应用程序名称、sessionID、日志类型（“Exception”）、异常消息、堆栈跟踪，以及（如果存在）内部异常的消息和堆栈跟踪，以及当前日期时间：
public class LoggingRepository
{
MusicStoreEntities storeDB = new MusicStoreEntities();
const string APPLICATION = "Music Store";
// Returns the LogId
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
{
// TODO: if Logging fails, provide an alternate mechanism for
// documentation of that fact than through the logging mechanism.
}
return -1;
}
// BLAH BLAH BLAH
}
关于会话变量使用的说明。 ASP.NET 生成一个随机 SessionID，该 SessionID 存储在浏览器上的非过期会话 cookie 中。在首次访问会话对象之前，每次页面请求都会创建一个新的 SessionID，之后 SessionID 变为静态。 只要浏览器在指定超时时间内继续使用相同的 SessionID 值发出请求，会话就保持活动状态。
为了确保存在用于日志记录的静态 SessionID，有必要在会话生命周期的早期至少访问一次会话对象。我们通过在 Global.asax 中实现 Session_Start() 方法并将数据存储在会话对象中来做到这一点，如下所示
void Session_Start(object sender, EventArgs e)
{
var context = System.Web.HttpContext.Current;
context.Session["MakeSessionIDStaticForEntireSession"] = "";
}
在 Global.asax 的 RegisterGlobalFilters() 方法中，我们用自己编写的 GeneralExceptionHandlerAttribute 替换了默认的 HandleErrorAttribute。
public static void RegisterGlobalFilters(GlobalFilterCollection filters)
{
// Replacing the default HandleErrorAttribute
// filters.Add(new HandleErrorAttribute());
filters.Add(new GeneralExceptionHandlerAttribute());
filters.Add(new LogActionRequestAttribute());
}
在附加的示例应用程序中，我编写了测试代码，如果将以前的迪斯科热门歌曲“MacArthur Park Suite”添加到购物车，该代码将抛出异常。抛出异常后，代码将重定向到以下屏幕，并将异常日志条目写入数据库。
一个全局跟踪日志过滤器
在不了解异常发生时情况的情况下，异常消息和堆栈跟踪有时难以解释。了解用户在异常发生时正在做什么以及发生异常的方法正在处理的输入参数的值通常非常有帮助。
在编写通用日志记录器时，我们面临一个问题，即不同动作方法的输入参数将是不同类型的：参数可以是字符串、数值、表单集合对象或与强类型视图关联的模型对象。
动作方法返回的结果更加异构：它们可以是 ViewResults、PartialViewResults、JsonResults、用户定义的 ContentResults 等。通常，动作方法返回的结果在诊断异常的根本原因方面不如输入参数有用，因为只有在没有发生异常中断其生成时才返回 ActionResults。然而，能够监控动作方法结果可以提供有用的见解，了解用户在异常发生前做了什么。
以下操作过滤器使用反射和递归解析器来解释输入参数和输出 ActionResult。其中留下了几个“TODO”供读者自行解决。
- 如果存在用户密码可能以纯文本形式记录的风险，则代码应掩盖密码。
- 需要提供某种管理日志记录级别的方法。TRACE_LEVEL_ENTRY 和 TRACE_LEVEL_EXIT 控制 DiscoverObjectProperties( ) 方法中允许的最大递归深度，以解析输入参数和输出 ActionResult。
public class LogActionRequestAttribute : ActionFilterAttribute, IActionFilter
{
// TODO: Provide some mechanism for these variables to be administratively controlled
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];
}
}
一个字符串扩展方法可以防止输出过于冗长
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 ? " ... " : "");
}
}
跟踪日志方法非常简单
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
{
// TODO: if Logging fails, provide an alternate mechanism for
// documentation of that fact than through the logging mechanism.
}
return -1;
}
解析例程并不完善。正如 Renaud Bompuis 所指出的，尽管反射是一个强大的工具，但某些涉及索引器的场景无法通过任何基于反射的解析器自动解决。反射和递归也非常慢。对于一般日志记录，我建议将 TRACE_LEVEL_EXIT 设置为零，并将 TRACE_LEVEL_ENTRY 设置为一个相当低的数字，肯定不超过三。
在 TRACE_LEVEL_ENTRY 和 TRACE_LEVEL_EXIT 的任何特定设置下，记录的跟踪详细信息量取决于 MVC 开发人员的设计选择。我已在各种在线演示 MVC 程序以及实际生产代码上测试了此处介绍的跟踪日志记录和异常日志记录过滤器。测试的演示程序包括 Jon Galloway 开发的 MVC Music Store、Adam Freeman 和 Steven Sanderson 开发的 MVC Sports Store 以及我自己的 JQGrid Demo。下图显示，在日志记录级别 1 下，Music Store 提供了大量的输入参数日志记录，而 Sports Store 只有在日志记录级别 2 下才能达到相同的程度。图中未显示 JQGridDemo 测试的图像，这些图像演示了跟踪过滤器在日志记录级别 4 下解析 JsonResults 的能力。
下图展示了一个带注释的会话，前总统约翰·亚当斯试图订购一份“MacArthur Park Suite”，结果遇到了异常。入口和出口跟踪级别都设置为 2。SessionID 在“Application”列中仅部分可见，它唯一地标识了会话，在真实情况下，这些会话可能会创建散布的记录。应该很明显，退出跟踪虽然有趣，但对于理解导致异常的事件并非真正必要。
使用代码
- 我已将我修改过的 MVC Music Store 版本附在本文中，其中包含异常和跟踪日志过滤器。
- NuGet 已配置，因此在构建时，它将下载 packages.config 文件中列出的所需包。
- 编辑 Web.config 文件中的连接字符串，使其指向正确的数据库服务器并能够登录到服务器。
- Entity Framework Code First 将在运行时创建 MusicStore 数据库并用示例数据填充 MusicStore 表。
- 您必须手动创建一个空的 MusicStoreSecurity 数据库。
- 在 Visual Studio 命令提示符下，运行 aspnet_regsql，按照说明用必要的表填充 MusicStoreSecurity 数据库，以进行登录、安全和账户管理。
- 请注意 Web.config 文件中，添加“LocalSqlServer”之前，需要先删除 Machine.config 文件中的默认引用。
历史
2014-10-17 首次提交
2014-10-25 添加了一个示例日志