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指的是線程IdI缆亍!V嘈)瞄崇,而每一筆交易請求的處理是在一個單獨的線程里,那么它就可以標記每一筆交易請求對應的所有日志尚猿。日志文件截圖如下:
分析日志發(fā)現(xiàn)凿掂,這個線程標識如截圖里的“DubboServerHandler-10.0.0.178:38001-thread-195”會被不同的交易請求重用纹蝴,不能唯一標記一個線程處理,這顯然加大了線上問題的排障難度糠涛。昨天晚上兼犯,項目組里我們2人決定要針對這一點不足做一次改進集漾。
之前的.net版支付中心砸脊,我對統(tǒng)一標記一筆交易請求的所有日志做過一次重構(gòu),見《巧用CurrentThread.Name來統(tǒng)一標識日志記錄》凌埂。顯然瞳抓,java的也有必要用一個唯一的標識來標記一筆交易請求的所有日志。
當前線程的線程Id是只讀的栓霜,我們改不了横蜒。那該怎么實現(xiàn)呢?
經(jīng)驗告訴我用currentThread的Name屬性來搞∫鹇遥可是問題來了孟岛,我在交易處理的第一個語句里給當前線程名賦值后,此后的各module各方法里的每一條log.info語句都要顯式記錄上當前線程名斤贰,改動太多了次询。而且,這樣的代碼不免有股怪怪的味道屯吊。
當然送巡,另一個辦法是按照.net版那種思路,做個日志代理類盒卸,對上面的調(diào)用log.info并顯式記錄當前線程名做個封裝骗爆,然后,邏輯代碼里記日志就調(diào)用這個代理類蔽介。這樣實現(xiàn)的弊端與上面的方案半斤八兩摘投。
那怎么辦呢煮寡?
問唄。
先問度娘犀呼,無解幸撕。
接著問同事,說要自己寫一個apperder圆凰。對logback底層代碼的未知會加大解決問題的難度。
【百度:logback 自定義appender
讀logback源碼系列文章(五)——Appender http://kyfxbl.iteye.com/blog/1173788】
無心插柳
我早上上班后专钉,先了解了一下構(gòu)造一個唯一字符串標識來給當前線程名賦值挑童。然后在交易處理的的第一個語句前,寫了如下兩行代碼跃须,
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,調(diào)用服務:{}", baseRequest.getMethod());
log.info("#IPayCenterFacadeImpl,請求參數(shù):{}", requestJSON);
//1.獲取API接口實現(xiàn)
IPayCenterApi payCenterApi = (IPayCenterApi) payCenterServiceFactory.getService(baseRequest.getMethod());
//2.處理業(yè)務邏輯
BaseResponse result = payCenterApi.handle(requestJSON);
return result;
}
不經(jīng)意間站叼,在運行代碼時,我發(fā)現(xiàn)%t那段的線程信息標識是我給當前線程名設置的那個字符串標識菇民。
這才發(fā)現(xiàn)尽楔,%t或%thread輸出的原來是產(chǎn)生日志的線程名!第练!
【調(diào)試代碼可知 Thread.currentThread().getName():DubboServerHandler-192.168.40.80:28005-thread-2阔馋,Thread.currentThread().getId():246】
經(jīng)過了這個波折,我們的問題最終得到解決娇掏,興奮異常呕寝。看看下面的日志截圖婴梧,一股強烈的成就感油然而生 O(∩_∩)O