如何打日誌才能方便排查問題？

作者：琴水玉
來源：https://cnblogs.com/lovesqcc/p/4319594.html

在程序中打錯誤日誌的主要目標是爲更好地排查問題和解決問題提供重要線索和指導。但是在實際中打的錯誤日誌內容和格式變化多樣，錯誤提示上可能殘缺不全、沒有相關背景、不明其義，使得排查解決問題成爲非常不方便或者耗時的操作。而實際上，如果編程的時候稍加用心，就會減少排查問題的很多無用功。

在闡述如何編寫有效的錯誤日誌之前，瞭解錯誤是怎麼產生的，非常重要。

錯誤是如何煉成的

對於當前系統來說， 錯誤的產生由三個地方引入：

1. 上層系統引入的非法參數。對於非法參數引入的錯誤， 可以通過參數校驗和前置條件校驗來截獲錯誤；

2. 與下層系統交互產生的錯誤。與下層交互產生的錯誤， 有兩種：

a. 下層系統處理成功了，但是通信出錯了， 這樣會導致子系統之間的數據不一致；

對於這種情況， 可以採用超時補償機制，預先將任務記錄下來，通過定時任務在後續將數據訂正過來。

更好的設計方案 ？

b. 通信成功了，但是下層處理出錯了。

對於這種情況， 需要與下層開發人員溝通， 協調子系統之間的交互；

需要根據下層返回的錯誤碼和錯誤描述做適當的處理或給予合理的提示信息。

無論哪一種情況， 都要假設下層系統可靠性一般， 做好出錯的設計考慮。

  1. 本層系統處理出錯。

本層系統產生錯誤的原因：

原因一：疏忽導致。

疏忽是指程序員能力完全可避免此類錯誤但實際上沒做到。比如將 && 敲成了 & ， == 敲成了 = ；邊界錯誤， 複合邏輯判斷錯誤等。疏忽要麼是程序員注意力不夠集中， 比如處於疲倦狀態、加班通宵、邊開會邊寫程序；要麼是急着實現功能，沒有顧及程序的健壯性等。

改進措施：使用代碼靜態分析工具，通過單元測試行覆蓋可有效避免此類問題。

原因二：錯誤與異常處理不夠周全導致的。

比如輸入問題。計算兩個數相加， 不僅要考慮計算溢出問題， 還要考慮輸入非法的情形。對於前者，可能通過了解、犯錯或經驗就可以避免， 而對於後者，則必須加以限定，以使之處於我們的智商能夠控制的範圍內，比如使用正則表達式過濾掉不合法的輸入。對於正則表達式必須進行測試。對於不合法輸入， 要給出儘可能詳細、易懂、友好的提示信息、原因及建議方案。

改進措施：儘可能周全地考慮各種錯誤情形和異常處理。在實現主流程之後，增加一個步驟：仔細推敲可能的各種錯誤和異常，返回合理錯誤碼和錯誤描述。每個接口或模塊都有效處理好自己的錯誤和異常，可有效避免因場景交互複雜導致的 bug。

譬如，一個業務用例由場景 A.B.C 交互完成。實際執行 A.B 成功了，C 失敗了，這時 B 需要根據 C 返回合理的代碼和消息進行回滾並返回給 A 合理的代碼和消息，A 根據 B 的返回進行回滾，並返回給客戶端合理的代碼和消息。這是一種分段回滾的機制，要求每個場景都必須考慮異常情況下的回滾。

原因三：邏輯耦合緊密導致。

由於業務邏輯耦合緊密， 隨着軟件產品一步步發展， 各種邏輯關係錯綜複雜， 難以看到全局狀況， 導致局部修改影響波及到全局範圍，造成不可預知的問題。

改進措施：編寫短函數和短方法， 每個函數或方法最好不超過 50 行。編寫無狀態函數和方法， 只讀全局狀態， 相同的前提條件總是會輸出相同的結果， 不會依賴外部狀態而變更自己的行爲；定義合理的結構、 接口和邏輯段，使接口之間的交互儘可能正交、低耦合；對於服務層， 儘可能提供簡單、正交的接口；持續重構， 保持應用模塊化和松耦合， 理清邏輯依賴關係。對於有大量業務接口相互影響的情況， 必須整理各個業務接口的邏輯流程及相互依賴關係， 從整體上進行優化；對於有大量狀態的實體， 也需要梳理相關的業務接口， 整理狀態之間的轉換關係。

原因四：算法不正確導致。

改進措施：首先將算法從應用中分離出來。若算法有多種實現， 可以通過交叉校驗的單元測試找出來， 比如排序操作；如果算法具有可逆性質， 可以通過可逆校驗的單元測試找出來， 比如加密解密操作。

原因五：相同類型的參數，傳入順序錯誤導致。

比如，modifyFlow(int rx, int tx), 實際調用爲 modifyFlow(tx,rx)

改進措施：儘可能使類型具體化， 該用浮點數就用浮點數， 該用字符串就用字符串， 該用具體對象類型就用具體對象類型；相同類型的參數儘可能錯開；如果上述都無法滿足， 就必須通過接口測試來驗證， 接口參數值務必是不同的。

原因六：空指針異常。

空指針異常通常是對象沒有正確初始化， 或者使用對象之前沒有對對象是否非空做檢測。避免空指針的 5 個案例推薦你看下。

改進措施：對於配置對象， 檢測其是否成功初始化；對於普通對象， 獲取到實體對象使用之前， 檢測是否非空。

原因七：網絡通信錯誤。

網絡通信錯誤通常是因爲網絡延遲、阻塞或不通導致的錯誤。網絡通信錯誤通常是小概率事件， 但小概率事件很可能會導致大面積的故障、 難以復現的 BUG。

改進措施：在前一個子系統的結束點和後一個子系統的入口點分別打 INFO 日誌。通過兩者的時間差提供一點線索。

原因八：事務與併發錯誤。

事務與併發結合在一起， 很容易產生非常難以定位的錯誤。

改進措施：對於程序中的併發操作， 涉及到共享變量及重要狀態修改的， 要加 INFO 日誌。更有效的做法？？？推薦閱讀：Spring 事務失效的 8 大原因。

原因九：配置錯誤。

改進措施：在啓動應用或啓動相應配置時， 檢測所有的配置項， 打印相應的 INFO 日誌， 確保所有配置都加載成功。

原因十：業務不熟悉導致的錯誤。

在中大型系統， 部分業務邏輯和業務交互都比較複雜， 整個的業務邏輯可能存在於多個開發同學的大腦裏， 每個人的認識都不是完整的。這很容易導致業務編碼錯誤。

原因十一：設計問題導致的錯誤。

比如同步串行方式會有性能、響應慢的問題， 而併發異步方式可以解決性能、響應慢的問題， 但會帶來安全、正確性的隱患。異步方式會導致編程模型的改變， 新增異步消息推送和接收等新的問題。使用緩存能夠提高性能， 但是又會存在緩存更新的問題。

改進措施：編寫和仔細評審設計文檔。設計文檔必須闡述背景、需求、所滿足的業務目標、要達到的業務性能指標、可能的影響、設計總體思路、詳細方案、預見該方案的優缺點及可能的影響；通過測試和驗收， 確保改設計方案確實滿足業務目標和業務性能指標。

原因十二：未知細節問題導致的錯誤。

比如緩衝區溢出、 SQL 注入攻擊。從功能上看是沒有問題的， 但是從惡意使用上看， 是存在漏洞的。再比如， 選擇 jackson 庫做 JSON 字符串解析， 默認情況下， 當對象新增字段時會導致解析出錯。必須在對象上加 @JsonIgnoreProperties(ignoreUnknown = true) 註解才能正確應對變化。如果選用其他 JSON 庫就不一定有這個問題。

改進措施：一方面要通過經驗積累， 另一方面， 考慮安全問題和例外情況， 選擇成熟的經過嚴格測試的庫。

原因十三：隨時間變化而出現的 bug。

有些解決方案在過去看來是很不錯的，但在當前或者未來的情景中可能變得笨拙甚至不中用，也是常見的事情。比如像加密解密算法， 在過去可能認爲是完善的， 在破解之後就要慎重使用了。

改進措施：關注變化以及漏洞修復消息，及時修正過時的代碼、庫、行爲。

原因十四：硬件相關的錯誤。

比如內存泄露， 存儲空間不足， OutOfMemoryError 等。另外，關注公衆號 Java 技術棧，在後臺回覆：JVM46，可以獲取一份 46 頁的 JVM 教程，非常齊全。

改進措施：增加對應用系統的 CPU / 內存 / 網絡等重要指標的性能監控。Java 系列最新教程：https://github.com/javastacks/javastack

系統出現的常見錯誤：

  1. 實體在數據庫中的記錄不存在， 必須指明是哪個實體或實體標識；

  2. 實體配置不正確， 必須指明是哪個配置有問題，正確的配置應該是什麼；

  3. 實體資源不滿足條件， 必須指明當前資源是什麼，資源要求是什麼；

  4. 實體操作前置條件不滿足， 必須指明需要滿足什麼前置條件，當前的狀態是什麼；

  5. 實體操作後置校驗不滿足， 必須指明需要滿足什麼後置校驗， 當前的狀態是什麼；

  6. 性能問題導致超時， 必須指明是什麼導致的性能問題，後續如何優化；

  7. 多個子系統交互通信出錯導致之間的狀態或數據不一致？

一般難以定位的錯誤會出現在比較底層的地方。因爲底層無法預知具體的業務場景， 給出的錯誤消息都是比較通用的。

這就要求在業務上層提供儘可能豐富的線索。錯誤的產生一定是多個系統或層次交互的過程中在某一層棧上不滿足前置條件導致。在編程時， 在每一層棧中儘可能確保所有必須的前置條件滿足，儘可能避免錯誤的參數傳遞到底層， 儘可能地將錯誤截獲在業務層。

大多數錯誤都是由多種原因組合產生。但每一種錯誤必定有其原因。在解決錯誤之後， 要深入分析錯誤是如何發生的， 如何避免這些錯誤再次發生。努力就能成功， 但是：反思才能進步 ！

如何編寫更容易排查問題的錯誤日誌

打錯誤日誌的基本原則：

  1. 儘可能完整。每一條錯誤日誌都完整描述了：什麼場景下發生了什麼錯誤， 什麼原因（或者哪些可能原因）， 如何解決（或解決提示）；

  2. 儘可能具體。比如 NC 資源不足， 究竟具體指什麼資源不足， 是否可以通過程序直接指明；通用錯誤，比如 VM NOT EXIST ， 要指明在什麼場景下發生的，可能便於後續統計的工作。

  3. 儘可能直接。最理想的錯誤日誌應該讓人在第一直覺下能夠知道是什麼原因導致，該怎麼去解決，而不是還要通過若干步驟去查找真正的原因。

  4. 將已有經驗集成直接到系統中。所有已經解決過的問題及經驗都要儘可能以友好的方式集成到系統中，給新進人員更好的提示，而不是埋藏在其他地方。

  5. 排版要整潔有序， 格式統一化規範化。密密麻麻、隨筆式的日誌看着就揪心， 相當不友好， 也不便於排查問題。

  6. 採用多個關鍵字唯一標識請求，突出顯示關鍵字：時間、實體標識（比如 vmname）、操作名稱。

排查問題的基本步驟：

登錄到應用服務器 -> 打開日誌文件 -> 定位到錯誤日誌位置 -> 根據錯誤日誌的線索的指導去排查、確認問題和解決問題。

其中：

  1. 從登陸到打開日誌文件：由於應用服務器有多臺， 要逐一登錄上去查看實在不方便。需要編寫一個工具放在 AG 上直接在 AG 上查看所有服務器日誌， 甚至直接篩選出所需要的錯誤日誌。

  2. 定位錯誤日誌位置。目前日誌的排版密密麻麻，不易定位到錯誤日誌。一般可以先採用 "時間" 來定位到錯誤日誌的附近前面的地方， 然後使用 實體關鍵字 / 操作名稱 組合來鎖定錯誤日誌地方。根據 requestId 定位錯誤日誌雖然比較符合傳統，但是要先找到 requestId , 並且不具有描述性。最好能直接根據時間 / 內容關鍵字來定位錯誤日誌位置。

  3. 分析錯誤日誌。錯誤日誌的內容最好能夠更加直接明瞭， 能夠明確指明與當前要排查的問題特徵是吻合的， 並且給出重要線索。

通常， 程序錯誤日誌的問題就是日誌內容是針對當前代碼情境才能理解，看上去簡潔， 但總是寫的不全， 半英文格式；一旦離開代碼情境， 就很難知道究竟說的是什麼， 非要讓人思考一下或者去看看代碼才能明白日誌說的是什麼含義。這不是自己給自己罪受？

比如：

if ((storageType == StorageType.dfs1 || storageType == StorageType.dfs2)
                && (zone.hasStorageType(StorageType.io3) || zone.hasStorageType(StorageType.io4))) {
// 進入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 !

錯誤日誌應該做到：即使離開代碼情境，也能清晰地描述發生了什麼。

此外，如果能夠直接在錯誤日誌中說明清楚原因， 在做巡檢日誌的時候也可以省些力氣。

從某種意義上來說， 錯誤日誌也可以是一種非常有益的文檔，記錄着各種不合法的運行用例。

目前程序錯誤日誌的內容可能存在如下問題：

1. 錯誤日誌沒有指明錯誤參數和內容：

catch(Exception ex){
      log.error("control ip insert failed", ex);
      return new ResultSet<AddControlIpResponse>(
ControlIpErrorCode.ERROR_CONTROL_IP_INSERT_FAILURE);
}

沒有指明插入失敗的 control ip. 如果加上 control ip 關鍵字， 更容易搜索和鎖定錯誤。

類似的還有：

log.error("Get some errors when insert subnet and its IPs into database. Add subnet or IP failure.", e);

沒有指明是哪個 subnet 的它下屬的哪些 IP. 值得注意的是， 要指明這些要額外做一些事情， 可能會稍微影響性能。這時候需要權衡性能和可調試性。

解決方案：使用 String.format("Some msg to ErrorObj: %s", errobj) 方法指明錯誤參數及內容。

這通常要求對 DO 對象編寫可讀的 toString 方法。

2. 錯誤場景不明確：

log.error("nc has exist, nc ip" + request.getIp());

在 createNc 中檢測到 NC 已經存在報錯。但是日誌上沒有指明錯誤場景， 讓人猜測，爲什麼會報 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 字句。推薦閱讀：Java 開發手冊（嵩山版）

3. 內容不明確, 或不明其義：

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);

解決方案：更清晰貼切地描述錯誤內容。

4. 排查問題的引導內容不明確：

log.error("get gw group ip segment failed. zkPath: " + LockResource.getGwGroupIpSegmnetLockPath(request.getGwGroupId()));

zkPath ? 如何去排查這個問題？我該去找誰？到哪裏去查找更具體的線索？

解決方案：加上相應的背景知識和引導排查措施。

5. 錯誤內容不夠具體細緻：

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);
}

究竟是什麼資源不夠？目前剩餘多少？現在需要多少？值得注意的是， 要指明這些要額外做一些事情， 可能會稍微影響性能。這時候需要權衡性能和可調試性。

解決方案：通過改進程序或程序技巧， 儘可能揭示出具體的差異所在， 減少人工比對的操作。

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));

解決方案：改爲自然可讀的英文句式。

總結起來， 錯誤日誌格式可以爲：

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 錯誤參數或內容 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]. 在某些情況下可以省略；在一些重要接口和場景下最好能說明一下。

每一條錯誤日誌都是獨立的，儘可能完整、具體、直接說明何種場景下發生了什麼錯誤，由什麼原因導致，要採用什麼措施或步驟。

Java 系列最新教程：https://github.com/javastacks/javastack

問題：

1.String.format 的性能會影響打日誌嗎？一般來說， 錯誤日誌應該是比較少的， 使用 String.format 的頻度並不會太高，不會對應用和日誌造成影響。

  1. 開發時間非常緊張時， 有時間去斟酌字句嗎？建立一個標準化的內容格式，將內容往格式套，可以節省斟酌字句的時間。

  2. 什麼時候使用 info, warn , error ?

info 用於打印程序應該出現的正常狀態信息， 便於追蹤定位；

warn 表明系統出現輕微的不合理但不影響運行和使用；

error 表明出現了系統錯誤和異常，無法正常完成目標操作。

http://stackoverflow.com/questions/2031163/when-to-use-log-level-warn-vs-error

錯誤日誌是排查問題的重要手段之一。當我們編程實現一項功能時， 通常會考慮可能發生的各種錯誤及相應原因：

要排查出相應的原因， 就需要一些關鍵描述來定位原因。這就會形成三元組：

錯誤現象 -> 錯誤關鍵描述 -> 最終的錯誤原因。

需要針對每一種錯誤儘可能提供相應的錯誤關鍵描述，從而定位到相應的錯誤原因。

也就是說，編程的時候，要仔細思考， 哪些描述是非常有利於定位錯誤原因的， 儘可能將這些描述添加到錯誤日誌中。

文中沒有指出的問題或困難， 請提出你的建議。

本文由 Readfog 進行 AMP 轉碼，版權歸原作者所有。
來源：https://mp.weixin.qq.com/s/0Xg773ErdZkly_s96e83QA

猜你喜歡