Wcf通讯基础框架方案（四）——横切日志

在第一篇文章中已经列出了几种日志的概览：





所有的日志都有一个最终基类，来看看这个类：

[DataContract(Namespace = "WcfExtension")]
[KnownType(typeof(WcfExceptionInfo))]
[KnownType(typeof(ServerExceptionInfo))]
[KnownType(typeof(ClientExceptionInfo))]
[KnownType(typeof(WcfInvokeInfo))]
[KnownType(typeof(ServerInvokeInfo))]
[KnownType(typeof(ClientInvokeInfo))]
[KnownType(typeof(WcfMessageInfo))]
[KnownType(typeof(ServerMessageInfo))]
[KnownType(typeof(ClientMessageInfo))]
[KnownType(typeof(StartInfo))]
[KnownType(typeof(ServerStartInfo))]
[KnownType(typeof(ClientStartInfo))]
public abstract class AbstractLogInfo
{
[DataMember]
[PersistenceColumn(IsIndex = true)]
public string ID { get; set; }

[DataMember]
[PersistenceColumn(IsIndex = true)]
public string RequestIdentity { get; set; }

[DataMember]
[PersistenceColumn(IsIndex = true)]
public DateTime Time { get; set; }

[DataMember]
[PersistenceColumn(IsIndex = true)]
public string MachineName { get; set; }

[DataMember]
[PersistenceColumn(IsIndex = true)]
public string MachineIP { get; set; }

[DataMember]
public string ExtraInfo { get; set; }

public override string ToString()
{
StringBuilder sb = new StringBuilder();
this.GetType().GetProperties().ToList().ForEach(p =>
{
var o = p.GetValue(this, null);
sb.AppendLine(p.Name + ": " + o);
if (o is Dictionary<string, string>)
{
var dic = o as Dictionary<string, string>;
foreach (var key in dic)
{
sb.AppendLine(" " + key.Key + ": " + key.Value);
}
}

});

return sb.ToString();
}
}

值得关注的几点：

1） 这里的日志我们会保存在Mongodb中，会有一些Attribute告诉日志服务端，字段是否需要做索引，是否需要分库等等。

2） 每一条日志都会有一个GUID作为ID，这个没什么特别的。但要注意一点，如果服务端执行方法出现异常的话，会把异常ID在Message里面返回给客户端。这个异常ID也就是这条异常日志的ID。客户端只能收到有关服务端异常的Message而不会收到更多的堆栈等信息。原因两个，一减少Fault消息大小，二客户端也不应该知道这么多服务端的信息，客户端也不一定能理解服务端的异常，服务端有自己的异常日志。

3） 每一条日志都会有一个RequestIdentity，这是一个请求的上下文关联字段。从客户端发出请求开始，到服务端处理，再到客户端接收到服务端的反馈消息。其中所有的调用日志、异常日志和消息日志都会有相同的RequestIdentity。也就是说在后台通过这个RequestIdentity可以查询到一条一种类型的日志关联的整个请求过程中的其它日志。打个比方，如果在查看客户端执行日志的时候发现方法执行失败，那么直接可以查看到对应的服务端失败的那条执行日志，以及服务端对应的那个异常日志和客户端对应的异常的日志，如果开启消息日志的话，还可以查到对应的客户端和服务端收发的消息。

4） 每条日志都会有机器名和机器IP地址，以及时间。ExtraInfo存的是一些其它信息，在这里我存的是记录这个日志的方法名称。

每一种类型的日志都会有服务端日志和客户端日志两种，分别实现两个接口：

internal interface IServerInfo

{

string ServiceName { get; set; }

}

internal interface IClientInfo

{

string ClientTypeName { get; set; }

string ContractName { get; set; }

}

我认为，服务端日志需要关注服务的类型，而客户端日志关注的是契约的类型，以及调用这个契约所在的类（比如某个页面的类型名），这样可以方便定位问题。因为服务的实现位置相对固定，而调用服务接口的地方就五花八门了。

再来看看其它集中日志类型增加了哪些东西：

[DataContract(Namespace = "WcfExtension")]
public abstract class WcfExceptionInfo : AbstractLogInfo
{
[DataMember]
[PersistenceColumn(IsIndex = true)]
public string Type { get; set; }

[DataMember]
public string Message { get; set; }

[DataMember]
public string StackTrace { get; set; }
}

异常日志记录异常类型、异常消息和堆栈。

[DataContract(Namespace = "WcfExtension")]
public abstract class WcfMessageInfo : AbstractLogInfo
{
[DataMember]
public MessageDirection MessageDirection { get; set; }

[DataMember]
public string Message { get; set; }
}
}

消息日志记录完整的消息以及消息的方向。

[DataContract(Namespace = "WcfExtension")]
[KnownType(typeof(ApplicationContext))]
public abstract class WcfInvokeInfo : AbstractLogInfo
{
[DataMember]
public long ExecutionTime { get; set; }

[DataMember]
public bool IsSuccessuful { get; set; }

[DataMember]
public string MethodName { get; set; }

[DataMember]
public ApplicationContext ApplicationContext { get; set; }
}

调用消息记录方法名、执行方法是否成功、执行时间以及一些上下文信息。

最后的启动日志记录了服务端和启动和客户端第一次获取服务接口的信息：

[DataContract(Namespace = "WcfExtension")]
[KnownType(typeof(WcfService))]
public class ServerStartInfo : StartInfo , IServerInfo
{
[DataMember]
public string ServiceName { get; set; }

[DataMember]
public WcfService WcfService { get; set; }
}

[DataContract(Namespace = "WcfExtension")]
public class ClientStartInfo : StartInfo , IClientInfo
{
[DataMember]
public string ContractName { get; set; }

[DataMember]
public string ClientTypeName { get; set; }

[DataMember]
public WcfEndpoint WcfEndpoint { get; set; }
}

在上一篇文章中我们看到了，客户端的执行日志、异常日志是在ServiceRealProxy中实现的，而启动日志是在WcfServiceClientFactory中的CreateServiceClient方法实现的。那么消息日志在哪里实现的呢？

internal class ClientMessageInspector : IClientMessageInspector
{
private static Dictionary<string, string> contractVersionCache = new Dictionary<string, string>();
private static object locker = new object();

public void AfterReceiveReply(ref Message reply, object correlationState)
{
#if DEBUG
var message = reply.ToString();
Console.WriteLine("客户端收到消息：" + message);
#endif
ClientApplicationContext.Current = reply.GetApplicationContext<ClientApplicationContext>();

try
{
if (WcfLogManager.Current((correlationState as Type)).MessageInfo.Client.Enabled)
{
var direct = WcfLogManager.Current((correlationState as Type)).MessageInfo.Client.Direction;
if (direct == WcfDirection.Both ||
direct == WcfDirection.Receive)
{
var log = WcfLogProvider.GetClientMessageInfo(
(correlationState as Type).FullName,
ClientApplicationContext.Current.RequestIdentity,
"ClientMessageInspector.AfterReceiveReply",
MessageDirection.Receive,
reply.ToString());

WcfServiceLocator.GetLogService().LogWithoutException(log);
}
}
}
catch (Exception ex)
{
LocalLogService.Log(ex.ToString());
}
}

public object BeforeSendRequest(ref Message request, IClientChannel channel)
{
try
{
var channelType = channel.GetType();

var serverContext = new ServerApplicationContext();
serverContext.RequestIdentity = Guid.NewGuid().ToString();
serverContext.ClientMachineName = WcfLogProvider.MachineName;

if (!contractVersionCache.ContainsKey(channelType.FullName))
{
lock (locker)
{
if (!contractVersionCache.ContainsKey(channelType.FullName))
{
contractVersionCache.Add(channelType.FullName, channelType.Assembly.GetName().Version.ToString());
}
}
}
serverContext.ClientVersion = contractVersionCache[channelType.FullName];
request.SetApplicationContext(serverContext);

var clientContext = new ClientApplicationContext();
clientContext.RequestIdentity = serverContext.RequestIdentity;
ClientApplicationContext.Current = clientContext;
#if DEBUG
var message = request.ToString();
Console.WriteLine("客户端发出消息：" + message);
#endif

if (WcfLogManager.Current(channel.GetType()).MessageInfo.Client.Enabled)
{
var direct = WcfLogManager.Current(channel.GetType()).MessageInfo.Client.Direction;
if (direct == WcfDirection.Both
|| direct == WcfDirection.Send)
{
var log = WcfLogProvider.GetClientMessageInfo(
channelType.FullName,
ClientApplicationContext.Current.RequestIdentity,
"ClientMessageInspector.BeforeSendRequest",
MessageDirection.Send,
request.ToString());
WcfServiceLocator.GetLogService().LogWithoutException(log);
}
}

return channelType;
}
catch (Exception ex)
{
LocalLogService.Log(ex.ToString());
}
return channel.GetType();
}
}

很明显，通过IClientMessageInspector实现，Wcf的扩展可以总结为以下几个步骤：

1） 实现Wcf定义的一些接口

2） 把实现通过代码方式加入XX行为

3） 把XX行为通过代码方式或配置文件方式加入Wcf内部

那么这里的第二步实现如下：

internal class MessageInspectorEndpointBehavior : IEndpointBehavior
{
#region IEndpointBehavior Members

public void AddBindingParameters(ServiceEndpoint endpoint, BindingParameterCollection bindingParameters)
{
}

public void ApplyClientBehavior(ServiceEndpoint endpoint, ClientRuntime clientRuntime)
{
clientRuntime.MessageInspectors.Add(new ClientMessageInspector());
}

public void ApplyDispatchBehavior(ServiceEndpoint endpoint, EndpointDispatcher endpointDispatcher)
{
endpointDispatcher.DispatchRuntime.MessageInspectors.Add(new ServerMessageInspector());
}

public void Validate(ServiceEndpoint endpoint)
{
}

#endregion
}

第三步的实现之前已经看到过了，在创建信道工厂的时候直接加入进去的。再来看一下ClientMessageInspector的实现，有几个需要注意的地方：

1） 通过WcfLogManager来读取各种日志是否要记录的开关，然后通过WcfLogProvider来获取各种日志，最后通过WcfServiceLocator.GetLogService()来获取日志服务记录日志。

2） 在这里为了性能，为契约对应的版本号做了缓存。这里要说明一点，由于这些横切日志部分是贯穿框架内部的，贯穿每一次方法调用的，所以一要确保高性能，二要确保不出错，不能为了一些日志而大幅降低服务的处理性能，甚至影响正常服务的运行。

3） 通过correlationState来返回契约类型，因为在AfterReceiveReply中很难提取契约类型。

再来说说服务端的部分，服务端的方法调用日志是通过IOperationInvoker实现的，具体实现不给出了。

服务端的消息日志很明显也是通过和IClientMessageInspector对应的IDispatchMessageInspector来实现的。

最后，服务端的异常是通过IErrorHandler来实现的：

internal class ErrorHandler : IErrorHandler
{
public bool HandleError(Exception error)
{
try
{
#if DEBUG
Console.WriteLine("服务端出现异常！ Message:{0}, id : {1}", error.Message, error.Data["id"]);
#endif
if (WcfLogManager.Current().ExceptionInfo.Server.Enabled)
{
var exceptionID = error.Data["id"].ToString();

var log = WcfLogProvider.GetServerExceptionInfo("ErrorHandler.HandleErrer", error);
log.ID = exceptionID;
WcfServiceLocator.GetLogService().LogWithoutException(log);
}

}
catch (Exception ex)
{
LocalLogService.Log(ex.ToString());
}
return true;
}

public void ProvideFault(Exception error, MessageVersion version, ref Message fault)
{
try
{
var errorid = Guid.NewGuid().ToString();
error.Data.Add("id", errorid);
ServerApplicationContext.Current.ServerExceptionID = errorid;
FaultException fe = new FaultException(new FaultReason(error.Message));
MessageFault messagefault = fe.CreateMessageFault();
fault = Message.CreateMessage(version, messagefault, "http://www.5173.com");
}
catch (Exception ex)
{
LocalLogService.Log(ex.ToString());
}
}
}

这里注意两点：

1） ProvideFault的时候我们会把异常包装为一个FaultException提供给客户端。

2） 会把服务端异常的ID在消息头中传给客户端，这个异常ID就是服务端记录的异常的ID。

我们可能还注意到，客户端需要传给服务端RequestIdentity，服务端需要传给客户端异常ID，客户端需要传给服务端客户端契约的版本和客户端的机器名，而服务端也需要把自己的机器名和契约版本传给客户端。这都是通过定义上下文类，在消息头中传递进行的：

1） 在IClientMessageInspector中，发送消息之前把服务端需要的上下文准备好，加入头传过去，在收到服务端返回的消息之后建立客户端的上下文。

2） 在IDispatchMessageInspector中，和1）反过来，收到消息之后建立服务端上下文，发回复之前把客户端需要的上下文数据准备好加入头中。

通过这些丰富的日志信息，我们可以：

1） 知道服务的启动信息，知道哪些客户端使用了我们的服务端

2） 知道客户端调用的信息，知道服务端执行方法的信息，知道两端的版本是否匹配，可以统计客户端和服务端的机器，知道方法的执行时间

3） 客户端通过异常可以关联服务端异常，服务端异常记录了详细的出错堆栈

4） 如果需要进一步跟踪问题可以开启消息记录（消耗一定的性能）

5） 通过上下文把客户端和服务端的调用变为一个整体

6） 由于都记录了机器名或IP地址，可以统计出有性能问题的机器，遇到问题也可以马上定位出错的机器，便于负载均衡环境定位问题

对于分布式的服务来说，服务端可能又会是其他服务的客户端，错综复杂，横切关注点尤其重要，因为这个框架很大一部分在实现这个。

当然，日志仅仅是存下来还不够，还需要有一个强大的查看以及统计后台，用于定位问题发现问题。