[[385165]]

【51CTO.com原創(chuàng)稿件】前言

寫(xiě)代碼的人就沒(méi)有不寫(xiě)日志的，但我們到底該怎么打印日志，打印日志能不能有點(diǎn)章法?

針對(duì)這個(gè)問(wèn)題，我查閱了《阿里巴巴Java開(kāi)發(fā)手冊(cè)》，里面有 8 條日志規(guī)約。比如不同作用的日志存放到不同的日志文件里，以 appName_logType_logName.log 方式進(jìn)行命名。是挺不錯(cuò)，但屬于是日志分類(lèi)的問(wèn)題，依舊解決不了程序員如何有章法的在代碼中書(shū)寫(xiě)日志的問(wèn)題。

探尋

先來(lái)看一個(gè)比較常見(jiàn)的日志打印示例：

log.info("開(kāi)始執(zhí)行業(yè)務(wù)邏輯 ----------------->{}",param); 
log.info("業(yè)務(wù)邏輯執(zhí)行中 ----------------->{}",param); 
log.info("結(jié)束執(zhí)行業(yè)務(wù)邏輯 ----------------->{}",param); 
log.error("業(yè)務(wù)執(zhí)行異常 ----------------->{}",param, e); 

這種日志打印有什么問(wèn)題？

第一、沒(méi)有綁定事件

在執(zhí)行什么業(yè)務(wù)邏輯呢？沒(méi)有一個(gè)明確的事件，或者說(shuō)是名字、歸類(lèi)，我更愿稱(chēng)之為事件。我們搜索日志時(shí)，是要有一個(gè)主語(yǔ)的，如果在日志打印中加入事件，我們搜索日志時(shí)，只需要輸入關(guān)鍵字即可獲取該事件的所有日志。改進(jìn)后的⽇志打?。?/p>

log.info("{}|開(kāi)始執(zhí)行業(yè)務(wù)邏輯 ----------------->{}",EVENT_NAME, param); 
log.info("{}|業(yè)務(wù)邏輯執(zhí)行中 ----------------->{}",EVENT_NAME, param); 
log.info("{}|結(jié)束執(zhí)行業(yè)務(wù)邏輯 ----------------->{}",EVENT_NAME, param); 
log.error("{}|業(yè)務(wù)執(zhí)行異常 ----------------->{}",EVENT_NAME, param, e); 

第二、沒(méi)有綁定主鍵

一個(gè)事件下的日志無(wú)時(shí)無(wú)刻不在產(chǎn)生，而發(fā)生問(wèn)題時(shí)，往往只會(huì)給你一個(gè) case 進(jìn)行診斷，所以，我們除了記錄事件，還需要記錄主鍵，通過(guò)觀察這個(gè)主鍵在執(zhí)行過(guò)程中都產(chǎn)生了哪些日志來(lái)定位問(wèn)題。改進(jìn)后的日志打?。?/p>

log.info("{}|ID={}|開(kāi)始執(zhí)行業(yè)務(wù)邏輯 ----------------->{}",EVENT_NAME, ID, param); 
log.info("{}|ID={}|業(yè)務(wù)邏輯執(zhí)行中 ----------------->{}",EVENT_NAME, ID, param); 
log.info("{}|ID={}|結(jié)束執(zhí)行業(yè)務(wù)邏輯 ----------------->{}",EVENT_NAME, ID, param); 
log.error("{}|ID={}|業(yè)務(wù)執(zhí)行異常 ----------------->{}",EVENT_NAME, ID, param, e); 

第三、沒(méi)有綁定請(qǐng)求

有了事件，有了主鍵，但是在查詢?nèi)罩镜倪^(guò)程中，發(fā)現(xiàn)該主鍵產(chǎn)生了許多重復(fù)日志，日志的上下文不連貫，我們想看某一次請(qǐng)求產(chǎn)生的連續(xù)日志就非常不方便，這時(shí)候就需要考慮并發(fā)的情況。改進(jìn)后的日志打?。?/p>

// 可以使用 UUID 生成ReqId 
// final String ReqId = UUID.randomUUID().toString(); 
log.info("{}|ReqId={}|ID={}|開(kāi)始執(zhí)行業(yè)務(wù)邏輯 ----------------->{}",EVENT_NAME, ReqId, ID, param); 
log.info("{}|ReqId={}|ID={}|業(yè)務(wù)邏輯執(zhí)行中 ----------------->{}",EVENT_NAME, ReqId, ID, param); 
log.info("{}|ReqId={}|ID={}|結(jié)束執(zhí)行業(yè)務(wù)邏輯 ----------------->{}",EVENT_NAME, ReqId, ID, param); 
log.error("{}|ReqId={}|ID={}|業(yè)務(wù)執(zhí)行異常 ----------------->{}",EVENT_NAME, ReqId, ID, param, e); 

第四、沒(méi)有綁定分詞符

不要在日志打印時(shí)使用 --- 這種分隔符，沒(méi)意義、不標(biāo)準(zhǔn)，非常不好做分詞。一定要將不變的文字說(shuō)明和變化的參數(shù)用分詞符分開(kāi)打印，因?yàn)椴蛔兊奈淖终f(shuō)明也是可以成為關(guān)鍵詞進(jìn)行搜索的。改進(jìn)后的日志打?。?/p>

log.info("{}|ReqId={}|ID={}|開(kāi)始執(zhí)行業(yè)務(wù)邏輯|參數(shù)={}",EVENT_NAME, ReqId, ID, param); 
log.info("{}|ReqId={}|ID={}|業(yè)務(wù)邏輯執(zhí)行中|參數(shù)={}",EVENT_NAME, ReqId, ID, param); 
log.info("{}|ReqId={}|ID={}|結(jié)束執(zhí)行業(yè)務(wù)邏輯|參數(shù)={}",EVENT_NAME, ReqId, ID, param); 
log.error("{}|ReqId={}|ID={}|業(yè)務(wù)執(zhí)行異常|參數(shù)={}",EVENT_NAME, ReqId, ID, param, e); 

第五、錯(cuò)誤日志需要輸出異常信息

對(duì)于異常日志的打印一定要帶上堆棧信息，異常堆棧不能使用 e.printStackTrace() 輸出到控制臺(tái)，這樣異常堆棧是寫(xiě)入不了日志文件的，需要將異常對(duì)象寫(xiě)進(jìn)最后的參數(shù)里，這點(diǎn)相信大家都懂。

除此之外，還需要將異常信息的 toString() 內(nèi)容打印進(jìn)同一行日志里。因?yàn)楫惓６褩６际橇砥鹨恍校瑢?duì)于一些單行日志記錄的系統(tǒng)，比如阿里云sls，根本看不到異常信息，還得爬進(jìn)服務(wù)器找日志堆棧。所以，還是很有必要將 e.toString() 寫(xiě)進(jìn)參數(shù)里的，有些異常只看 e.toString() 的內(nèi)容就可以定位了。為什么我這里要求使用 e.toString() 而不是 e.getMessage() ?因?yàn)槿绻荖ullPointerException異常， e.getMessage() 返回空。改進(jìn)后的代碼：

log.error("{}|ReqId={}|ID={}|業(yè)務(wù)執(zhí)行異常|參數(shù)={}|e={}",EVENT_NAME, ReqId, ID, param, e.toString(), e); 

第六、若有循環(huán)，需要綁定循環(huán)主鍵

將上面例子加個(gè)業(yè)務(wù)上的循環(huán)，再來(lái)看下代碼：

log.info("{}|ReqId={}|ID={}|開(kāi)始執(zhí)行業(yè)務(wù)邏輯|參數(shù)={}",EVENT_NAME, ReqId, ID, param); 
for (Key key : KeyList) { 
log.info("{}|ReqId={}|ID={}|業(yè)務(wù)邏輯執(zhí)行中|參數(shù)={}",EVENT_NAME, ReqId, ID, param); 
} 
log.info("{}|ReqId={}|ID={}|結(jié)束執(zhí)行業(yè)務(wù)邏輯|參數(shù)={}",EVENT_NAME, ReqId, ID, param); 

這樣產(chǎn)生的日志，非常不方便定位到具體的某次循環(huán)。如果循環(huán)體內(nèi)出了異常，也不清楚具體是哪個(gè)Key 引發(fā)的。所以，遇到業(yè)務(wù)邏輯位于循環(huán)內(nèi)的代碼，應(yīng)該打印出每次處理的 Key。改進(jìn)后的代碼：

log.info("{}|ReqId={}|ID={}|開(kāi)始執(zhí)行業(yè)務(wù)邏輯|參數(shù)={}",EVENT_NAME, ReqId, ID, param); 
for (Key key : KeyList) { 
log.info("{}|ReqId={}|ID={}|Key={}|業(yè)務(wù)邏輯執(zhí)行中|參數(shù)={}",EVENT_NAME, ReqId, ID, key, param); 
} 
log.info("{}|ReqId={}|ID={}|結(jié)束執(zhí)行業(yè)務(wù)邏輯|參數(shù)={}",EVENT_NAME, ReqId, ID, param); 

公式

經(jīng)過(guò)上面的分析之后，我們可以總結(jié)出日志打印的公式：

EVENT_NAME={}|ReqId={}|Key={}|childKey={}|doing something|result={} 

如果沒(méi)有過(guò)程的話，ReqId 是可以省略的，Key 的數(shù)量也不一定只是一個(gè)，你也可以看情況給日志加一列 [start|end] ，表示業(yè)務(wù)過(guò)程的開(kāi)始和結(jié)束。

JSON日志

之前有段時(shí)間寫(xiě)過(guò) JSON 格式的日志，就是每一個(gè)行日志都是一個(gè) JSON 串，上面講到的日志可以稱(chēng)為單行日志。

舉個(gè)例子：

Map<String, Object> logMap = new HashMap<>(); 
try{ 
logMap.put("EVENT_NAME", "monitor"); 
// .... 
}finally { 
LogUtil.save(JSON.toJSONString(logMap)); 
} 

輸出日志(為了方便查看，我已格式化)：

{ 
"EVENT_NAME": "monitor", 
"ReqId": "654321", 
"ID": "123456", 
"success": true, 
"param": { 
"name": "zs", 
"age": 14 
 } 
} 

JSON 日志天然綁定了請(qǐng)求過(guò)程，它最大的優(yōu)勢(shì)是輸出序列化好的 JSON 串，非常方便離線對(duì)其各種操作。但對(duì)比于單行日志，代碼嵌入性太高，需要通過(guò) try..finally 代碼塊進(jìn)行捕捉。

主⻚：https://github.com/onblog

PS：以前我喜歡用 JSON 日志，現(xiàn)在我更喜歡用單行日志

【51CTO原創(chuàng)稿件，合作站點(diǎn)轉(zhuǎn)載請(qǐng)注明原文作者和出處為51CTO.com】