首页 > 代码库 > 巧用CurrentThread.Name来统一标识日志记录

巧用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来统一标识日志记录