天天看點

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位址,可以統計出有性能問題的機器,遇到問題也可以馬上定位出錯的機器,便于負載均衡環境定位問題

對于分布式的服務來說,服務端可能又會是其他服務的用戶端,錯綜複雜,橫切關注點尤其重要,因為這個架構很大一部分在實作這個。

當然,日志僅僅是存下來還不夠,還需要有一個強大的檢視以及統計背景,用于定位問題發現問題。

作者:

lovecindywang

本文版權歸作者和部落格園共有,歡迎轉載,但未經作者同意必須保留此段聲明,且在文章頁面明顯位置給出原文連接配接,否則保留追究法律責任的權利。