巧用CurrentThread.Name來統一標識日誌記錄
先看下面的日誌：
2017/5/21 18:00:01 [OrderQuery_180001914_C72FF]請求支付中心參數：{"order_no":"KB201705210000165","sign":"e6c3559cd4b36458b180f15bfcd9b5a5"} 2017/5/21 18:00:01 [OrderQuery_180001914_C72FF]支付中心驗簽通過。 2017/5/21 18:00:01 [OrderQuery_180001914_C72FF]進入統一訂單查詢服務類... 2017/5/21 18:00:02 [OrderQuery_180001914_C72FF]支付中心支付結果是NotPay，接下來直接從上遊渠道[QingdaoCITIC]查 2017/5/21 18:00:02 [180002CITIC648]請求報文：<xml><mch_id><![CDATA[102540884712]]></mch_id><nonce_str>......<sign><![CDATA[***]]></sign></xml> 2017/5/21 18:00:02 [OrderQuery_180002492_C6E22]請求支付中心參數：{"order_no":"KB201705210000157","sign":"472086c6ec01fa1360e779c2517389bc"} 2017/5/21 18:00:02 [JSPay_102157155_D0F3F]請求支付中心參數：{"order_no":"20170623Test7715",... ...,"merchant_id":"m20170613000000973"} 2017/5/21 18:00:02 [JSPay_102157155_D0F3F]支付中心驗簽通過。 2017/5/21 18:00:02 [180002CITIC648]響應報文：<xml><appid><![CDATA[wx290ce4878c943699]]></appid> <charset><![CDATA[UTF-8]]></charset> <mch_id><![CDATA[102540884712]]></mch_id> <nonce_str><![CDATA[DF44F363-BA23-443B-97DF-73D2DA72]]></nonce_str> <result_code><![CDATA[0]]></result_code> <sign><![CDATA[***]]></sign> <sign_type><![CDATA[MD5]]></sign_type> <status><![CDATA[0]]></status> <trade_state><![CDATA[NOTPAY]]></trade_state> <trade_state_desc><![CDATA[訂單未支付]]></trade_state_desc> <version><![CDATA[2.0]]></version> </xml> 2017/5/21 18:00:02 [OrderQuery_180001914_C72FF]渠道處理結果：{"pay_status":5,"pay_status_notmatched":"NOTPAY","pay_money":0.0,"ThirdPayNo":null,"StatusIsSuccess":true,"ReturnCodeIsSuccess":true,......} 2017/5/21 18:00:02 [OrderQuery_180001914_C72FF]訂單支付結果更新完成。 2017/5/21 18:00:02 [JSPay_102157155_D0F3F]支付中心響應結果:{"pay_url":"http://***.com/QRCode/JSPayPage.ashx?tokenId=***","status":"SUCCESS","return_code":"0","return_time":"20170623102157","sign":...} 2017/5/21 18:00:03 [OrderQuery_180001914_C72FF]支付中心響應結果:{"order_no":"KB201705210000165","pay_status":"5","status":"SUCCESS","return_code":"0","return_message":"未支付","return_time":"20170521180002","sign":...}
即，應用程序對每一次請求的處理過程所記錄的日誌統一打了一個標識。 這樣，在系統運維過程中進行排障時，尤其在並發請求的情況下，即使日誌記錄得你中有我我中有你，也很容易就可以查到處理某次請求的來龍去脈，進而幫助我們快速定位原因。
的確是這樣的，我對這種日誌記錄實現方式屢試不爽。
我這個項目是一個webapi站點，提供支付接口，供下遊系統調用。
本文要說的是我是如何實現這種統一標識日誌記錄的。
最初的方式，也是多數程序員可以想到的常規的實現方式，是每次請求的最開始處定義一個LogFlag，日誌helper類裏在持久化日誌時把加上這個LogFlag。 由於程序是分層的，比如web入口層、通信服務層、bll層、渠道通信層。那麽，就需要逐層傳遞這個LogFlag。為此我用到了兩種實現方式，一是靠構造器傳參，一是定義public屬性。
/* 通過構造器傳參來傳遞LogFlag */ public class QRCodeService { private readonly LogHelperUtil _logHelperUtil; public QRCodeService(string logFlag) { _logHelperUtil = new LogHelperUtil(logFlag); } ... ... }
/* 通過封裝屬性來傳遞LogFlag */ public interface IThirdPay { string LogFlag { set; get; } ... ... }
程序裏本身已經有LogHelper.cs類，為了實現這種統一標識日誌的方式，避免修改原LogHelper類代碼，我重新定義了一個代理類LogHelperUtil.cs：
public class LogHelperUtil { private readonly string _LOG_FLAG; public string LOG_FLAG { get { return _LOG_FLAG; } } public LogHelperUtil(string log_flag) { _LOG_FLAG = log_flag; if (string.IsNullOrEmpty(_LOG_FLAG)) _LOG_FLAG = string.Format("[{0}LOG{1}]", DateTime.Now.ToString("HHmmssfff"), new Random().Next(9999)); } public void WriteLog(string format, params object[] args) { LogHelper.Write(_LOG_FLAG + format, args); } }
WebApi接口層用的Asp.Net框架，每個對外接口都是一個一般處理程序文件（.ashx）。我為這每個一般處理程序的類抽象出一個基類，封裝了標準的處理請求的邏輯，並定義了抽象方法MyBiz(string requestJson)。每個子類職責單一，只需關註獲取並返回自己本身的處理結果數據。
public abstract class HandlerBase : IHttpHandler { protected readonly LogHelperUtil _logHelperUtil; public HandlerBase() { string logFlag = string.Format("[{0}_{1:HHmmssfff}_{2}]", this.GetType().Name, DateTime.Now, Guid.NewGuid().ToString().Replace("-", "").Substring(0, 5).ToUpper()); _logHelperUtil = new LogHelperUtil(logFlag); } public bool IsReusable { get { return false; } } public void ProcessRequest(HttpContext context) { context.Response.ContentType = "application/json"; Stopwatch watch = new Stopwatch(); string requestJson = string.Empty; watch.Start(); try { using (var stream = new StreamReader(context.Request.InputStream)) { requestJson = stream.ReadToEnd(); if (string.IsNullOrEmpty(requestJson)) { throw new ResponseErrorException("請求支付中心參數為空"); } _logHelperUtil.WriteLog("請求支付中心參數：{0}", requestJson); //偽代碼：驗簽 ResponseModelBase responseModel = MyBiz(requestJson); _logHelperUtil.WriteLog("支付中心響應結果:{0}", JsonConvert.SerializeObject(responseModel)); context.Response.Write(JsonConvert.SerializeObject(responseModel)); watch.Stop(); //偽代碼：記錄本次請求的duration } } catch (Exception ex) { if (ex is ResponseErrorException) { _logHelperUtil.WriteLog(ex.Message); } else { _logHelperUtil.WriteLog("系統異常:{0}", ex.ToString()); } var responseModel = new ResponseModelBase { status = PayResponseConstant.Failed, return_code = "1", return_message = ex.Message, }; context.Response.Write(JsonConvert.SerializeObject(responseModel)); watch.Stop(); //偽代碼：記錄本次請求的duration } } protected abstract ResponseModelBase MyBiz(string requestJson); }
接下來說子類，即每個一般處理程序的.cs類的邏輯，職責當然就是重寫MyBiz了，如下：
上面所引用的QRCodeService類的構造器提供了logFlag參數，從而把這個LogFlag傳遞到Service層。 當然，我上文說的，另一種方式是借助屬性來實現這個LogFlag的傳遞，我上一篇博客《多類繼承情況下適應變化設計一例》裏也有談及LogFlag這方面的重構。
這樣編碼後，就實現了統一標識日誌記錄了。
我們每個人的認知都有他的局限性，在一次跟java組的雲龍溝通中，我向他展示日誌文件裏井然有序的日誌，他跟我說用線程號就可以實現，log4j裏設置一下就實現了。 他這麽一說線程，可以說是醍醐灌頂。於是，我也要利用Thread.CurrentThread.Name來實現。
我大概的盤算了一下，要改用當前線程Name的方式的話，可以說web層、service層、渠道通信層裏的每個類文件都要做變動。 我是喜歡接受這樣重構挑戰的，所以，在完成工作既定任務後，我終於鼓足勇氣來做這次比較大的重構。 去掉構造器裏的logFlag參數，不用的LogFlag屬性也去掉。這樣地給程序做了一次大的瘦身，代碼整潔了不少。
web層一般處理程序的基類HandlerBase.cs調整如下：
public abstract class HandlerBase : IHttpHandler { protected readonly LogHelperUtil _LogHelperUtil; public HandlerBase() { Thread.CurrentThread.Name = string.Format("[{0}_{1:HHmmssfff}_{2}]", this.GetType().Name, DateTime.Now, Guid.NewGuid().ToString().Replace("-", "").Substring(0, 5).ToUpper()); _LogHelperUtil = new LogHelperUtil(); } ... ... }
LogHelperUtil的變化不大，一是去掉了LOG_FLAG屬性，一是取消了給字段_LOG_FLAG賦默認值，一是——最重要的——在記日誌時加上當前線程名：
public class LogHelperUtil { private readonly string _LOG_FLAG; //public string LOG_FLAG { get { return _LOG_FLAG; } } public LogHelperUtil(string log_flag = "") { _LOG_FLAG = log_flag; //if (string.IsNullOrEmpty(_LOG_FLAG)) // _LOG_FLAG = string.Format("[{0}LOG{1}]", DateTime.Now.ToString("HHmmssfff"), new Random().Next(9999)); } public void WriteLog(string format, params object[] args) { LogHelper.Write(System.Threading.Thread.CurrentThread.Name + _LOG_FLAG + format, args); } }
然而，要出事的節奏O(∩_∩)O~ O(∩_∩)O~ O(∩_∩)O~ ————
發布到準生產環境，經過持續觀察，發現，很多的日誌都沒有獲取到當前線程名。很奇怪————
————兩天前的夜晚打的這篇草稿該發布一下了，不能再拖延了，後續如何定位問題並解決問題，下回分解。
巧用CurrentThread.Name來統一標識日誌記錄