前言

日志用來記錄用戶操作、系統(tǒng)運行狀態(tài)等，是一個系統(tǒng)的重要組成部分。然而由于日志并非系統(tǒng)核心功能，通常情況下并不受團隊的重視。在出現(xiàn)問題需要通過日志來定位時，才發(fā)現(xiàn)日志還存在很多問題。

日志記錄的好壞直接關系到系統(tǒng)出現(xiàn)問題時定位的速度，同時可以通過對日志的觀察和分析，提前發(fā)現(xiàn)系統(tǒng)可能的風險，避免線上事故的發(fā)生。

我們在開發(fā)和運維NOS（網(wǎng)易對象存儲，Netease Object Storage）的過程中，對整個系統(tǒng)的日志進行了分析優(yōu)化，積累出一些經(jīng)驗，歸納如下。

相關問題經(jīng)驗整理

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級別的定義應該是清楚明確的，是每個開發(fā)人員所遵循的；
• 即使是TRACE或者DEBUG級別的日志，也應該有一定的規(guī)范，要保證除了開發(fā)人員自己以外，包括測試人員和運維人員都可以方便地通過日志定位問題；
• 對于日志級別的分類，有以下參考：
  FATAL — 表示需要立即被處理的系統(tǒng)級錯誤。當該錯誤發(fā)生時，表示服務已經(jīng)出現(xiàn)了某種程度的不可用，系統(tǒng)管理員需要立即介入。這屬于最嚴重的日志級別，因此該日志級 別必須慎用，如果這種級別的日志經(jīng)常出現(xiàn)，則該日志也失去了意義。通常情況下，一個進程的生命周期中應該只記錄一次FATAL級別的日志，即該進程遇到無 法恢復的錯誤而退出時。當然，如果某個系統(tǒng)的子系統(tǒng)遇到了不可恢復的錯誤，那該子系統(tǒng)的調(diào)用方也可以記入FATAL級別日志，以便通過日志報警提醒系統(tǒng)管 理員修復；
  ERROR — 該級別的錯誤也需要馬上被處理，但是緊急程度要低于FATAL級別。當ERROR錯誤發(fā)生時，已經(jīng)影響了用戶的正常訪問。從該意義上來說，實際上 ERROR錯誤和FATAL錯誤對用戶的影響是相當?shù)?。FATAL相當于服務已經(jīng)掛了，而ERROR相當于好死不如賴活著，然而活著卻無法提供正常的服 務，只能不斷地打印ERROR日志。特別需要注意的是，ERROR和FATAL都屬于服務器自己的異常，是需要馬上得到人工介入并處理的。而對于用戶自己 操作不當，如請求參數(shù)錯誤等等，是絕對不應該記為ERROR日志的；
  WARN — 該日志表示系統(tǒng)可能出現(xiàn)問題，也可能沒有，這種情況如網(wǎng)絡的波動等。對于那些目前還不是錯誤，然而不及時處理也會變?yōu)殄e誤的情況，也可以記為WARN日 志，例如一個存儲系統(tǒng)的磁盤使用量超過閥值，或者系統(tǒng)中某個用戶的存儲配額快用完等等。對于WARN級別的日志，雖然不需要系統(tǒng)管理員馬上處理，也是需要 即使查看并處理的。因此此種級別的日志也不應太多，能不打WARN級別的日志，就盡量不要打；
  INFO — 該種日志記錄系統(tǒng)的正常運行狀態(tài)，例如某個子系統(tǒng)的初始化，某個請求的成功執(zhí)行等等。通過查看INFO級別的日志，可以很快地對系統(tǒng)中出現(xiàn)的 WARN,ERROR,FATAL錯誤進行定位。INFO日志不宜過多，通常情況下，INFO級別的日志應該不大于TRACE日志的10%；
  DEBUG or TRACE — 這兩種日志具體的規(guī)范應該由項目組自己定義，該級別日志的主要作用是對系統(tǒng)每一步的運行狀態(tài)進行精確的記錄。通過該種日志，可以查看某一個操作每一步的執(zhí) 行過程，可以準確定位是何種操作，何種參數(shù)，何種順序導致了某種錯誤的發(fā)生?？梢员ＷC在不重現(xiàn)錯誤的情況下，也可以通過DEBUG（或TRACE）級別的 日志對問題進行診斷。需要注意的是，DEBUG日志也需要規(guī)范日志格式，應該保證除了記錄日志的開發(fā)人員自己外，其他的如運維，測試人員等也可以通過 DEBUG（或TRACE）日志來定位問題；

Rule 1：整個團隊（包括運維人員）需要對日志級別有明確的規(guī)定，什么日志記入什么級別的日志，什么級別的錯誤出現(xiàn)要如何處理等

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

由于DEBUG（或TRACE）級別的日志對于定位問題至關重要，因此該種日志記錄是否完備且不冗余、格式是否規(guī)范等也需要花費大量精力來優(yōu)化。此處有以下幾個比較好的實踐：

• 定義好整個團隊記錄DEBUG（或TRACE）日志的規(guī)范，保證每個開發(fā)記錄的日志格式統(tǒng)一；
• 整個團隊（包括開發(fā)，運維和測試）定期對記錄的日志內(nèi)容進行Review；
• 開發(fā)做運維，通過在查問題的過程來優(yōu)化日志記錄的方式；
• 運維或測試在日志中發(fā)現(xiàn)的問題，都需要及時向開發(fā)人員反映；

Rule 2：需要定期對日志內(nèi)容進行優(yōu)化更新，目的就是通過日志快速準確的定位問題

3. 關于日志分類

日志從功能來說，可分為診斷日志、統(tǒng)計日志、審計日志。

診斷日志， 典型的有：

• 請求入口和出口
• 外部服務調(diào)用和返回
• 資源消耗操作: 打開文件等
• 容錯行為： 譬如云硬盤的副本修復操作
• 程序異常： 譬如數(shù)據(jù)庫無法連接
• 后臺操作：清理程序
• 啟動、關閉、配置加載
• 拋出異常時，不記錄日志

統(tǒng)計日志：

• 用戶訪問統(tǒng)計
• 計費日志（如記錄用戶使用的網(wǎng)絡資源或磁盤占用，格式較為嚴格，便于統(tǒng)計）

審計日志：

• 管理操作

將不同需求的日志記入到不同的日志文件中，可以方便相關問題（管理平臺操作審計，用戶操作計費等）的處理。針對每一種需求，需要對日志的格式，日志記錄的內(nèi)容等進行特別的記錄。

Rule 3：要明確不同日志的用途，對日志內(nèi)容進行分類

4. 日志中不要記錄無用信息

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

POSIX標準中文件系統(tǒng)接口不允許文件 /a 與目錄 /a/ 同時存在，而NOS作為對象存儲系統(tǒng)，/a 和 /a/是不同的對象，是能夠同時存在的，一般地，NOS 中我們會規(guī)定 /a/ 是目錄，/a 是文件，目錄對象大小為0。

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

因此當用戶訪問 */a/b/c.txt* 時，實際上向NOS發(fā)送了以下請求：
# HeadObject(“/a”)
# HeadObject(“/a/”)
# HeadObject(“/a/b”)
# HeadObject(“/a/b/”)
# HeadObject(“/a/b/c.txt”)

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

然而對于NOS來說，這將導致產(chǎn)生大量無意義的NoSuchKey日志（整個日志文件的80%都是該錯誤日志）。這些日志對于開發(fā)人員進行日志觀察，運維人員定位問題，日志監(jiān)控等都造成了困難。

Rule 4: 絕不要打印沒有用的日志，防止無用日志淹沒重要信息

解決辦法：Fuse請求時，在Http頭部加入 User-Agent 字段，當NOS發(fā)現(xiàn)請求是 Fuse發(fā)過來的且為HeadObject操作且為NoSuchKey錯誤時，則不打印錯誤日志。

5. 日志記錄信息要完整

問題描述：

NOS提供分塊上傳的接口，用戶可以通過以下的調(diào)用序列，來實現(xiàn)一次分塊上傳的流程：

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

之前在某個產(chǎn)品上線初期，由于其開發(fā)人員對NOS的熟悉程度不夠等原因。出現(xiàn)過如下問題：客戶端常常會收到NoSuchUpload的錯誤。該錯誤 出現(xiàn)的原因是，用戶在未調(diào)用InitMultiUpload之前，或者在調(diào)用了 CompleteMultiUpload（AbortMultiUpload）之后再次調(diào)用UploadPart。

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

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

因此，需要進一步對日志中需要記錄哪些內(nèi)容進行規(guī)定，此處推薦的需要在日志中記錄的內(nèi)容有：

• 在系統(tǒng)啟動或初始化時記錄重要的系統(tǒng)初始化參數(shù)
• 記錄系統(tǒng)運行過程中的所有的錯誤
• 記錄系統(tǒng)運行過程中的所有的警告
• 在持久化數(shù)據(jù)修改時記錄修改前和修改后的值
• 記錄系統(tǒng)各主要模塊之間的請求和響應（如在NOS中的視頻處理模塊在接收到請求和發(fā)送應答時，或者向客戶端發(fā)送回調(diào)請求時）
• 重要的狀態(tài)變化（如NOS中對系統(tǒng)白名單的修改等）
• 系統(tǒng)中一些長期執(zhí)行的任務的執(zhí)行進度

而不推薦記錄日志的內(nèi)容有：

• 函數(shù)入口信息 —— 除非該函數(shù)入口表示了一個重要事件的開始，或者將該信息記入DEBUG級別日志
• 文件內(nèi)容或者一大段消息的內(nèi)容 —— 如果實在需要記錄，則可以截取其中一些重要的信息來記入日志
• “良性”錯誤 —— 有時候雖然出現(xiàn)了錯誤，然而錯誤處理的流程可以正確解決這種情況，例如插入數(shù)據(jù)庫時有重復的記錄，盡管是個錯誤，然而錯誤處理流程可以對這種情況進行處理

Rule 5：日志信息要準確全面，能做到僅憑日志就可以定位問題

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

6. 測試的日志

測試代碼（單元測試，接口測試……）的日志同樣重要。特別是，當一個測試失敗時，可以通過日志很快確定是測試代碼有問題，還是系統(tǒng)出現(xiàn)了故障，如果做不到這一點，那就需要優(yōu)化測試的日志了。

測試日志應該包含以下內(nèi)容：

• 測試執(zhí)行的環(huán)境
• 測試執(zhí)行前的初始狀態(tài)
• 測試的詳細步驟
• 測試和系統(tǒng)的交互信息
• 測試期望的返回結果
• 測試實際的返回結果

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

7. 從問題中完善日志

在線上出現(xiàn)問題的時候，需要盡快發(fā)現(xiàn)問題并解決，而同時，需要借此機會好好思考一下當前系統(tǒng)的日志是否合理。需要考慮以下問題：

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

通過系統(tǒng)出現(xiàn)的問題來優(yōu)化日志，應該是一項長期的實踐，不斷地從日志發(fā)現(xiàn)系統(tǒng)的問題，不斷地從系統(tǒng)異常發(fā)現(xiàn)日志的問題。

Rule 7：日志的優(yōu)化是一件持續(xù)不斷需要投入精力的事，需要不斷從錯誤中學習

8. 關于RequestID

RequestID的生成：

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

NOS通過以下信息生成一個請求的RequestID：

• 收到請求的時間
• 處理請求的服務器ip地址
• 隨機數(shù)

因此我們可以通過一個簡單的程序從RequestID中得到該請求的處理時間和處理請求的服務器地址，更方便的去查看日志：

./decode.sh 4b2c009a0a7800000142789f42b8ca96 
 Thu Nov 21 11:06:12 CST 2013 
 10.120.202.150 
 4b2c009a 

Rule 8：在RequestID中盡量編碼更多的信息。

用RequestID將請求的處理流程關聯(lián)起來：

在NOS性能測試中，之前存在的一個問題是，由于在打印錯誤堆棧的地方，并沒有打印請求的RequestID，因此當一個請求出現(xiàn)錯誤時，很難（日志量太大）將該請求的錯誤堆棧和具體的請求關聯(lián)起來。

另一個問題是，NOS后端有視頻服務器集群和圖片處理服務器集群。因此我們可能會有以下需求：當用戶視頻截圖失敗時，用戶會告訴我們請求的 RequestID，由于NOS并沒有將該RequestID轉發(fā)到后端的圖片處理服務器，因此無法利用該信息去查看視頻處理服務器上的日志，而需要通過 用戶請求的URL進行查找。同時，由于我們無法知道該請求是在哪個具體的視頻處理的worker上進行，進一步導致查找日志的困難。

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

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

9. 關于線上機器的日志級別

問題描述：

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

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

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

10. 上線后的日志觀察

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

舉例來說：

NOS在實現(xiàn)了桶表緩存的功能之后，首先上線一臺服務器，并對該功能是否工作正常進行觀察。通過將桶緩存的所有操作（如插入，查找，過期刪除等）以 及桶緩存的狀態(tài)（如緩存桶數(shù)量）都記錄在DEBUG級別的日志中。將新上線的機器的日志級別調(diào)為DEBUG，并對桶緩存的相關操作是否正確，緩存桶數(shù)量等 信息進行觀察，確認一切正常之后再上線其他機器。

Rule 11：新上線服務器后一定要對日志進行觀察，特別地，開發(fā)人員可以通過觀察日志來確認新功能是否工作正常

11. 慢操作日志

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

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

慢日志的時間閥值應該是可以動態(tài)調(diào)整的，這樣在進行系統(tǒng)優(yōu)化時，可以將該報警時間閥值逐漸調(diào)小，不斷地對系統(tǒng)進行優(yōu)化。

Rule 12：通過日志級別的提升來發(fā)現(xiàn)潛在問題

12. 日志報警

錯誤日志報警：

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

此處需要注意的問題是，日志報警相當于grep操作，如果日志量過大，或者匹配規(guī)則過多，可能對線上的服務產(chǎn)生影響。因此在設置好日志報警后，需要周期性的關注每次日志掃描的時間，評估日志監(jiān)控是否對服務產(chǎn)生影響。

Rule 13：對日志進行監(jiān)控報警，比客戶先發(fā)現(xiàn)系統(tǒng)問題

關鍵字報警：

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

類似的關鍵字報警還有很多：如對InternalError的數(shù)量進行監(jiān)控，對緩存的桶數(shù)量進行監(jiān)控等等。

Rule 14：通過日志中的關鍵字來確定系統(tǒng)的運行狀態(tài)

13. 關于日志格式

日志格式一定要統(tǒng)一，不能任由開發(fā)人員的喜好來。舉例來說，對于NOS視頻截圖超時的ERROR日志，有以下幾種方式打?。?/p>

***種：
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));

***種方式打印日志即是開發(fā)人員按照自己的喜好來的，這種方法帶來的問題是：

• 系統(tǒng)中日志格式不統(tǒng)一，不利于自動化處理
• 有些日志可能只有開發(fā)人員自己才能看懂
• 代碼規(guī)范性不好

而第三種方式，通過一個函數(shù)來規(guī)范日志格式，所有開發(fā)人員便可以通過該接口實現(xiàn)統(tǒng)一的日志。

Rule 15：日志格式要統(tǒng)一規(guī)范

14. 錯誤日志輸出到不同文件

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

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

Rule 16：將錯誤日志輸出到一個單獨的文件中進行分析

15. 關于日志文件大小

日志文件不宜過大，過大的日志文件對于日志監(jiān)控，問題定位等都會帶來不便。因此需要進行日志文件的切分，日志文件的切分可以通過log4j等日志工具來配置，日志文件應該按天來分割，還是按照小時來分割，應該根據(jù)日志量來決定，原則就是方便開發(fā)或運維人員能快速查找日志。

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

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

log4j關于日志切分的相關配置，可以參考這篇文章。

Rule 17：要把日志的大小，如何切分，如何刪除等作為規(guī)范建立起來

經(jīng)驗匯總

此處對以上總結的所有經(jīng)驗進行匯總：

• 整個團隊（包括運維人員）需要對日志級別有明確的規(guī)定，什么日志記入什么級別的日志，什么級別的錯誤出現(xiàn)要如何處理等
• 需要定期對日志內(nèi)容進行優(yōu)化更新，目的就是通過日志快速準確的定位問題
• 要明確不同日志的用途，對日志內(nèi)容進行分類
• 絕不要打印沒有用的日志，防止無用日志淹沒重要信息
• 日志信息要準確全面，努力做到僅憑日志就可以定位問題
• 要以同樣嚴格的要求對待測試程序的日志
• 日志的優(yōu)化是一件持續(xù)不斷需要投入精力的事，需要不斷從錯誤中學習
• 在RequestID中盡量編碼更多的信息
• 將一個請求的整個處理流程和唯一的requestID關聯(lián)起來
• 讓一臺機器開啟DEBUG日志
• 新上線服務器后一定要對日志進行觀察，特別地，開發(fā)人員可以通過觀察日志來確認新功能是否工作正常
• 通過日志級別的提升來發(fā)現(xiàn)潛在問題
• 對日志進行監(jiān)控報警，比客戶先發(fā)現(xiàn)系統(tǒng)問題
• 通過日志中的關鍵字來確定系統(tǒng)的運行狀態(tài)
• 日志格式要統(tǒng)一規(guī)范
• 將錯誤日志輸出到一個單獨的文件中進行分析
• 要把日志的大小，如何切分，如何刪除等作為規(guī)范建立起來

參考文獻

[1]  ”Optimal Logging” Anthony Vallone from Google

http://googletesting.blogspot.jp/2013/06/optimal-logging.html