歡迎光臨
每天分享高質量文章

最佳日誌實踐

作者:王健

網址: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

赞(0)

分享創造快樂