[转载]我的架构经验小结(五)-- 日志记录 – zhuweisky – 博客园.
以前写的关于架构经验方面的文章(如上一篇实战中演化的三层架构)都是从整体的角度出发的,采用全局的视角,本文我们将拉近镜头,聚焦于日志记录这一块。随着做软件的时间越长、经验积累得越来越多,就越觉得日志记录的重要。
日志记录的主要作用可以从正反两个方面来说:
(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定义:
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接口来进行。