最佳日誌實踐

作者：王健

網址：http://www.bitstech.net/2014/01/07/log-best-practice/

點選“閱讀原文”可檢視本文網頁版

前言

日誌用來記錄使用者操作、系統執行狀態等，是一個系統的重要組成部分。然而由於日誌並非系統核心功能，通常情況下並不受團隊的重視。在出現問題需要透過日誌來定位時，才發現日誌還存在很多問題。

日誌記錄的好壞直接關係到系統出現問題時定位的速度，同時可以透過對日誌的觀察和分析，提前發現系統可能的風險，避免線上事故的發生。

我們在開發和運維NOS（網易物件儲存，Netease Object Storage）的過程中，對整個系統的日誌進行了分析最佳化，積累出一些經驗，歸納如下。

相關問題經驗整理

1. 關於日誌級別

我們通常使用的日誌庫（如log4j等），將日誌基本分為以下幾類（從低到高）：

TRACE – The TRACE Level designates finer-grained informational events than the DEBUG

DEBUG – The DEBUG Level designates fine-grained informational events that are most useful to debug an application.

INFO – The INFO level designates informational messages that highlight the progress of the application at coarse-grained level.

WARN – The WARN level designates potentially harmful situations.

ERROR – The ERROR level designates error events that might still allow the application to continue running.

FATAL – The FATAL level designates very severe error events that will presumably lead the application to abort.

儘管log4j官方檔案對各個日誌級別進行了簡單定義。然而在實踐中，究竟哪些操作需要記入日誌，哪種錯誤應該記為WARN級別，而哪種錯誤又為ERROR級別，還需要進行進一步討論。

關於該問題，在StackOverflow上有一個討論貼進行過討論。

此處對貼子中的一些觀點，加上我們在平時運維過程中遇到的相關問題進行歸納：

• 一個專案各個log級別的定義應該是清楚明確的，是每個開發人員所遵循的；
• 即使是TRACE或者DEBUG級別的日誌，也應該有一定的規範，要保證除了開發人員自己以外，包括測試人員和運維人員都可以方便地透過日誌定位問題；
• 對於日誌級別的分類，有以下參考：FATAL — 表示需要立即被處理的系統級錯誤。當該錯誤發生時，表示服務已經出現了某種程度的不可用，系統管理員需要立即介入。這屬於最嚴重的日誌級別，因此該日誌級 別必須慎用，如果這種級別的日誌經常出現，則該日誌也失去了意義。通常情況下，一個行程的生命週期中應該只記錄一次FATAL級別的日誌，即該行程遇到無 法恢復的錯誤而退出時。當然，如果某個系統的子系統遇到了不可恢復的錯誤，那該子系統的呼叫方也可以記入FATAL級別日誌，以便透過日誌報警提醒系統管 理員修複；ERROR — 該級別的錯誤也需要馬上被處理，但是緊急程度要低於FATAL級別。當ERROR錯誤發生時，已經影響了使用者的正常訪問。從該意義上來說，實際上 ERROR錯誤和FATAL錯誤對使用者的影響是相當的。FATAL相當於服務已經掛了，而ERROR相當於好死不如賴活著，然而活著卻無法提供正常的服 務，只能不斷地列印ERROR日誌。特別需要註意的是，ERROR和FATAL都屬於伺服器自己的異常，是需要馬上得到人工介入並處理的。而對於使用者自己 操作不當，如請求引數錯誤等等，是絕對不應該記為ERROR日誌的；

  WARN — 該日誌表示系統可能出現問題，也可能沒有，這種情況如網路的波動等。對於那些目前還不是錯誤，然而不及時處理也會變為錯誤的情況，也可以記為WARN日 志，例如一個儲存系統的磁碟使用量超過閥值，或者系統中某個使用者的儲存配額快用完等等。對於WARN級別的日誌，雖然不需要系統管理員馬上處理，也是需要 即使檢視並處理的。因此此種級別的日誌也不應太多，能不打WARN級別的日誌，就儘量不要打；

  INFO — 該種日誌記錄系統的正常執行狀態，例如某個子系統的初始化，某個請求的成功執行等等。透過檢視INFO級別的日誌，可以很快地對系統中出現的 WARN,ERROR,FATAL錯誤進行定位。INFO日誌不宜過多，通常情況下，INFO級別的日誌應該不大於TRACE日誌的10%；

  DEBUG or TRACE — 這兩種日誌具體的規範應該由專案組自己定義，該級別日誌的主要作用是對系統每一步的執行狀態進行精確的記錄。透過該種日誌，可以檢視某一個操作每一步的執 行過程，可以準確定位是何種操作，何種引數，何種順序導致了某種錯誤的發生。可以保證在不重現錯誤的情況下，也可以透過DEBUG（或TRACE）級別的 日誌對問題進行診斷。需要註意的是，DEBUG日誌也需要規範日誌格式，應該保證除了記錄日誌的開發人員自己外，其他的如運維，測試人員等也可以透過 DEBUG（或TRACE）日誌來定位問題；

Rule 1：整個團隊（包括運維人員）需要對日誌級別有明確的規定，什麼日誌記入什麼級別的日誌，什麼級別的錯誤出現要如何處理等

2. 對記錄的日誌要進行更新維護

由於DEBUG（或TRACE）級別的日誌對於定位問題至關重要，因此該種日誌記錄是否完備且不冗餘、格式是否規範等也需要花費大量精力來最佳化。此處有以下幾個比較好的實踐：

• 定義好整個團隊記錄DEBUG（或TRACE）日誌的規範，保證每個開發記錄的日誌格式統一；
• 整個團隊（包括開發，運維和測試）定期對記錄的日誌內容進行Review；
• 開發做運維，透過在查問題的過程來最佳化日誌記錄的方式；
• 運維或測試在日誌中發現的問題，都需要及時向開發人員反映；

Rule 2：需要定期對日誌內容進行最佳化更新，目的就是透過日誌快速準確的定位問題

3. 關於日誌分類

日誌從功能來說，可分為診斷日誌、統計日誌、審計日誌。

診斷日誌， 典型的有：

• 請求入口和出口
• 外部服務呼叫和傳回
• 資源消耗操作: 開啟檔案等
• 容錯行為： 譬如雲硬碟的副本修複操作
• 程式異常： 譬如資料庫無法連線
• 後臺操作：清理程式
• 啟動、關閉、配置載入
• 丟擲異常時，不記錄日誌

統計日誌：

• 使用者訪問統計
• 計費日誌（如記錄使用者使用的網路資源或磁碟佔用，格式較為嚴格，便於統計）

審計日誌：

• 管理操作

將不同需求的日誌記入到不同的日誌檔案中，可以方便相關問題（管理平臺操作審計，使用者操作計費等）的處理。針對每一種需求，需要對日誌的格式，日誌記錄的內容等進行特別的記錄。

Rule 3：要明確不同日誌的用途，對日誌內容進行分類

4. 日誌中不要記錄無用資訊

在很多應用中，使用者都需要透過Fuse方式來掛載使用NOS。

POSIX標準中檔案系統介面不允許檔案 /a 與目錄 /a/ 同時存在，而NOS作為物件儲存系統，/a 和/a/ 是不同的物件，是能夠同時存在的，一般地，NOS 中我們會規定 /a/ 是目錄，/a 是檔案，目錄物件大小為0。

POSIX標準對檔案的getattr操作，無論是 /a 還是 /a/，對應的請求都是 /a。為了避免遺漏，需分別向 NOS 請求 HeadObject(“/a“)和 HeadObject(“/a/“)。如果命中/a，說明 /a 是一個檔案，不用再請求 getattr(“/a/“)。

因此當使用者訪問 */a/b/c.txt* 時，實際上向NOS發送了以下請求：

# HeadObject(“/a”)
# HeadObject(“/a/”)
# HeadObject(“/a/b”)
# HeadObject(“/a/b/”)
# HeadObject(“/a/b/c.txt”)

對於上面的請求，實際上HeadObject(“/a”)和HeadObject(“/a/b”)都會傳回NoSuchKey錯誤，而Fuse正是該錯誤來判斷該檔案不存在，而可能是個目錄的。

然而對於NOS來說，這將導致產生大量無意義的NoSuchKey日誌（整個日誌檔案的80%都是該錯誤日誌）。這些日誌對於開發人員進行日誌觀察，運維人員定位問題，日誌監控等都造成了困難。

Rule 4: 絕不要列印沒有用的日誌，防止無用日誌淹沒重要資訊

解決辦法：Fuse請求時，在Http頭部加入 User-Agent 欄位，當NOS發現請求是 Fuse發過來的且為HeadObject操作且為NoSuchKey錯誤時，則不列印錯誤日誌。

5. 日誌記錄資訊要完整

問題描述：

NOS提供分塊上傳的介面，使用者可以透過以下的呼叫序列，來實現一次分塊上傳的流程：

• InitMultiUpload（生成一個UploadID）
• UploadPart
• UploadPart
• ……
• UploadPart
• CompleteMultiUpload（AbortMultiUpload）

之前在某個產品上線初期，由於其開發人員對NOS的熟悉程度不夠等原因。出現過如下問題：客戶端常常會收到NoSuchUpload的錯誤。該錯誤 出現的原因是，使用者在未呼叫InitMultiUpload之前，或者在呼叫了 CompleteMultiUpload（AbortMultiUpload）之後再次呼叫UploadPart。

然而當我們查日誌，希望可以看到該UploadPart請求對哪個UploadID進行操作，該UploadID又對應哪些操作時，卻發現我們的日誌中沒有記錄UploadPart請求對應的UploadID。

類似的問題還有很多，很多針對特定請求的日誌缺失，導致很多問題無法定位。

因此，需要進一步對日誌中需要記錄哪些內容進行規定，此處推薦的需要在日誌中記錄的內容有：

• 在系統啟動或初始化時記錄重要的系統初始化引數
• 記錄系統執行過程中的所有的錯誤
• 記錄系統執行過程中的所有的警告
• 在持久化資料修改時記錄修改前和修改後的值
• 記錄系統各主要模組之間的請求和響應（如在NOS中的影片處理模組在接收到請求和傳送應答時，或者向客戶端發送回呼請求時）
• 重要的狀態變化（如NOS中對系統白名單的修改等）
• 系統中一些長期執行的任務的執行進度

而不推薦記錄日誌的內容有：

• 函式入口資訊 —— 除非該函式入口表示了一個重要事件的開始，或者將該資訊記入DEBUG級別日誌
• 檔案內容或者一大段訊息的內容 —— 如果實在需要記錄，則可以擷取其中一些重要的資訊來記入日誌
• “良性”錯誤 —— 有時候雖然出現了錯誤，然而錯誤處理的流程可以正確解決這種情況，例如插入資料庫時有重覆的記錄，儘管是個錯誤，然而錯誤處理流程可以對這種情況進行處理

Rule 5：日誌資訊要準確全面，能做到僅憑日誌就可以定位問題

解決辦法：整理所有的請求處理流程，針對每一個操作（去重，分塊上傳……）列印特定的日誌。

6. 測試的日誌

測試程式碼（單元測試，介面測試……）的日誌同樣重要。特別是，當一個測試失敗時，可以透過日誌很快確定是測試程式碼有問題，還是系統出現了故障，如果做不到這一點，那就需要最佳化測試的日誌了。

測試日誌應該包含以下內容：

• 測試執行的環境
• 測試執行前的初始狀態
• 測試的詳細步驟
• 測試和系統的互動資訊
• 測試期望的傳回結果
• 測試實際的傳回結果

Rule 6：要以同樣嚴格的要求對待測試程式的日誌

7. 從問題中完善日誌

線上上出現問題的時候，需要儘快發現問題並解決，而同時，需要藉此機會好好思考一下當前系統的日誌是否合理。需要考慮以下問題：

• 如果定位問題花費了很長時間，那就說明系統日誌還存在問題，需要進一步完善和最佳化
• 需要思考是否可以透過最佳化日誌，來提前預判該問題是否可能發生（如某種資源耗盡而導致的錯誤，可以對資源的使用情況進行記錄）

透過系統出現的問題來最佳化日誌，應該是一項長期的實踐，不斷地從日誌發現系統的問題，不斷地從系統異常發現日誌的問題。

Rule 7：日誌的最佳化是一件持續不斷需要投入精力的事，需要不斷從錯誤中學習

8. 關於RequestID

RequestID的生成：

如今NOS有8臺機器，共40個tomcat對外提供服務。通常使用者在請求出錯的時候，我們都希望使用者告訴我們請求的RequestID，以此我們可以確定請求是在哪臺機器上進行處理的。

NOS透過以下資訊生成一個請求的RequestID：

• 收到請求的時間
• 處理請求的伺服器ip地址
• 隨機數

因此我們可以透過一個簡單的程式從RequestID中得到該請求的處理時間和處理請求的伺服器地址，更方便的去檢視日誌：

./decode.sh 4b2c009a0a7800000142789f42b8ca96

Thu Nov 21 11:06:12 CST 2013

10.120.202.150

4b2c009a

Rule 8：在RequestID中儘量編碼更多的資訊

用RequestID將請求的處理流程關聯起來：

在NOS效能測試中，之前存在的一個問題是，由於在列印錯誤堆疊的地方，並沒有列印請求的RequestID，因此當一個請求出現錯誤時，很難（日誌量太大）將該請求的錯誤堆疊和具體的請求關聯起來。

另一個問題是，NOS後端有影片伺服器叢集和圖片處理伺服器叢集。因此我們可能會有以下需求：當使用者影片截圖失敗時，使用者會告訴我們請求的 RequestID，由於NOS並沒有將該RequestID轉發到後端的圖片處理伺服器，因此無法利用該資訊去檢視影片處理伺服器上的日誌，而需要透過 使用者請求的URL進行查詢。同時，由於我們無法知道該請求是在哪個具體的影片處理的worker上進行，進一步導致查詢日誌的困難。

還有一個潛在的問題是：如果NOS將所有的日誌收集起來（tomcat，圖片處理叢集，影片處理叢集……），我們無法做到透過requestID來查詢一個請求的處理流程。

Rule 9：將一個請求的整個處理流程和唯一的requestID關聯起來

9. 關於線上機器的日誌級別

問題描述：

NOS的DEBUG日誌非常詳細的記錄了請求處理相關資訊，然而由於DEBUG日誌量太大，因此通常線上只開INFO級別日誌。然而INFO級別的 日誌卻有可能導致部分問題無法定位。NOS線上一個請求可能隨機地分發到4臺機器進行處理，因此如果某一種錯誤在一段時間內多次出現，它也會在4臺伺服器 上都出現。

因此我們推薦的做法是，選擇一臺機器開啟DEBUG級別的日誌，方便定位問題。其實該做法背後的目的是，線上上任何問題的時候，都可以透過日誌最快的找到問題的根源。

Rule 10：讓一臺機器開啟DEBUG日誌

10. 上線後的日誌觀察

隨著NOS開始服務越來越多的產品，NOS每次版本升級之後，透過對日誌的觀察來確定服務是否正常變得至關重要。同時在上線新功能時，來發人員需要透過觀察一些特定的日誌，來確定新功能是否工作正常。

舉例來說：

NOS在實現了桶錶快取的功能之後，首先上線一臺伺服器，並對該功能是否工作正常進行觀察。透過將桶快取的所有操作（如插入，查詢，過期刪除等）以 及桶快取的狀態（如快取桶數量）都記錄在DEBUG級別的日誌中。將新上線的機器的日誌級別調為DEBUG，並對桶快取的相關操作是否正確，快取桶數量等 資訊進行觀察，確認一切正常之後再上線其他機器。

Rule 11：新上線伺服器後一定要對日誌進行觀察，特別地，開發人員可以透過觀察日誌來確認新功能是否工作正常

11. 慢操作日誌

NOS在接收到一個請求的時候，會記錄請求的接收時間（T1），在請求處理完成待傳送的時候，會記錄請求傳送時間（T2），通常一個請求的日誌都記 為INFO級別，然而當出現請求處理時間（T2-T1）超過一定時間（如10s）時，會將該日誌提升為WARN級別。透過該方法，可以預先發現系統可能存 在的一些問題。

同樣的慢操作日誌還可以用來記錄系統一些外部依賴的處理時間，如NOS依賴外部認證伺服器來進行認證。我們會記錄每個請求的認證時間，如果認證時間超過某個值，也需要將該事件的日誌級別進行提升，這樣我們可以儘早發現認證伺服器是不是需要擴容等問題。

慢日誌的時間閥值應該是可以動態調整的，這樣在進行系統最佳化時，可以將該報警時間閥值逐漸調小，不斷地對系統進行最佳化。

Rule 12：透過日誌級別的提升來發現潛在問題

12. 日誌報警

錯誤日誌報警：

NOS透過[運維平臺|https://m.hz.netease.com/]設定了日誌監控報警，週期性的（1分鐘，5分鐘）對伺服器新產生的日 志進行監控，如果發現錯誤數超過某個閥值，則進行報警。這類報警通常不一定是我們服務本身的問題，也有可能是使用者使用NOS不當造成的。

此處需要註意的問題是，日誌報警相當於grep操作，如果日誌量過大，或者匹配規則過多，可能對線上的服務產生影響。因此在設定好日誌報警後，需要週期性的關註每次日誌掃描的時間，評估日誌監控是否對服務產生影響。

Rule 13：對日誌進行監控報警，比客戶先發現系統問題

關鍵字報警：

NOS為每個使用者分配了一定量的儲存配額，當使用者容量超限時，會限制使用者的上傳操作。透過在日誌中記錄關鍵字，如“Quota Warning”等，可以及時提醒使用者進行擴容，避免使用者服務中斷。

類似的關鍵字報警還有很多：如對InternalError的數量進行監控，對快取的桶數量進行監控等等。

Rule 14：透過日誌中的關鍵字來確定系統的執行狀態

13. 關於日誌格式

日誌格式一定要統一，不能任由開發人員的喜好來。舉例來說，對於NOS影片截圖超時的ERROR日誌，有以下幾種方式列印：

第一種：

logger.error(“Gearman timeout exception for request ” + getRequestID() + ” value: ” + value, e);

第二種：

logger.error(“RequestID: ” + getRequestID() + “, Error Message: Gearman timeout exception: ” + e);

第三種：

logger.error(getErrorMessage(getRequestID(), getErrorMessage(), e));

第一種方式列印日誌即是開發人員按照自己的喜好來的，這種方法帶來的問題是：

• 系統中日誌格式不統一，不利於自動化處理
• 有些日誌可能只有開發人員自己才能看懂
• 程式碼規範性不好

而第三種方式，透過一個函式來規範日誌格式，所有開發人員便可以透過該介面實現統一的日誌。

Rule 15：日誌格式要統一規範

14. 錯誤日誌輸出到不同檔案

在效能測試中遇到的另一個問題是，當併發量很大時，可能會有一些請求處理失敗（如0.5%），為了對這些錯誤進行分析，需要去查這些錯誤請求的日誌。而由於這種情況下併發量很大，使得對錯誤日誌的分析變得困難。

這種情況下可以將所有的錯誤日誌同時輸出到一個單獨的檔案之中。

Rule 16：將錯誤日誌輸出到一個單獨的檔案中進行分析

15. 關於日誌檔案大小

日誌檔案不宜過大，過大的日誌檔案對於日誌監控，問題定位等都會帶來不便。因此需要進行日誌檔案的切分，日誌檔案的切分可以透過log4j等日誌工具來配置，日誌檔案應該按天來分割，還是按照小時來分割，應該根據日誌量來決定，原則就是方便開發或運維人員能快速查詢日誌。

為了防止日誌檔案將整個磁碟空間佔滿，需要定期對日誌檔案進行刪除。例如，在收到磁碟報警時，可以將兩個月以前的日誌檔案刪除。此處比較好的實踐是：

• 將所有日誌檔案收集起來，這樣即使在記錄日誌的機器上刪除，也可以透過收集的日誌對之前的問題進行定位；
• 每天透過定時任務來刪除過期日誌，如每天在凌晨4點刪除60天前的日誌

Rule 17：要把日誌的大小，如何切分，如何刪除等作為規範建立起來

經驗彙總

此處對以上總結的所有經驗進行彙總：

• 整個團隊（包括運維人員）需要對日誌級別有明確的規定，什麼日誌記入什麼級別的日誌，什麼級別的錯誤出現要如何處理等
• 需要定期對日誌內容進行最佳化更新，目的就是透過日誌快速準確的定位問題
• 要明確不同日誌的用途，對日誌內容進行分類
• 絕不要列印沒有用的日誌，防止無用日誌淹沒重要資訊
• 日誌資訊要準確全面，努力做到僅憑日誌就可以定位問題
• 要以同樣嚴格的要求對待測試程式的日誌
• 日誌的最佳化是一件持續不斷需要投入精力的事，需要不斷從錯誤中學習
• 在RequestID中儘量編碼更多的資訊
• 將一個請求的整個處理流程和唯一的requestID關聯起來
• 讓一臺機器開啟DEBUG日誌
• 新上線伺服器後一定要對日誌進行觀察，特別地，開發人員可以透過觀察日誌來確認新功能是否工作正常
• 透過日誌級別的提升來發現潛在問題
• 對日誌進行監控報警，比客戶先發現系統問題
• 透過日誌中的關鍵字來確定系統的執行狀態
• 日誌格式要統一規範
• 將錯誤日誌輸出到一個單獨的檔案中進行分析
• 要把日誌的大小，如何切分，如何刪除等作為規範建立起來

參考文獻

[1] ”Optimal Logging” Anthony Vallone from Google