如何使錯誤日誌更加方便排查問題

時間 2019-11-06

標籤如何錯誤日誌更加方便排查問題简体版

原文原文鏈接

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

錯誤是如何煉成的

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

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

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

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

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

更好的設計方案？

b. 通訊成功了，可是下層處理出錯了。

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

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

不管哪種狀況，都要假設下層系統可靠性通常，作好出錯的設計考慮。

3. 本層系統處理出錯。

本層系統產生錯誤的緣由：

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

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

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

改進措施：儘量周全地考慮各類錯誤情形和異常處理。在實現主流程以後，增長一個步驟：仔細推敲可能的各類錯誤和異常，返回合理錯誤碼和錯誤描述。每一個接口或模塊都有效處理好本身的錯誤和異常，可有效避免因場景交互複雜致使的bug. 譬如，一個業務用例由場景A.B.C交互完成。實際執行A.B成功了，C失敗了，這時B須要根據C返回合理的代碼和消息進行回滾並返回給A合理的代碼和消息，A根據B的返回進行回滾，並返回給客戶端合理的代碼和消息。這是一種分段回滾的機制，要求每一個場景都必須考慮異常狀況下的回滾。

緣由三：邏輯耦合緊密緻使。 因爲業務邏輯耦合緊密，隨着軟件產品一步步發展，各類邏輯關係錯綜複雜，難以看到全局情況，致使局部修改影響波及到全局範圍，形成不可預知的問題。

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

緣由四：算法不正確致使。

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

緣由五：相同類型的參數，傳入順序錯誤致使。好比，modifyFlow(int rx, int tx), 實際調用爲 modifyFlow(tx,rx)

改進措施：儘量使類型具體化，該用浮點數就用浮點數，該用字符串就用字符串，該用具體對象類型就用具體對象類型；相同類型的參數儘量錯開；若是上述都沒法知足，就必須經過接口測試來驗證，接口參數值務必是不一樣的。

緣由六：空指針異常。 空指針異常一般是對象沒有正確初始化，或者使用對象以前沒有對對象是否非空作檢測。

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

緣由七：網絡通訊錯誤。 網絡通訊錯誤一般是由於網絡延遲、阻塞或不通致使的錯誤。網絡通訊錯誤一般是小几率事件，但小几率事件極可能會致使大面積的故障、難以復現的BUG。

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

緣由八：事務與併發錯誤。 事務與併發結合在一塊兒，很容易產生很是難以定位的錯誤。

改進措施：對於程序中的併發操做，涉及到共享變量及重要狀態修改的，要加 INFO 日誌。更有效的作法？？？

緣由九：配置錯誤。

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

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

改進措施：經過多人討論和溝通，設計正確的業務用例，根據業務用例來編寫和實現業務邏輯；最終的業務邏輯和業務用例必須完整存檔；在業務接口中註明該業務的前置條件、處理邏輯、後置校驗和注意事項；當業務變化時，須要同步更新業務註釋；代碼REVIEW。業務註釋是業務接口的重要文檔，對業務理解起着重要的緩存做用。

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

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

緣由十二：未知細節問題致使的錯誤。 好比緩衝區溢出、 SQL 注入攻擊。從功能上看是沒有問題的，可是從惡意使用上看，是存在漏洞的。再好比，選擇 jackson 庫作 JSON 字符串解析，默認狀況下，當對象新增字段時會致使解析出錯。必須在對象上加 @JsonIgnoreProperties(ignoreUnknown = true) 註解才能正確應對變化。若是選用其餘 JSON 庫就不必定有這個問題。

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

緣由十三：隨時間變化而出現的bug。有些解決方案在過去看來是很不錯的，但在當前或者將來的情景中可能變得笨拙甚至不中用，也是常見的事情。好比像加密解密算法，在過去可能認爲是完善的，在破解以後就要慎重使用了。

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

緣由十四：硬件相關的錯誤。 好比內存泄露，存儲空間不足， OutOfMemoryError 等。

改進措施：增長對應用系統的 CPU / 內存 / 網絡等重要指標的性能監控。

系統出現的常見錯誤：

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 字句。

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]. 在某些狀況下能夠省略；在一些重要接口和場景下最好能說明一下。

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

問題：

1. String.format 的性能會影響打日誌嗎？通常來講，錯誤日誌應該是比較少的，使用 String.format 的頻度並不會過高，不會對應用和日誌形成影響。

2. 開發時間很是緊張時，有時間去斟酌字句嗎？創建一個標準化的內容格式，將內容往格式套，能夠節省斟酌字句的時間。