日誌最佳實踐

陳咬金發表於2022-04-07

近一年多以來想要分享知識的慾望降低了許多,不知道是否是近一年來工作較忙的原因,導致整個21年沒有對外輸出什麼內容,唯一的一篇 “Log4j2 Jndi 漏洞原理解析、覆盤” 還是在趁熱想抓波熱點的情況下寫的這篇文章(21年12月10號爆出漏洞、11號公司內修復、12號凌晨05:00趁熱釋出文章,釋出完以後直接埋頭睡了一天,現在想來簡直喪心病狂!)。

轉眼已經到了2022,覆盤2021的時候會發現並非如此,整個2021年是有做很多輸入的,但由於並沒有對外輸出,而只是將對應的內容簡單的記錄到了自己的筆記中,導致回頭再看時,會發現筆記中的很多內容並不系統,只是記錄了一個點的問題,而非面。

輸出是一個很好的習慣,輸入並輸出的過程也是在不斷的翻新自我知識體系的過程,在持續輸出的過程中,不僅幫助了自己也可能會幫助到他人。一舉多得。

所以,就用這篇來作為2022年部落格園的第一篇吧,GO,GO! (PS:該篇文章已經在筆記中躺了有段時間了、略微整理後,重新分享出來。)

背景

公司當前日誌平臺一天所沉澱的業務日誌有近600億條,40T左右的大小,隨著公司內降本增效的事項推進,再加上業務方業務日誌越來越多等問題,導致整個日誌平臺的資源是越發緊張的。

為了約束業務團隊的日誌數量,除了一些硬性的手段(日誌SDK端取樣、服務端取樣、成本平攤),以及通過一些硬性的指標,要求業務團隊的日誌條數鏈路比、日誌大小鏈路比 必須控制在一個合理的範圍內之外,還需要一些小的科普。

而這個科普便是這次內容的主題 “日誌最佳實踐”,目的是為了讓部分研發知曉:“噢,日誌原來也是要像程式碼一樣不斷優化的啊”。

前言

日誌用來記錄使用者操作、系統執行狀態等,是一個系統的重要組成部分。然而,由於日誌通常不屬於系統的核心功能,所以常常不被團隊成員所重視,在出現問題需要通過日誌來定位時,才發現日誌還存在很多問題;日誌記錄的好壞直接關係到系統出現問題時定位的速度,同時通過對日誌的監控和分析,可以提前發現系統可能的風險,避免線上事故的發生。

現階段我們的監控系統已經為我們的服務穩定性提供了較強的支撐,其中實時的異常大盤、日誌的異常告警、日誌的統一收集檢索以及日誌和鏈路的串聯等功能為我們在微服務體系下問題的診斷提供了快速的排查方案。但隨著時間的推移,程式碼中的日誌質量持續降低(當專案變大時,專案的程式碼也存在一樣的問題,越寫越亂)。隨著越來越多不規範的日誌開始出現,除了會增加監控系統的承壓,還會對線上的問題定位、穩定性監控等造成干擾。所以,日誌的優化則勢在必行,一方面監控系統降壓降本,另一方面增加線上服務的穩定性及故障快速定位的能力。

原創宣告:作者:陳咬金、 部落格地址:https://www.cnblogs.com/zh94/

日誌的分類

日誌從功能來說,可分為診斷日誌、統計日誌、審計日誌。
診斷日誌, 典型的有:

  • 請求入口和出口
  • 外部服務呼叫和返回
  • 資源消耗操作: 如讀寫檔案等
  • 容錯行為:如雲硬碟的副本修復操作
  • 程式異常: 如資料庫無法連線
  • 後臺操作:定期執行刪除的執行緒啟動、關閉、配置載入

統計日誌:

  • 使用者訪問統計:使用者IP、上傳下載的資料量,請求耗時等。(常用的Log Metric 則是統計日誌)

審計日誌:

  • 管理操作、系統安全事件、非法訪問記錄等

需要避免的日誌記錄方式

在寫程式碼的過程中,統計和審計日誌是帶有強烈目的性、功能性的,比如:使用者訪問統計的圖表,非法訪問的記錄等。

但是針對診斷日誌則不然,由於我們無法確定系統在具體哪行程式碼中會出現異常,所以診斷日誌的新增也就因人而異,不同研發的風格,喜歡在不同的程式碼處增加診斷日誌。

比如:有些研發同學喜歡在方法的入口處增加日誌,有些研發則是在可能會出現不確定性的判斷體中增加日誌。這些都沒問題,畢竟某塊程式碼哪裡最容易出現問題,最需要診斷日誌,這些只有具體的研發才知曉。

但是我們需要約束並避免的情況是:

1、日誌中不要記錄無用的資訊

如下圖中的服務日誌:單條日誌的長度已經超出了5000的長度,並已經觸發了服務端的日誌截斷操作。(既然是診斷日誌,應該是診斷該方法內的部分屬性,或者可能出現問題的屬性,而不應該是全部輸出)

2、不要記錄無用的日誌(不利於問題分析診斷的日誌)

如下圖中:日誌Msg為 “threadLocal進行清除”這段日誌,如果說這段日誌有沒有意義?“有的”,這段日誌表示 threadLocal被清除了,很直接明瞭。但是如果說這段日誌對問題的分析診斷有沒有作用?作用極小。

假設這裡 ThreadLocal remove() 的操作執行前是有 If 判斷,判斷為 true 時,則執行ThreadLocal 清除,那麼對應的日誌應該是新增到 else 程式碼塊中,如果判斷條件為 false,則 else 程式碼中輸出 WARN 日誌,或者 ERROR 日誌,表示此處存在風險或者異常需要進行關注,而不是在此處增加 INFO 日誌,告知對應的研發或者測試同學 “ThreadLocal 清除成功了”。

ThreadLocal remove() 這個程式碼塊被執行,是一個必然為真的操作,如果存在對應清除失敗的情況,應該最終是會體現在對應的異常當中。所以針對這樣一個必然為真的程式碼一定要增加對應的日誌,那麼最好的方式是調整日誌級別為DEBUG。

3、能夠放在一條日誌中的資訊,儘量放在一條日誌當中,而不要放在多條日誌中進行輸出。

4、日誌內容中不能包含敏感性資訊

原創宣告:作者:陳咬金、 部落格地址:https://www.cnblogs.com/zh94/

日誌的持續優化

理想中的日誌應該是不多不少的狀態,太多的資訊則是噪音,太少的資訊又不夠充分,我們需要在實際的運維過程中,結合線上問題的定位,不斷地進行優化。最關鍵的一點是,團隊要重視日誌優化這件事情,不要讓日誌的質量持續降低。

此處推薦如下幾個較好的實踐:

  • 在定位問題的過程中完善日誌,如果定位問題花費了很長時間,那就說明系統日誌還存在問題,需要進一步完善和優化;
  • 需要思考是否可以通過優化日誌,來提前預判該問題是否可能發生(如某種資源耗盡而導致的錯誤,可以對資源的使用情況進行記錄)
  • 定義好整個團隊記錄日誌的規範,保證每個開發記錄的日誌格式統一;特別需要說明的是,對於DEBUG/TRACE級別的日誌,也需要定義好清晰的格式,而不是由研發人員自由發揮;
  • 整個團隊(包括開發,運維和測試)定期對記錄的日誌內容進行Review;
  • 開發做運維、測試,通過在查問題的過程來優化日誌記錄的方式;
  • 測試在日誌中發現的問題,都需要及時向開發人員反映;

1、輸出日誌時要考慮日誌的使用者,例如如果日誌需要由系統的測試人員來看,那就不能輸出:

2022-03-01 14:08:16.244 WARN [http-nio-20959-exec-86] com.ymm.ability.IdentifyValidateAbility ErrorCode:1426

至少應該是:

2022-03-01 14:08:16.244 WARN [http-nio-20959-exec-86] com.ymm.ability.IdentifyValidateAbility ErrorCode:1426, Message: callback request (to http://example.com/callback) failed due to socket timeout

這樣測試人員一眼就能清楚問題的原因,而不需要再通過開發來檢視ErrorCode對應的具體錯誤。

2、日誌的記錄資訊要完整,尤其是針對異常的日誌而言,如:

  • 在持久化資料修改時記錄修改前和修改後的值。
  • 記錄關鍵引數,出錯時的關鍵原因等。
  • 記錄對應的異常程式碼執行前的上下文資訊。

關於日誌級別

  • 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)日誌來定位問題;

原創宣告:作者:陳咬金、 部落格地址:https://www.cnblogs.com/zh94/

INFO和DEBUG

瞭解了上述日誌級別的含義後,可能仍然會存在的一個問題是,INFO和DEBUG到底如何區分?我覺得這個日誌既可以是INFO也可以是DEBUG?如何處理?

此處簡單給出一些參考:

對於業務系統來說,INFO 日誌應該看起來像一本書。它應該告訴你發生了什麼,而不一定是如何發生的,比如:

INFO  | 傳送使用者註冊郵件通知。[user="Thomas", email="thomas@tuhrig.de"]
INFO  | 郵件傳送給使用者 [user="Thomas"]
INFO  | 傳送使用者取消關注郵件通知。[user="Thomas", email="thomas@tuhrig.de"]

而對於系統當中的技術細節,則通常更應該使用DEBUG日誌,DEBUG 日誌可以更詳細地瞭解該過程的工作方式

DEBUG | 將使用者資訊傳送進MQ通知列表。[user="Thomas", email="thomas@tuhrig.de"]
INFO  | 傳送使用者註冊通知 [user="Thomas", email="thomas@tuhrig.de"]
DEBUG | 開始傳送當天郵件通知的定時任務。 [subscribers=24332]
INFO  | 郵件傳送給使用者 [user="Thomas"]
INFO  | 傳送使用者取消關注郵件通知。 [user="Thomas", email="thomas@tuhrig.de"]

想象一下,你在瀏覽INFO日誌的時候,是在檢視該系統的執行狀態,此時看INFO日誌更關注的是系統的執行指標,而並非那些技術上的細節是否執行成功。對應的技術細節是否執行成功應該是體現在對應的DEBUG日誌當中,通過瀏覽DEBUG日誌以此來對系統的執行進行精確的記錄和診斷。

所以,類似於上面最初所提到的“ threadLocal 清除成功”這種日誌,如果有必須存在的意義,則應該是新增到DEBUG級別當中更為合適。

而對於技術類系統來說,比如中介軟體,工具類,公共服務等來說,INFO級別的日誌同樣應該是告訴你發生了什麼,而不是對應的技術細節。

比如:

  1. 遠端載入了對應的配置檔案,那麼此時 INFO 輸出該配置檔案的內容則沒有問題。
  2. JVM啟動成功後,會有一個INFO級別的 Started Application in 35.499 seconds (JVM running for 45.536) 來表示JVM啟動成功,但JVM是不會把類的載入過程 INFO 輸出出來,因為對於INFO日誌來說,並不關注這個。
  3. MVC的服務在服務啟動後,同樣會使用INFO級別的日誌,將載入成功的Controller介面輸出出來,而並不會通過INFO來告知使用方Controller的載入細節。
2022-03-01 15:18:03,553 INFO  [org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping] [main] Mapped "{[/nondestructive/release/health/check],methods=[POST],consumes=[application/json;charset=UTF-8],produces=[application/json;charset=UTF-8]}"

所以基於上述的一些內容,我們可以得到一些共性的認知,INFO級別的日誌更應該關注的是系統中發生了什麼較為重要的事件,需要讓日誌的檢視者關注到這些資訊。而不是技術的執行細節上執行了那些流程。執行細節應該是由DEBUG日誌來進行輸出。

所以對於線上下DEV和QA環境進行日誌診斷、問題排查時,應該更多的是檢視DEBUG日誌來進行問題的排查,而不應該過多的依賴 INFO 日誌。

對於線上環境則應該遮蔽掉DEBUG日誌的輸出,僅需要觀察INFO,WARN,ERROR日誌,來觀察服務的執行狀態。

在專案中日誌優化應該是比程式碼、架構優化更為頻繁的操作,我們應該隨著問題的排查來不斷的優化我們的日誌輸出。

同時,從日誌的功能分類上我們也可以得知,日誌的最重要的一個特性是:診斷日誌,我們在不斷優化日誌的同時,也是對自己專案深入診斷的過程,在優化診斷日誌的過程中,如果可以提前預判到某些問題的發生,如:連線池的耗盡,物件等資源的載入統計,而提前增加了診斷日誌。這將會對於我們後續故障時的問題定位有著非常好的參考作用。

參考資料

Log4j2 Articles and Tutorials
Logging best practices to get the most out of application level logging
The Art of Test Driven Development: Understanding Logging
中小企業運維需要重視日誌分析
王健:最佳日誌實踐

相關文章