[[385165]]

【51CTO.com原創稿件】前言

寫代碼的人就沒有不寫日志的，但我們到底該怎么打印日志，打印日志能不能有點章法?

針對這個問題，我查閱了《阿里巴巴Java開發手冊》，里面有 8 條日志規約。比如不同作用的日志存放到不同的日志文件里，以 appName_logType_logName.log 方式進行命名。是挺不錯，但屬于是日志分類的問題，依舊解決不了程序員如何有章法的在代碼中書寫日志的問題。

探尋

先來看一個比較常見的日志打印示例：

log.info("開始執行業務邏輯 ----------------->{}",param); 
log.info("業務邏輯執行中 ----------------->{}",param); 
log.info("結束執行業務邏輯 ----------------->{}",param); 
log.error("業務執行異常 ----------------->{}",param, e); 

這種日志打印有什么問題？

第一、沒有綁定事件

在執行什么業務邏輯呢？沒有一個明確的事件，或者說是名字、歸類，我更愿稱之為事件。我們搜索日志時，是要有一個主語的，如果在日志打印中加入事件，我們搜索日志時，只需要輸入關鍵字即可獲取該事件的所有日志。改進后的⽇志打印：

log.info("{}|開始執行業務邏輯 ----------------->{}",EVENT_NAME, param); 
log.info("{}|業務邏輯執行中 ----------------->{}",EVENT_NAME, param); 
log.info("{}|結束執行業務邏輯 ----------------->{}",EVENT_NAME, param); 
log.error("{}|業務執行異常 ----------------->{}",EVENT_NAME, param, e); 

第二、沒有綁定主鍵

一個事件下的日志無時無刻不在產生，而發生問題時，往往只會給你一個 case 進行診斷，所以，我們除了記錄事件，還需要記錄主鍵，通過觀察這個主鍵在執行過程中都產生了哪些日志來定位問題。改進后的日志打印：

log.info("{}|ID={}|開始執行業務邏輯 ----------------->{}",EVENT_NAME, ID, param); 
log.info("{}|ID={}|業務邏輯執行中 ----------------->{}",EVENT_NAME, ID, param); 
log.info("{}|ID={}|結束執行業務邏輯 ----------------->{}",EVENT_NAME, ID, param); 
log.error("{}|ID={}|業務執行異常 ----------------->{}",EVENT_NAME, ID, param, e); 

第三、沒有綁定請求

有了事件，有了主鍵，但是在查詢日志的過程中，發現該主鍵產生了許多重復日志，日志的上下文不連貫，我們想看某一次請求產生的連續日志就非常不方便，這時候就需要考慮并發的情況。改進后的日志打印：

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

第四、沒有綁定分詞符

不要在日志打印時使用 --- 這種分隔符，沒意義、不標準，非常不好做分詞。一定要將不變的文字說明和變化的參數用分詞符分開打印，因為不變的文字說明也是可以成為關鍵詞進行搜索的。改進后的日志打印：

log.info("{}|ReqId={}|ID={}|開始執行業務邏輯|參數={}",EVENT_NAME, ReqId, ID, param); 
log.info("{}|ReqId={}|ID={}|業務邏輯執行中|參數={}",EVENT_NAME, ReqId, ID, param); 
log.info("{}|ReqId={}|ID={}|結束執行業務邏輯|參數={}",EVENT_NAME, ReqId, ID, param); 
log.error("{}|ReqId={}|ID={}|業務執行異常|參數={}",EVENT_NAME, ReqId, ID, param, e); 

第五、錯誤日志需要輸出異常信息

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

除此之外，還需要將異常信息的 toString() 內容打印進同一行日志里。因為異常堆棧都是另起一行，對于一些單行日志記錄的系統，比如阿里云sls，根本看不到異常信息，還得爬進服務器找日志堆棧。所以，還是很有必要將 e.toString() 寫進參數里的，有些異常只看 e.toString() 的內容就可以定位了。為什么我這里要求使用 e.toString() 而不是 e.getMessage() ?因為如果是NullPointerException異常， e.getMessage() 返回空。改進后的代碼：

log.error("{}|ReqId={}|ID={}|業務執行異常|參數={}|e={}",EVENT_NAME, ReqId, ID, param, e.toString(), e); 

第六、若有循環，需要綁定循環主鍵

將上面例子加個業務上的循環，再來看下代碼：

log.info("{}|ReqId={}|ID={}|開始執行業務邏輯|參數={}",EVENT_NAME, ReqId, ID, param); 
for (Key key : KeyList) { 
log.info("{}|ReqId={}|ID={}|業務邏輯執行中|參數={}",EVENT_NAME, ReqId, ID, param); 
} 
log.info("{}|ReqId={}|ID={}|結束執行業務邏輯|參數={}",EVENT_NAME, ReqId, ID, param); 

這樣產生的日志，非常不方便定位到具體的某次循環。如果循環體內出了異常，也不清楚具體是哪個Key 引發的。所以，遇到業務邏輯位于循環內的代碼，應該打印出每次處理的 Key。改進后的代碼：

log.info("{}|ReqId={}|ID={}|開始執行業務邏輯|參數={}",EVENT_NAME, ReqId, ID, param); 
for (Key key : KeyList) { 
log.info("{}|ReqId={}|ID={}|Key={}|業務邏輯執行中|參數={}",EVENT_NAME, ReqId, ID, key, param); 
} 
log.info("{}|ReqId={}|ID={}|結束執行業務邏輯|參數={}",EVENT_NAME, ReqId, ID, param); 

公式

經過上面的分析之后，我們可以總結出日志打印的公式：

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

如果沒有過程的話，ReqId 是可以省略的，Key 的數量也不一定只是一個，你也可以看情況給日志加一列 [start|end] ，表示業務過程的開始和結束。

JSON日志

之前有段時間寫過 JSON 格式的日志，就是每一個行日志都是一個 JSON 串，上面講到的日志可以稱為單行日志。

舉個例子：

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 日志天然綁定了請求過程，它最大的優勢是輸出序列化好的 JSON 串，非常方便離線對其各種操作。但對比于單行日志，代碼嵌入性太高，需要通過 try..finally 代碼塊進行捕捉。

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

PS：以前我喜歡用 JSON 日志，現在我更喜歡用單行日志

【51CTO原創稿件，合作站點轉載請注明原文作者和出處為51CTO.com】