巧用CurrentThread.Name来统一标识日志记录

Posted 2020-09-26 buguge

▄︻┻┳═一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~ ————

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

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