buguge - Keep it simple,stupid

知识就是力量,但更重要的,是运用知识的能力why buguge?

导航

巧用CurrentThread.Name来唯一标记一次请求的所有日志

▄︻┻┳═一Agenda:

▄︻┻┳═一巧用CurrentThread.Name来唯一标记一次请求的所有日志

▄︻┻┳═一巧用CurrentThread.Name来唯一标记一次请求的所有日志(续)

▄︻┻┳═一巧用CurrentThread.Name来唯一标记一次请求的所有日志(完结篇)

▄︻┻┳═一asp.net拦截器

▄︻┻┳═一巧用CurrentThread.Name来唯一标记一次请求的所有日志(java-logback篇)


 

先看下面的日志:

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~ ————

发布到准生产环境,经过持续观察,发现,很多的日志都没有获取到当前线程名。很奇怪————

————两天前的夜晚打的这篇草稿该发布一下了,不能再拖延了,后续如何定位问题并解决问题,下回分解。

posted on 2017-06-29 21:58  buguge  阅读(602)  评论(0编辑  收藏  举报