如何使錯誤日志更加方便排查問題
不點(diǎn)藍(lán)字，我們哪來故事？
每天 11 點(diǎn)更新文章，餓了點(diǎn)外賣，點(diǎn)擊 ??《無門檻外賣優(yōu)惠券，每天免費(fèi)領(lǐng)！》
作者 | 琴水玉
錯誤是如何煉成的
對于當(dāng)前系統(tǒng)來說， 錯誤的產(chǎn)生由三個地方引入：
1.上層系統(tǒng)引入的非法參數(shù)。對于非法參數(shù)引入的錯誤， 可以通過參數(shù)校驗(yàn)和前置條件校驗(yàn)來截獲錯誤；
2.與下層系統(tǒng)交互產(chǎn)生的錯誤。與下層交互產(chǎn)生的錯誤， 有兩種：
a.下層系統(tǒng)處理成功了，但是通信出錯了， 這樣會導(dǎo)致子系統(tǒng)之間的數(shù)據(jù)不一致；
對于這種情況， 可以采用超時補(bǔ)償機(jī)制，預(yù)先將任務(wù)記錄下來，通過定時任務(wù)在后續(xù)將數(shù)據(jù)訂正過來。
更好的設(shè)計方案 ？
b.通信成功了，但是下層處理出錯了。
對于這種情況， 需要與下層開發(fā)人員溝通， 協(xié)調(diào)子系統(tǒng)之間的交互；
需要根據(jù)下層返回的錯誤碼和錯誤描述做適當(dāng)?shù)奶幚砘蚪o予合理的提示信息。
無論哪一種情況， 都要假設(shè)下層系統(tǒng)可靠性一般， 做好出錯的設(shè)計考慮。
3.本層系統(tǒng)處理出錯。
本層系統(tǒng)產(chǎn)生錯誤的原因：
原因一：疏忽導(dǎo)致。 疏忽是指程序員能力完全可避免此類錯誤但實(shí)際上沒做到。比如將 && 敲成了 & ， == 敲成了 = ；邊界錯誤， 復(fù)合邏輯判斷錯誤等。疏忽要么是程序員注意力不夠集中， 比如處于疲倦狀態(tài)、加班通宵、邊開會邊寫程序；要么是急著實(shí)現(xiàn)功能，沒有顧及程序的健壯性等。
改進(jìn)措施：使用代碼靜態(tài)分析工具，通過單元測試行覆蓋可有效避免此類問題。
原因二：錯誤與異常處理不夠周全導(dǎo)致的。 比如輸入問題。計算兩個數(shù)相加， 不僅要考慮計算溢出問題， 還要考慮輸入非法的情形。對于前者，可能通過了解、犯錯或經(jīng)驗(yàn)就可以避免， 而對于后者，則必須加以限定，以使之處于我們的智商能夠控制的范圍內(nèi)，比如使用正則表達(dá)式過濾掉不合法的輸入。對于正則表達(dá)式必須進(jìn)行測試。對于不合法輸入， 要給出盡可能詳細(xì)、易懂、友好的提示信息、原因及建議方案。
改進(jìn)措施：盡可能周全地考慮各種錯誤情形和異常處理。在實(shí)現(xiàn)主流程之后，增加一個步驟：仔細(xì)推敲可能的各種錯誤和異常，返回合理錯誤碼和錯誤描述。每個接口或模塊都有效處理好自己的錯誤和異常，可有效避免因場景交互復(fù)雜導(dǎo)致的bug. 譬如，一個業(yè)務(wù)用例由場景A.B.C交互完成。實(shí)際執(zhí)行A.B成功了，C失敗了，這時B需要根據(jù)C返回合理的代碼和消息進(jìn)行回滾并返回給A合理的代碼和消息，A根據(jù)B的返回進(jìn)行回滾，并返回給客戶端合理的代碼和消息。這是一種分段回滾的機(jī)制，要求每個場景都必須考慮異常情況下的回滾。
原因三：邏輯耦合緊密導(dǎo)致。 由于業(yè)務(wù)邏輯耦合緊密， 隨著軟件產(chǎn)品一步步發(fā)展， 各種邏輯關(guān)系錯綜復(fù)雜， 難以看到全局狀況， 導(dǎo)致局部修改影響波及到全局范圍，造成不可預(yù)知的問題。
改進(jìn)措施：編寫短函數(shù)和短方法， 每個函數(shù)或方法最好不超過 50 行。編寫無狀態(tài)函數(shù)和方法， 只讀全局狀態(tài)， 相同的前提條件總是會輸出相同的結(jié)果， 不會依賴外部狀態(tài)而變更自己的行為；定義合理的結(jié)構(gòu)、 接口和邏輯段， 使接口之間的交互盡可能正交、低耦合；對于服務(wù)層， 盡可能提供簡單、正交的接口；持續(xù)重構(gòu)， 保持應(yīng)用模塊化和松耦合， 理清邏輯依賴關(guān)系。對于有大量業(yè)務(wù)接口相互影響的情況， 必須整理各個業(yè)務(wù)接口的邏輯流程及相互依賴關(guān)系， 從整體上進(jìn)行優(yōu)化；對于有大量狀態(tài)的實(shí)體， 也需要梳理相關(guān)的業(yè)務(wù)接口， 整理狀態(tài)之間的轉(zhuǎn)換關(guān)系。
原因四：算法不正確導(dǎo)致。
改進(jìn)措施：首先將算法從應(yīng)用中分離出來。若算法有多種實(shí)現(xiàn)， 可以通過交叉校驗(yàn)的單元測試找出來， 比如排序操作；如果算法具有可逆性質(zhì)， 可以通過可逆校驗(yàn)的單元測試找出來， 比如加密解密操作。
原因五：相同類型的參數(shù)，傳入順序錯誤導(dǎo)致。 比如，modifyFlow(int rx, int tx), 實(shí)際調(diào)用為 modifyFlow(tx,rx)
改進(jìn)措施：盡可能使類型具體化， 該用浮點(diǎn)數(shù)就用浮點(diǎn)數(shù)， 該用字符串就用字符串， 該用具體對象類型就用具體對象類型；相同類型的參數(shù)盡可能錯開；如果上述都無法滿足， 就必須通過接口測試來驗(yàn)證， 接口參數(shù)值務(wù)必是不同的。
原因六：空指針異常。 空指針異常通常是對象沒有正確初始化， 或者使用對象之前沒有對對象是否非空做檢測。
改進(jìn)措施：對于配置對象， 檢測其是否成功初始化；對于普通對象， 獲取到實(shí)體對象使用之前， 檢測是否非空。
原因七：網(wǎng)絡(luò)通信錯誤。 網(wǎng)絡(luò)通信錯誤通常是因?yàn)榫W(wǎng)絡(luò)延遲、阻塞或不通導(dǎo)致的錯誤。網(wǎng)絡(luò)通信錯誤通常是小概率事件， 但小概率事件很可能會導(dǎo)致大面積的故障、 難以復(fù)現(xiàn)的BUG。
改進(jìn)措施：在前一個子系統(tǒng)的結(jié)束點(diǎn)和后一個子系統(tǒng)的入口點(diǎn)分別打 INFO 日志。通過兩者的時間差提供一點(diǎn)線索。
原因八：事務(wù)與并發(fā)錯誤。 事務(wù)與并發(fā)結(jié)合在一起， 很容易產(chǎn)生非常難以定位的錯誤。
改進(jìn)措施：對于程序中的并發(fā)操作， 涉及到共享變量及重要狀態(tài)修改的， 要加 INFO 日志。更有效的做法？？？
原因九：配置錯誤。
改進(jìn)措施：在啟動應(yīng)用或啟動相應(yīng)配置時， 檢測所有的配置項， 打印相應(yīng)的INFO日志， 確保所有配置都加載成功。
原因十：業(yè)務(wù)不熟悉導(dǎo)致的錯誤。 在中大型系統(tǒng)， 部分業(yè)務(wù)邏輯和業(yè)務(wù)交互都比較復(fù)雜， 整個的業(yè)務(wù)邏輯可能存在于多個開發(fā)同學(xué)的大腦里， 每個人的認(rèn)識都不是完整的。這很容易導(dǎo)致業(yè)務(wù)編碼錯誤。
改進(jìn)措施：通過多人討論和溝通， 設(shè)計正確的業(yè)務(wù)用例， 根據(jù)業(yè)務(wù)用例來編寫和實(shí)現(xiàn)業(yè)務(wù)邏輯；最終的業(yè)務(wù)邏輯和業(yè)務(wù)用例必須完整存檔；在業(yè)務(wù)接口中注明該業(yè)務(wù)的前置條件、處理邏輯、后置校驗(yàn)和注意事項；當(dāng)業(yè)務(wù)變化時， 需要同步更新業(yè)務(wù)注釋；代碼REVIEW。業(yè)務(wù)注釋是業(yè)務(wù)接口的重要文檔， 對業(yè)務(wù)理解起著重要的緩存作用。
原因十一：設(shè)計問題導(dǎo)致的錯誤。 比如同步串行方式會有性能、響應(yīng)慢的問題， 而并發(fā)異步方式可以解決性能、響應(yīng)慢的問題， 但會帶來安全、正確性的隱患。異步方式會導(dǎo)致編程模型的改變， 新增異步消息推送和接收等新的問題。使用緩存能夠提高性能， 但是又會存在緩存更新的問題。
改進(jìn)措施：編寫和仔細(xì)評審設(shè)計文檔。設(shè)計文檔必須闡述背景、需求、所滿足的業(yè)務(wù)目標(biāo)、要達(dá)到的業(yè)務(wù)性能指標(biāo)、可能的影響、設(shè)計總體思路、詳細(xì)方案、預(yù)見該方案的優(yōu)缺點(diǎn)及可能的影響；通過測試和驗(yàn)收， 確保改設(shè)計方案確實(shí)滿足業(yè)務(wù)目標(biāo)和業(yè)務(wù)性能指標(biāo)。
原因十二：未知細(xì)節(jié)問題導(dǎo)致的錯誤。 比如緩沖區(qū)溢出、 SQL 注入攻擊。從功能上看是沒有問題的， 但是從惡意使用上看， 是存在漏洞的。再比如， 選擇 jackson 庫做 JSON 字符串解析， 默認(rèn)情況下， 當(dāng)對象新增字段時會導(dǎo)致解析出錯。必須在對象上加 @JsonIgnoreProperties(ignoreUnknown = true) 注解才能正確應(yīng)對變化。如果選用其他 JSON 庫就不一定有這個問題。
改進(jìn)措施：一方面要通過經(jīng)驗(yàn)積累， 另一方面， 考慮安全問題和例外情況， 選擇成熟的經(jīng)過嚴(yán)格測試的庫。
原因十三：隨時間變化而出現(xiàn)的bug。 有些解決方案在過去看來是很不錯的，但在當(dāng)前或者未來的情景中可能變得笨拙甚至不中用，也是常見的事情。比如像加密解密算法， 在過去可能認(rèn)為是完善的， 在破解之后就要慎重使用了。
改進(jìn)措施：關(guān)注變化以及漏洞修復(fù)消息，及時修正過時的代碼、庫、行為。
原因十四：硬件相關(guān)的錯誤。 比如內(nèi)存泄露， 存儲空間不足， OutOfMemoryError 等。
改進(jìn)措施：增加對應(yīng)用系統(tǒng)的 CPU / 內(nèi)存 / 網(wǎng)絡(luò)等重要指標(biāo)的性能監(jiān)控。
系統(tǒng)出現(xiàn)的常見錯誤：
1.實(shí)體在數(shù)據(jù)庫中的記錄不存在， 必須指明是哪個實(shí)體或?qū)嶓w標(biāo)識；
2.實(shí)體配置不正確， 必須指明是哪個配置有問題，正確的配置應(yīng)該是什么；
3.實(shí)體資源不滿足條件， 必須指明當(dāng)前資源是什么，資源要求是什么；
4.實(shí)體操作前置條件不滿足， 必須指明需要滿足什么前置條件，當(dāng)前的狀態(tài)是什么；
5.實(shí)體操作后置校驗(yàn)不滿足， 必須指明需要滿足什么后置校驗(yàn)， 當(dāng)前的狀態(tài)是什么；
6.性能問題導(dǎo)致超時， 必須指明是什么導(dǎo)致的性能問題，后續(xù)如何優(yōu)化；
7.多個子系統(tǒng)交互通信出錯導(dǎo)致之間的狀態(tài)或數(shù)據(jù)不一致？
一般難以定位的錯誤會出現(xiàn)在比較底層的地方。因?yàn)榈讓訜o法預(yù)知具體的業(yè)務(wù)場景， 給出的錯誤消息都是比較通用的。
這就要求在業(yè)務(wù)上層提供盡可能豐富的線索。錯誤的產(chǎn)生一定是多個系統(tǒng)或?qū)哟谓换サ倪^程中在某一層棧上不滿足前置條件導(dǎo)致。在編程時， 在每一層棧中盡可能確保所有必須的前置條件滿足，盡可能避免錯誤的參數(shù)傳遞到底層， 盡可能地將錯誤截獲在業(yè)務(wù)層。
大多數(shù)錯誤都是由多種原因組合產(chǎn)生。但每一種錯誤必定有其原因。在解決錯誤之后， 要深入分析錯誤是如何發(fā)生的， 如何避免這些錯誤再次發(fā)生。努力就能成功， 但是： 反思才能進(jìn)步 ！
如何編寫更容易排查問題的錯誤日志
打錯誤日志的基本原則：
1.盡可能完整。每一條錯誤日志都完整描述了：什么場景下發(fā)生了什么錯誤， 什么原因（或者哪些可能原因）， 如何解決（或解決提示）；
2.盡可能具體。比如 NC 資源不足， 究竟具體指什么資源不足， 是否可以通過程序直接指明；通用錯誤，比如 VM NOT EXIST ， 要指明在什么場景下發(fā)生的，可能便于后續(xù)統(tǒng)計的工作。
3.盡可能直接。最理想的錯誤日志應(yīng)該讓人在第一直覺下能夠知道是什么原因?qū)е?，該怎么去解決，而不是還要通過若干步驟去查找真正的原因。
4.將已有經(jīng)驗(yàn)集成直接到系統(tǒng)中。所有已經(jīng)解決過的問題及經(jīng)驗(yàn)都要盡可能以友好的方式集成到系統(tǒng)中，給新進(jìn)人員更好的提示，而不是埋藏在其他地方。
5.排版要整潔有序， 格式統(tǒng)一化規(guī)范化。密密麻麻、隨筆式的日志看著就揪心， 相當(dāng)不友好， 也不便于排查問題。
6.采用多個關(guān)鍵字唯一標(biāo)識請求，突出顯示關(guān)鍵字：時間、實(shí)體標(biāo)識（比如vmname）、操作名稱。
排查問題的基本步驟：
登錄到應(yīng)用服務(wù)器 -> 打開日志文件 -> 定位到錯誤日志位置 -> 根據(jù)錯誤日志的線索的指導(dǎo)去排查、確認(rèn)問題和解決問題。
其中：
1.從登陸到打開日志文件：由于應(yīng)用服務(wù)器有多臺， 要逐一登錄上去查看實(shí)在不方便。需要編寫一個工具放在 AG 上直接在 AG 上查看所有服務(wù)器日志， 甚至直接篩選出所需要的錯誤日志。
2.定位錯誤日志位置。目前日志的排版密密麻麻，不易定位到錯誤日志。一般可以先采用"時間"來定位到錯誤日志的附近前面的地方， 然后使用 實(shí)體關(guān)鍵字 / 操作名稱 組合來鎖定錯誤日志地方。根據(jù) requestId 定位錯誤日志雖然比較符合傳統(tǒng)，但是要先找到 requestId , 并且不具有描述性。最好能直接根據(jù)時間/內(nèi)容關(guān)鍵字來定位錯誤日志位置。
3.分析錯誤日志。錯誤日志的內(nèi)容最好能夠更加直接明了， 能夠明確指明與當(dāng)前要排查的問題特征是吻合的， 并且給出重要線索。
通常， 程序錯誤日志的問題就是日志內(nèi)容是針對當(dāng)前代碼情境才能理解，看上去簡潔， 但總是寫的不全， 半英文格式；一旦離開代碼情境， 就很難知道究竟說的是什么， 非要讓人思考一下或者去看看代碼才能明白日志說的是什么含義。這不是自己給自己罪受？
比如：
if ((storageType == StorageType.dfs1 || storageType == StorageType.dfs2)
&& (zone.hasStorageType(StorageType.io3) || zone.hasStorageType(StorageType.io4))) {
// 進(jìn)入dfs1 和dfs2 在io3 io4 存儲。
} else {
log.info("zone storage type not support, zone: " + zone.getZoneId() + ", storageType: "
+ storageType.name());
throw new BizException(DeviceErrorCode.ZONE_STORAGE_TYPE_NOT_SUPPORT);
}
zone 要支持什么 storage type 才是正確的? Do Not Let Me Think !
錯誤日志應(yīng)該做到：即使離開代碼情境，也能清晰地描述發(fā)生了什么。
此外，如果能夠直接在錯誤日志中說明清楚原因， 在做巡檢日志的時候也可以省些力氣。
從某種意義上來說， 錯誤日志也可以是一種非常有益的文檔，記錄著各種不合法的運(yùn)行用例。
目前程序錯誤日志的內(nèi)容可能存在如下問題：
1. 錯誤日志沒有指明錯誤參數(shù)和內(nèi)容：
catch(Exception ex){
log.error("control ip insert failed", ex);
return new ResultSet<AddControlIpResponse>(
ControlIpErrorCode.ERROR_CONTROL_IP_INSERT_FAILURE);
}
沒有指明插入失敗的 control ip. 如果加上 control ip 關(guān)鍵字， 更容易搜索和鎖定錯誤。
類似的還有：
log.error("Get some errors when insert subnet and its IPs into database. Add subnet or IP failure.", e);
沒有指明是哪個 subnet 的它下屬的哪些 IP. 值得注意的是， 要指明這些要額外做一些事情， 可能會稍微影響性能。這時候需要權(quán)衡性能和可調(diào)試性。
解決方案：使用 String.format("Some msg to ErrorObj: %s", errobj) 方法指明錯誤參數(shù)及內(nèi)容。
這通常要求對 DO 對象編寫可讀的 toString 方法。
2. 錯誤場景不明確：
log.error("nc has exist, nc ip" + request.getIp());
在 createNc 中檢測到 NC 已經(jīng)存在報錯。但是日志上沒有指明錯誤場景， 讓人猜測，為什么會報NC已存在錯誤。
可以改為
log.error("nc has exist when want to create nc, please check nc parameters. Given nc ip: " + request.getIp());
log.error("[create nc] nc has exist, please check nc parameters. Given nc ip: " + request.getIp());
類似的還有：
log.error("not all vm destroyed, nc id " + request.getNcId());
改成 log.error("[delete nc] some vms [%s] in the nc are not destroyed. nc id: %s", vmNames, request.getNcId());
解決方案：錯誤消息加上 when 字句， 或者錯誤消息前加上 【接口名】, 指明錯誤場景，直接從錯誤日志就知道明白了。
一般能夠知道 executor 的可以加上 【接口名】， service 加上 when 字句。
3. 內(nèi)容不明確, 或不明其義：
if(aliMonitorReporter == null) {
log.error("aliMonitorReporter is null!");
} else {
aliMonitorReporter.attach(new ThreadPoolMonitor(namePrefix, asynTaskThreadPool.getThreadPoolExecutor()));
}
改為：log.error("aliMonitorReporter is null, probably not initialized properly, please check configuration in file xxx.");
類似的還有：
if (diskWbps == null && diskRbps == null && diskWiops == null && diskRiops == null) {
log.error("none of attribute is specified for modifying");
throw new BizException(DeviceErrorCode.NO_ATTRIBUTE_FOR_MODIFY);
}
改為 log.error("[modify disk attribute] None of [diskWbps,diskRbps,diskWiops,diskRiops] is specified for disk id:" + diskId);
解決方案：更清晰貼切地描述錯誤內(nèi)容。
4. 排查問題的引導(dǎo)內(nèi)容不明確：
log.error("get gw group ip segment failed. zkPath: " + LockResource.getGwGroupIpSegmnetLockPath(request.getGwGroupId()));
zkPath ? 如何去排查這個問題？我該去找誰？到哪里去查找更具體的線索？
解決方案：加上相應(yīng)的背景知識和引導(dǎo)排查措施。
5. 錯誤內(nèi)容不夠具體細(xì)致：
if (!ncResourceService.isNcResourceEnough(ncResourceDO, vmResourceCondition)) {
log.error("disk space is not enough at vm's nc, nc id:" + vmDO.getNcId());
throw new BizException(ResourceErrorCode.ERROR_RESOURCE_NOT_ENOUGH);
}
究竟是什么資源不夠？目前剩余多少？現(xiàn)在需要多少？值得注意的是， 要指明這些要額外做一些事情， 可能會稍微影響性能。這時候需要權(quán)衡性能和可調(diào)試性。
解決方案：通過改進(jìn)程序或程序技巧， 盡可能揭示出具體的差異所在， 減少人工比對的操作。
6. 半英文句式讀起來不夠清晰明白，需要思考來拼湊起完整的意思：
log.warn("cache status conflict, device id "+deviceDO.getId()+" db status "+deviceDO.getStatus() +", nc status "+ status);
改為:
log.warn(String.format("[query cache status] device cache status conflicts between regiondb and nc, status of device '%s' in regiondb is %s , but is %s in nc.", deviceDO.getId(), deviceDO.getStatus(), status));
解決方案：改為自然可讀的英文句式。
總結(jié)起來， 錯誤日志格式可以為：
log.error("[接口名或操作名] [Some Error Msg] happens. [params] [Probably Because]. [Probably need to do].");
log.error(String.format("[接口名或操作名] [Some Error Msg] happens. [%s]. [Probably Because]. [Probably need to do].", params));
或
log.error("[Some Error Msg] happens to 錯誤參數(shù)或內(nèi)容 when [in some condition]. [Probably Because]. [Probably need to do].");
log.error(String.format("[Some Error Msg] happens to %s when [in some condition]. [Probably Because]. [Probably need to do].", parameters));
[Probably Reason]. [Probably need to do]. 在某些情況下可以省略；在一些重要接口和場景下最好能說明一下。
每一條錯誤日志都是獨(dú)立的，盡可能完整、具體、直接說明何種場景下發(fā)生了什么錯誤，由什么原因?qū)е?，要采用什么措施或步驟。
問題：
1.String.format 的性能會影響打日志嗎？一般來說， 錯誤日志應(yīng)該是比較少的， 使用 String.format 的頻度并不會太高，不會對應(yīng)用和日志造成影響。
2.開發(fā)時間非常緊張時， 有時間去斟酌字句嗎？建立一個標(biāo)準(zhǔn)化的內(nèi)容格式，將內(nèi)容往格式套，可以節(jié)省斟酌字句的時間。
3.什么時候使用 info, warn , error ?
info 用于打印程序應(yīng)該出現(xiàn)的正常狀態(tài)信息， 便于追蹤定位；
warn 表明系統(tǒng)出現(xiàn)輕微的不合理但不影響運(yùn)行和使用；
error 表明出現(xiàn)了系統(tǒng)錯誤和異常，無法正常完成目標(biāo)操作。
http://stackoverflow.com/questions/2031163/when-to-use-log-level-warn-vs-error
錯誤日志是排查問題的重要手段之一。當(dāng)我們編程實(shí)現(xiàn)一項功能時， 通常會考慮可能發(fā)生的各種錯誤及相應(yīng)原因：
要排查出相應(yīng)的原因， 就需要一些關(guān)鍵描述來定位原因。這就會形成三元組：
錯誤現(xiàn)象 -> 錯誤關(guān)鍵描述 -> 最終的錯誤原因。
需要針對每一種錯誤盡可能提供相應(yīng)的錯誤關(guān)鍵描述，從而定位到相應(yīng)的錯誤原因。
也就是說，編程的時候，要仔細(xì)思考， 哪些描述是非常有利于定位錯誤原因的， 盡可能將這些描述添加到錯誤日志中。
文中沒有指出的問題或困難， 請?zhí)岢瞿愕慕ㄗh。
往期推薦
下方二維碼關(guān)注我
技術(shù)草根，堅持分享 編程，算法，架構(gòu)
看完文章，餓了點(diǎn)外賣，點(diǎn)擊 ??《無門檻外賣優(yōu)惠券，每天免費(fèi)領(lǐng)！》