開發者必知的日志記錄最佳實踐

??對程序來說，良好的日志風格能夠極大的降低排錯的成本，增強程序的健壯性與可運維性，但大多數開發同學并沒有將日志的重要性提的和代碼本身一樣高，本文討論我個人記錄日志的一些最佳實踐

基本原則

將日志作為程序的第二個UI

??軟件的第一UI當然是使用方或API調用方，而日志作為第二UI，用于開發、運維、合作方進行線上應用狀態的檢測與問題排查。日志的質量是代碼質量的一部分。

寫日志時，考慮看日志的人無法訪問代碼

??通常來說，看日志的角色不僅僅是開發代碼的人員，包括線上值班人員、售后人員、其他合作方系統的人員，可能都需要依賴日志排查問題。今天的IT系統日志更容易收集后中心化，使得不同角色可以更容易訪問日志。對于API，尤其是涉及其他多個子系統調用的復雜API，良好的日志可以為調用方、線上值班提供豐富的問題排查依據，在代碼中打印日志時要考慮無法訪問代碼的角色。

日志的主要用戶是Human，次要用戶是機器，所以可讀性很重要

??可讀性包含的內容很多，下面會解釋一些原則，但最基本的原則是縮進、空格等需要讓閱讀者易于閱讀。同時日志格式也保證易于模式化解析（簡單的字符串匹配，而不是復雜的正則）

考慮日志的目的是什么

??日志的目的不僅僅是線上Debug，也可以是記錄性能或是收集后做數據分析，考慮日志在系統的目的，寫日志時具備一定針對性。

最佳實踐

為日志添加上下文

??非常General的日志是非常糟糕的，不僅無助于定位問題，更容易造成混淆。比如下面這個日志：

2021-11-30 16:44:52,725 [WARN] Connection failed!

無法定位是哪段代碼，連接什么失敗，也不知道失敗的參數是什么，更好的日志格式如下：

2021-11-30 16:44:52,725 [WARN][C97E2488-170A-4D01-8B90-BE562FD78342] Connection to XXX Service failed with message [msg=xxx, param1=xxx, param2=xxx]

類似問題還比如:

//don't do that
java.lang.IndexOutOfBoundsException

//do that
IndexOutOfBoundsException: index 25 is greater than list size 20.

對于日志，盡量避免太general的日志，記得我們的原則，知道我們的第二個UI的目標受眾是誰，看日志的人大多數可能無法訪問代碼。

端到端的日志&并發線程日志問題

每個請求都需要有一個唯一標識符與之對應，通常是一個GUID，主要用于兩個用途

1.在不同系統或微服務間唯一標識一個請求

2.同一個應用內不同并發線程唯一標識一個請求

比如我們可以通過下面一個GUID追蹤的一個請求完整的過程

careyson@CareySonMac log % grep "C97E2488-170A-4D01-8B90-BE562FD78342" xxx.log
2021-11-30 16:44:52,725 [WARN] ModifyDBInstanceVersionImpl(46) - [C97E2488-170A-4D01-8B90-BE562FD78342,yunji-dbsingle2,ModifyDBInstanceVersion] XXX Start
2021-11-30 16:44:53,009 [WARN] ModifyDBInstanceVersionImpl(46) - [C97E2488-170A-4D01-8B90-BE562FD78342,yunji-dbsingle2,ModifyDBInstanceVersion] Begin Instance Rule Check [source version=, target version=]
2021-11-30 16:44:53,010 [WARN] ModifyDBInstanceVersionImpl(46) - [C97E2488-170A-4D01-8B90-BE562FD78342,yunji-dbsingle2,ModifyDBInstanceVersion] rule check passed. [source version=, target version=]
2021-11-30 16:44:53,011 [WARN] ModifyDBInstanceVersionImpl(46) - [C97E2488-170A-4D01-8B90-BE562FD78342,yunji-dbsingle2,ModifyDBInstanceVersion] Starting check  config
2021-11-30 16:44:53,078 [WARN] ModifyDBInstanceVersionImpl(46) - [C97E2488-170A-4D01-8B90-BE562FD78342,yunji-dbsingle2,ModifyDBInstanceVersion] Check  config Complete
2021-11-30 16:44:53,079 [WARN] ModifyDBInstanceVersionImpl(46) - [C97E2488-170A-4D01-8B90-BE562FD78342,yunji-dbsingle2,ModifyDBInstanceVersion] Starting get Source Custins info
.....

變量值與常量值分開

將變量值與常量值分開可以使得日志更容易閱讀，無論在代碼還是日志本身的搜索也會變的簡單，如果用工具抽取參數值也變的簡單，下面是一個示例:

// don't do that
ClientAgent.makeRequest()
log.info("Made request to {} on our application.", url)
 
// do that
ClientAgent.makeRequest()
log.info("Made request to XXX Service. [url={}]", url)

如果URL是一個很長的串，那么閱讀的體驗將會非常糟糕。

區分Warn與Error

日志按照嚴重性同樣也會分級，業界標準使用最多的還是Info、Warn與Error。Info通常沒什么說的，程序符合預期正常工作，在過程中記錄相關信息，就是Info，Warn和Error值得提一下。

Warn意味著程序正常工作，但存在一些問題，這種問題通常在我們預期之內。

Error意味著程序異常，且這種異常不在我們預期內。

下面是一個程序中調用其他服務的簡單例子：

try{
    ClientAgent.makeRequest()
    log.info("Made request to XXX Service. [url={}]",url)
}catch(e:RDSException){
    log.warn("Request to XXX Service was rejected because parameter beyond some business boundary [url={}, param={}, result={}]",url,result)
}catch(e:Exception){
    log.error("Request to XXX Service failed. [url={}, exception={}]",url,exception)
}

如果可能，出錯時附上KB或錯誤代號

寫程序的人通常對程序所代表的業務有一定了解，但其他日志用戶可能并沒有背景知識以及業務限制，在有限的日志中通常很難說清楚，如果有對應KB或幫助文檔，以及錯誤代號，可以附在日志中，幫助日志用戶快速了解背景。比如下面這個例子：

log.error("some error C5D1 happend due to bussiness limit, for more information, please see https://help.aliyun.com/product/26090.html")

避免記錄敏感信息

??日志并不會像數據庫那樣有高安全等級，也就是訪問日志的安全權限通常遠遠低于其他應用，且今天的日志更多是上傳后中心化，更無法控制日志的擴散范圍，因此對于敏感信息請不要記錄，包括密碼信息、Security Token信息、敏感身份信息等。

使用英文記錄日志

??英文記錄不僅僅是標準化和易于閱讀的問題，而是今天的IT系統，日志可能經過多個系統中心化，這些系統只要有一個不支持UTF格式，就可能導致亂碼，使用英文可以盡量避免這些麻煩。

小結

??對于程序來說，代碼質量除了代碼本身，還包括日志。將日志當做程序的第二UI認真對待，不僅能使得我們的程序調試與開發成本大幅下降，還能使得程序的運維排錯更加簡潔，Bug更早發現。

posted @ 2025-03-07 09:49 CareySon 閱讀(1540) 評論(2) 收藏舉報

刷新頁面返回頂部