巧用CurrentThread.Name來統一標識日志記錄（java-logback篇）

                            _       
                           | |      
  __ _  __ _  ___ _ __   __| | __ _ 
 / _` |/ _` |/ _ \ '_ \ / _` |/ _` |
| (_| | (_| |  __/ | | | (_| | (_| |
 \__,_|\__, |\___|_| |_|\__,_|\__,_|
        __/ |                       
       |___/                        

▄︻┻┳═一巧用CurrentThread.Name來統一標識日志記錄

▄︻┻┳═一巧用CurrentThread.Name來統一標識日志記錄（續）

▄︻┻┳═一巧用CurrentThread.Name來統一標識日志記錄（完結篇）

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

▄︻┻┳═一巧用CurrentThread.Name來統一標識日志記錄（java-logback篇）

---

 

java版本支付中心，日志組件使用的是logback。logback.xml里日志pattern配置如下：

    <!--本地日志目錄-->
    <property name="USER_HOME" value="${catalina.base}/logs/logback-srv" />
    <property name="LOG_MSG" value="%X{sid}%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5p [%c] - %m%n" />
    <property name="LOG_DIR" value="${USER_HOME}/%d{yyyyMMdd}"/>
    <!--2017-08-22 10:43:19.307 [DubboServerHandler-10.0.0.178:38001-thread-187] INFO  [com.emax.paycenter.backend.facade.IPayCenterFacadeImpl]-->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${LOG_MSG}</pattern>
        </encoder>
    </appender>

 

pattern里有%t，即代表的是線程Id（起初，我誤認為這個%t指的是線程Id！！！），而每一筆交易請求的處理是在一個單獨的線程里，那么它就可以標記每一筆交易請求對應的所有日志。日志文件截圖如下：

分析日志發現，這個線程標識如截圖里的“DubboServerHandler-10.0.0.178:38001-thread-195”會被不同的交易請求重用，不能唯一標記一次請求的所有處理日志，這顯然加大了線上問題的排障難度。昨天晚上，項目組里我們2人決定要針對這一點不足做一次改進。

之前的.net版支付中心，我對統一標記一筆交易請求的所有日志做過一次重構，見【巧用CurrentThread.Name來統一標識日志記錄】。顯然，java的也有必要用一個唯一的標識來標記一筆交易請求的所有日志。

當前線程的線程Id是只讀的，我們改不了。那該怎么實現呢？
此前.net的經驗告訴我用currentThread的Name屬性來搞。可是問題來了，我在交易處理的第一個語句里給當前線程名賦值后，此后的各module各方法里的每一條log.info語句都要顯式記錄上當前線程名，改動太多了。而且，這樣的代碼不免有股怪怪的味道。
當然，另一個辦法是按照.net版那種思路，做個日志代理類，對上面的調用log.info並顯式記錄當前線程名做個封裝，然后，邏輯代碼里記日志就調用這個代理類。這樣實現的弊端與上面的方案半斤八兩。

那怎么辦呢？

問唄。
先問度娘，無解。
接着問同事，說可能要自己寫一個apperder。對logback底層代碼的未知會加大解決問題的難度。
【百度：logback 自定義appender
讀logback源碼系列文章（五）——Appender http://kyfxbl.iteye.com/blog/1173788】

無心插柳

我早上上班后，先了解了一下構造一個唯一字符串標識來給當前線程名賦值。然后在交易處理的的第一個語句前，寫了如下兩行代碼，

public BaseResponse invoke(String requestJSON, BaseRequest baseRequest) throws Exception {
        String threadName = String.format("%s_%s_%s", baseRequest.getMethod(), new SimpleDateFormat("HHmmssS").format(new Date()), UUID.randomUUID().toString().toUpperCase().substring(0, 5)); Thread.currentThread().setName(threadName);

        log.info("#IPayCenterFacadeImpl,調用服務：{}", baseRequest.getMethod());
        log.info("#IPayCenterFacadeImpl,請求參數：{}", requestJSON);
        //1.獲取API接口實現
        IPayCenterApi payCenterApi = (IPayCenterApi) payCenterServiceFactory.getService(baseRequest.getMethod());

        //2.處理業務邏輯
        BaseResponse result = payCenterApi.handle(requestJSON);

        return result;
    }

 

不經意間，在運行代碼時，我發現%t那段的線程信息標識是我給當前線程名設置的那個字符串標識。
這才發現，%t或%thread輸出的原來是產生日志的線程名！！

【調試代碼可知 Thread.currentThread().getName():DubboServerHandler-192.168.40.80:28005-thread-2，Thread.currentThread().getId():246】

經過了這個波折，我們的問題最終得到解決，興奮異常。看看下面的日志截圖，一股強烈的成就感油然而生 O(∩_∩)O