我的架构经验小结（五）－－ 日志记录
以前写的关于架构经验方面的文章（如上一篇实战中演化的三层架构）都是从整体的角度出发的，采用全局的视角，本文我们将拉近镜头，聚焦于日志记录这一块。随着做软件的时间越长、经验积累得越来越多，就越觉得日志记录的重要。
日志记录的主要作用可以从正反两个方面来说：
（1）如果程序运行出现问题，可以通过相关日志快速定位到出问题的地方，找到问题的根源，从而快速解决问题。对于已上线的系统来说，如果出现一个bug，通常，解决这个bug的时间主要花在定位bug上，一旦找到bug根源，修复它是非常快的。而恰当的日志记录可以帮我们迅速定位bug。
（2）确保我们的系统运行在正常状态。当我们看到日志中类似“***成功完成！”字眼时，我们就确信我们的程序很好的执行了任务，心里就会很踏实。
1.记录应用程序异常
应用程序出现异常，要么是程序bug，要么是出现了意外事件（如磁盘坏掉、网络断开等），这些都是非常严重的事情，否则怎么叫“异”常了。我的习惯是，所有重要的应用程序异常都是必须记录的。当然，如果某异常是属于正常业务逻辑处理的一部分，则也许没必要记录。
我使用ESBasic.Loggers.IExceptionLogger来记录异常：
{
/// <summary>
/// 记录异常。
/// </summary>
/// <param name="ee">异常</param>
/// <param name="methodPath">抛出异常的目标方法。</param>
/// <param name="genericTypes">目标方法的类型参数。如果为非泛型方法，则传入null</param>
/// <param name="argumentNames">调用方法的各Parameters的名称。如果方法没有参数，则传入null</param>
/// <param name="argumentValues">调用方法的各Parameters的值。如果方法没有参数，则传入null</param>
void Log(Exception ee, string methodPath, Type[] genericTypes, string[] argumentNames, object[] argumentValues);
}
Log方法记录的信息非常详细，包括异常的详细内容、异常发声的方法的路径（格式通常为：命名空间.类名.方法名），调用该方法的参数名称和对应的参数值，如果为泛型方法，还要记录泛型参数的类型。
你可能有疑问说，使用起来太麻烦了！因为构造调用这个方法所需的参数比较麻烦，特别是后三个参数。是的，确实是这样，如果你是手动来使用它的话，就需要亲手去打造每一个参数。而我，很少手动去使用它，而是让动态代理来自动使用它。动态代理会截获所有的方法抛出的异常，并构造好上述Log方法所需的所有参数，再调用IExceptionLogger接口来记录这些信息。
ESBasic.Emit.DynamicProxy.DynamicProxyFactory的CreateEfficientAopProxy方法可以创建截获异常的代理，如其重载的某个签名如下：
方法的第二个参数可以传入“截获子”ExceptionInterceptor对象，而ExceptionInterceptor使用IExceptionLogger接口来记录截获到的异常：
/// ExceptionInterceptor 的构造函数。
/// </summary>
public ExceptionInterceptor(IExceptionLogger logger)
至于将截获的异常记录到哪里，取决于IExceptionLogger接口的实现，我的框架提供了两个实现：
（1）ESBasic提供了ESBasic.Loggers.ExceptionFileLogger 用于将异常记录到文本文件。
（2）DataRabbit提供了DataRabbit.Application.Log.AppExceptionTableLogger 用于将异常记录到数据表，数据表可以是物理数据库中的表（如SqlServer中的表），也可以是内存数据库中的表。
如果记录到物理数据库，则可以使用下列的SQL语句创建对应的数据表：
([AutoID] [int] IDENTITY(1,1) NOT FOR REPLICATION NOT NULL, [ApplicationID] [varchar](10) NOT NULL,
[ExceptionType] [varchar](20) NOT NULL,[ErrorMessage] [varchar](200) NOT NULL,[ErrorLevel] [nvarchar](10) NOT NULL,
[Location] [varchar](100) NOT NULL,[ArgumentInfo] [varchar](200) NOT NULL,[OccureTime] [datetime] NOT NULL
CONSTRAINT [PK_AppException] PRIMARY KEY CLUSTERED ([AutoID] ASC))
如果是记录到内存数据库，可以使用对应的Entity定义：
代码
public class AppException
{
public const string TableName = "AppException";
public const string _AutoID = "AutoID";
public const string _ApplicationID = "ApplicationID";
public const string _ExceptionType = "ExceptionType";
public const string _ErrorMessage = "ErrorMessage";
public const string _ErrorLevel = "ErrorLevel";
public const string _Location = "Location";
public const string _ArgumentInfo = "ArgumentInfo";
public const string _OccureTime = "OccureTime";
public AppException() { }
public AppException(string _appID, string _errorType, string _errorMessage, string _location, string _errorLevel, string _argumentInfo)
{
this.applicationID = _appID ?? "";
this.errorType = _errorType ?? "";
this.errorMessage = _errorMessage ?? "";
this.location = _location ?? "";
this.errorLevel = _errorLevel ?? "";
this.argumentInfo = _argumentInfo ?? "";
}
#region AutoID
private System.Int32 m_AutoID = 0;
public System.Int32 AutoID
{
get
{
return this.m_AutoID;
}
set
{
this.m_AutoID = value;
}
}
#endregion
#region ApplicationID
private string applicationID = "";
/// <summary>
/// 出现异常的应用程序的标志。
/// </summary>
public string ApplicationID
{
get { return applicationID; }
set { applicationID = value; }
}
#endregion
#region ExceptionType
private string errorType = "";
/// <summary>
/// 异常的类型。如NullObjectReference。
/// </summary>
public string ExceptionType
{
get { return errorType; }
set { errorType = value; }
}
#endregion
#region ErrorMessage
private string errorMessage = "";
/// <summary>
/// 异常的详细信息。
/// </summary>
public string ErrorMessage
{
get { return errorMessage; }
set { errorMessage = value; }
}
#endregion
#region ErrorLevel
private string errorLevel = "";
/// <summary>
/// 异常的级别 -- 高、中、低。
/// </summary>
public string ErrorLevel
{
get { return errorLevel; }
set { errorLevel = value; }
}
#endregion
#region Location
private string location = "";
/// <summary>
/// 出现异常的具体位置，精确到方法名称。
/// </summary>
public string Location
{
get { return location; }
set { location = value; }
}
#endregion
#region ArgumentInfo
private string argumentInfo = "";
/// <summary>
/// 抛出异常时方法的调用参数信息。
/// </summary>
public string ArgumentInfo
{
get { return argumentInfo; }
set { argumentInfo = value; }
}
#endregion
#region OccureTime
private DateTime occureTime = DateTime.Now;
/// <summary>
/// 异常发生的时间。
/// </summary>
public DateTime OccureTime
{
get { return occureTime; }
set { occureTime = value; }
}
#endregion
}
2.记录数据库访问异常
当程序执行sql语句时抛出的数据访问异常，也是属于异常的一种，当然也可以通过上面的IExceptionLogger来将其记录到文本文件或数据表。DataRabbit框架内部会自动截获所有的数据库访问异常，并调用IExceptionLogger来记录它。
对Log方法所需的调用参数是如此构造的：
（1）第一个参数直接传入截获到的Exception。
（2）第二个参数由发生异常的方法加上所执行的sql语句构成。格式通常为：命名空间.类名.方法名@<commandText>......</commandText>。
（3）第三个参数为泛型类型，由于没有泛型，所以此处传入null即可。
（4）第四个参数由执行SQL语句所需的各个参数的名称构成。
（5）第五个参数由执行SQL语句所需的各个参数的值构成。
所以，当数据库访问抛出异常的时候，通过日志我们可以知道是哪个方法抛出的异常，并且执行的sql语句的文本是什么样的，sql参数是如何的。
3.记录方法执行的时间
在大型系统中，我们经常需要监视我们系统执行的性能状况，当出现性能问题时，我们要能够迅速地找到瓶颈在什么地方。在程序的层面上来说，就是看哪个方法执行所消耗的时间很长（当然，内存也是一个重要方面，这里我们暂且不谈）。
我使用ESBasic.Loggers.IMethodTimeLogger来记录异常：
{
/// <summary>
/// 记录方法执行的时间。
/// </summary>
/// <param name="methodPath">抛出异常的目标方法。</param>
/// <param name="genericTypes">目标方法的类型参数。如果为非泛型方法，则传入null</param>
/// <param name="argumentNames">调用方法的各Parameters的名称。如果方法没有参数，则传入null</param>
/// <param name="argumentValues">调用方法的各Parameters的值。如果方法没有参数，则传入null</param>
/// <param name="millisecondsConsumed">方法执行的时间，毫秒</param>
void Log(string methodPath, Type[] genericTypes, string[] argumentNames, object[] argumentValues, double millisecondsConsumed);
}
同样的，我们不需要手动构造方法所需的参数来调用它，而仍然可以通过上面介绍的动态代理来自动完成这些事情，只需要使用对应的截获子MethodTimeInterceptor就可以了，而MethodTimeInterceptor使用IMethodTimeLogger接口来记录方法的执行时间：
/// MethodTimeInterceptor 的构造函数。
/// </summary>
public MethodTimeInterceptor(IMethodTimeLoggerlogger)
我的框架提供了ESBasic.Loggers.MethodTimeFileLogger 用于将方法执行时间记录到文本文件，并且可以设定只记录那些执行时间大于指定值（如100ms）的方法调用。
4.记录安全日志
安全日志主要用于记录与安全相关的一些操作，比如用户的登陆/退出、修改密码、上线/掉线等。通过记录这些信息我们可以跟踪用户使用系统的状况，并且可以做一些有意义的统计。在我的框架中，我使用ESBasic.Loggers.ISecurityLogger来记录相关安全事件和安全操作。
/// 用于记录安全日志。比如用户的登陆/退出、进入/注销等日志。
/// </summary>
public interface ISecurityLogger
{
/// <summary>
/// 记录安全日志。
/// </summary>
/// <param name="userID">进行安全操作的用户编号</param>
/// <param name="source">来源（比如用户的IP）</param>
/// <param name="taskType">安全操作的类型</param>
/// <param name="comment">备注</param>
void Log(string userID, string source, string taskType ,string comment);
}
比如，在ESFramework的使用中，我们可以使用ISecurityLogger来记录用户的上线/下线/掉线等信息：
/// 用于将用户的上下线事件记录到用户安全日志（可以是文件、数据库、内存数据库等）。
/// </summary>
public class UserSecurityLogBridge
{
#region UserManager
private IUserManager userManager;
public IUserManager UserManager
{
set { userManager = value; }
}
#endregion
#region SecurityLogger
private ISecurityLogger securityLogger;
public ISecurityLogger SecurityLogger
{
set { securityLogger = value; }
}
#endregion
public void Initialize()
{
this.userManager.SomeOneConnected += new ESBasic.CbGeneric<UserData>(userManager_SomeOneConnected);
this.userManager.SomeOneDisconnected += new ESBasic.CbGeneric<UserData>(userManager_SomeOneDisconnected);
this.userManager.SomeOneTimeOuted += new ESBasic.CbGeneric<UserData>(userManager_SomeOneTimeOuted);
this.userManager.SomeOneBeingPushedOut += new ESBasic.CbGeneric<UserData>(userManager_SomeOneBeingPushedOut);
}
void userManager_SomeOneBeingPushedOut(UserData userData)
{
this.securityLogger.Log(userData.UserID, userData.UserAddress.ToString(), "BeingPushedOut", "");
}
void userManager_SomeOneTimeOuted(UserData userData)
{
this.securityLogger.Log(userData.UserID, userData.UserAddress.ToString(), "TimeOuted", "");
}
void userManager_SomeOneDisconnected(UserData userData)
{
this.securityLogger.Log(userData.UserID, userData.UserAddress.ToString(), "Disconnected", string.Format("LogonTime:{0},DownloadBytes:{1}", userData.TimeLogon, userData.TotalDownloadBytes));
}
void userManager_SomeOneConnected(UserData userData)
{
this.securityLogger.Log(userData.UserID, userData.UserAddress.ToString(), "Connected", "");
}
}
只要实现ISecurityLogger接口我们就可以执行真正的记录动作，我们也提供了两种实现：
（1）ESBasic提供了ESBasic.Loggers.SecurityFileLogger 用于将安全日志记录到文本文件。
（2）DataRabbit提供了DataRabbit.Application.Log.SecurityOperationTableLogger用于将安全日志记录到物理数据库或内存数据库。
如果记录到物理数据库，则可以使用下列的SQL语句创建对应的数据表：
([AutoID] [int] IDENTITY(1,1) NOT FOR REPLICATION NOT NULL, [ApplicationID] [varchar](10) NOT NULL, [UserID] [nvarchar](20) NOT NULL,
[Source] [nvarchar](20) NOT NULL,[TaskType] [nvarchar](20) NOT NULL,[Comment] [nvarchar](100) NOT NULL,
[OccureTime] [datetime] NOT NULL
CONSTRAINT [PK_SecurityOperation] PRIMARY KEY CLUSTERED ([AutoID] ASC))
如果是记录到内存数据库，可以使用对应的Entity定义：
View Code
public class SecurityOperation
{
public SecurityOperation() { }
public SecurityOperation(string _appID, string _userID, string _source, string _taskType, string _comment)
{
this.applicationID = _appID ?? "";
this.userID = _userID ?? "";
this.source = _source ?? "";
this.taskType = _taskType ?? "";
this.comment = _comment ?? "";
}
#region AutoID
private System.Int32 m_AutoID = 0;
public System.Int32 AutoID
{
get
{
return this.m_AutoID;
}
set
{
this.m_AutoID = value;
}
}
#endregion
#region ApplicationID
private string applicationID = "";
/// <summary>
/// 出现异常的应用程序的标志。
/// </summary>
public string ApplicationID
{
get { return applicationID; }
set { applicationID = value; }
}
#endregion
#region UserID
private string userID = "";
/// <summary>
/// 进行安全操作的用户编号
/// </summary>
public string UserID
{
get { return userID; }
set { userID = value; }
}
#endregion
#region Source
private string source = "";
/// <summary>
/// 来源（比如用户的IP）
/// </summary>
public string Source
{
get { return source; }
set { source = value; }
}
#endregion
#region TaskType
private string taskType = "";
/// <summary>
/// 安全操作的类型
/// </summary>
public string TaskType
{
get { return taskType; }
set { taskType = value; }
}
#endregion
#region Comment
private string comment = "";
/// <summary>
/// 备注
/// </summary>
public string Comment
{
get { return comment; }
set { comment = value; }
}
#endregion
#region OccureTime
private DateTime occureTime = DateTime.Now;
/// <summary>
/// 操作发生的时间。
/// </summary>
public DateTime OccureTime
{
get { return occureTime; }
set { occureTime = value; }
}
#endregion
}
5.记录重要的业务操作
记录重要的业务操作日志也是非常重要的，比如类似某操作员修改了某个用户的权限这样关键性的操作，通过业务操作日志，当发现操作失误时，我们可以地查找到是哪个操作员在什么时间犯错而导致误操作的，这就为我们的系统安全又提供了一层监控机制。
由于业务操作类型千变万化，所以我们没有提供一个标准统一的接口来规范它，在不同的系统中，根据不同的需求，我们可能会采用不同的记录方式。当然，有些业务操作日志也许可以作为安全日志记录下来，这样就可以使用上面的ISecurityLogger接口来进行。
