15種最佳系統日志優化實踐
前言
日志用來記錄用戶操作、系統運行狀態等，是一個系統的重要組成部分。然而由于日志并非系統核心功能，通常情況下并不受團隊的重視。在出現問題需要通過日志來定位時，才發現日志還存在很多問題。 日志記錄的好壞直接關系到系統出現問題時定位的速度，同時可以通過對日志的觀察和分析，提前發現系統可能的風險，避免線上事故的發生。 我們在開發和運維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. 錯誤日志輸出到不同文件
在性能測試中遇到的另一個問題是，當并發量很大時，可能會有一些請求處理失?。ㄈ?.5%），為了對這些錯誤進行分析，需要去查這些錯誤請求的日志。而由于這種情況下并發量很大，使得對錯誤日志的分析變得困難。
這種情況下可以將所有的錯誤日志同時輸出到一個單獨的文件之中。
Rule 16：將錯誤日志輸出到一個單獨的文件中進行分析
15. 關于日志文件大小
日志文件不宜過大，過大的日志文件對于日志監控，問題定位等都會帶來不便。因此需要進行日志文件的切分，日志文件的切分可以通過log4j等日志工具來配置，日志文件應該按天來分割，還是按照小時來分割，應該根據日志量來決定，原則就是方便開發或運維人員能快速查找日志。
為了防止日志文件將整個磁盤空間占滿，需要定期對日志文件進行刪除。例如，在收到磁盤報警時，可以將兩個月以前的日志文件刪除。此處比較好的實踐是：
- 將所有日志文件收集起來，這樣即使在記錄日志的機器上刪除，也可以通過收集的日志對之前的問題進行定位；
- 每天通過定時任務來刪除過期日志，如每天在凌晨4點刪除60天前的日志
log4j關于日志切分的相關配置，可以參考這篇文章。
Rule 17：要把日志的大小，如何切分，如何刪除等作為規范建立起來
經驗匯總
此處對以上總結的所有經驗進行匯總：
- 整個團隊（包括運維人員）需要對日志級別有明確的規定，什么日志記入什么級別的日志，什么級別的錯誤出現要如何處理等
- 需要定期對日志內容進行優化更新，目的就是通過日志快速準確的定位問題
- 要明確不同日志的用途，對日志內容進行分類
- 絕不要打印沒有用的日志，防止無用日志淹沒重要信息
- 日志信息要準確全面，努力做到僅憑日志就可以定位問題
- 要以同樣嚴格的要求對待測試程序的日志
- 日志的優化是一件持續不斷需要投入精力的事，需要不斷從錯誤中學習
- 在RequestID中盡量編碼更多的信息
- 將一個請求的整個處理流程和唯一的requestID關聯起來
- 讓一臺機器開啟DEBUG日志
- 新上線服務器后一定要對日志進行觀察，特別地，開發人員可以通過觀察日志來確認新功能是否工作正常
- 通過日志級別的提升來發現潛在問題
- 對日志進行監控報警，比客戶先發現系統問題
- 通過日志中的關鍵字來確定系統的運行狀態
- 日志格式要統一規范
- 將錯誤日志輸出到一個單獨的文件中進行分析
- 要把日志的大小，如何切分，如何刪除等作為規范建立起來
參考文獻
[1] ”Optimal Logging” Anthony Vallone from Google
http://googletesting.blogspot.jp/2013/06/optimal-logging.html
