日誌列印的碎碎念總結

bmilk發表於2023-02-17

眾所周知，日子作為最強的甩鍋神器，合理合適的記錄日誌就是一個問題。今天我想總結下我對日誌的看法

1、有意義的日誌資訊——為日誌訊息新增上下文

寫這一行日誌的時候思考下，生產出現異常的時候，這一行日誌是否能提供有效的幫助去解決問題

這是最重要，也是最難做到的一個總結。在處理問題的時候，尤其是難以復現的問題，能協助處理問題的就只有日誌檔案，開發人員必須能從中瞭解到當時發生了什麼！

當開發人員看到日誌時，通常會根據日誌推斷問題發生時的上下文訊息，不幸的時候日誌本身並沒有這個上下文，因此需要開發者手動將這些資訊補充到日誌中，如果不能也可加入操作的目的或者結果，便於理解。

比如ERROR: save error - SQL Excepetion這條日誌，當你排查問題的時候價值幾乎為0，除了知道時SQL執行出錯外，沒有任何資訊。更好，更有用的資訊應該是這樣ERROR: save error, data com.xxx.Cat(name = name, age=1) - SQL Excepetion,其中解釋了Cat是一個類，並且記錄了對應示例的相關內容，注意是相關內容，而不是全部，無用的資訊應該被去除，避免一些無用資訊混淆日誌檔案。

2、儘可能使用英文記錄日誌

英文可能沒有中文讀起來方便，但是英文依然是記錄日誌最好的語言，沒有之一，原因如下：

  • 無法預知日誌訊息的內容以及他將被歸檔在何地，以何種方式被開啟。英文將以ASCII字元被記錄，如果日誌訊息使用特殊字符集乃至UTF-8，當被閱讀者開啟的時候都有可能無法正確呈現。並且還可能存在使用者的輸入採用不同的字符集或者編碼的問題
  • 國際化。如果不確定程式的使用者是誰，那麼英文會是最好的選擇。

3、選擇合適的記錄工具

猶記得在我剛開始寫程式碼的時候，為了記錄日誌資訊使用了System.out.println()，儘管這個解決了問題，但是這是一個非常愚蠢的方式。缺點數不勝數。
儘管java生態種提供了諸如Log4j、JCL、slf4j 和 logback等諸多第三方日誌框架，但請儘量使用slf4j的門面模式來記錄，有利於維護和各個類的日誌處理方式統一，並且可以在保證不修改程式碼的情況下，很方便的實現底層日誌框架的更換。

4、不要寫的太多但更不能太少

這句話聽起來似乎很矛盾，但我們確實應該平衡日誌的數量。試想在凌晨3點，你要在漫天日誌中尋找問題的根源，如果被大量日誌混亂你的思路這並不是一件好事。但如果日誌太少，找不到問題根源，這更是一個問題。

到底多少合適，沒有一個準確的數字，有一個解決思路是，前期可以多打日誌，功能上線後，對日誌進行分析，並根據問題的減少而減少日誌，或者補上缺失的日誌

5、在合適的地方記錄日誌

看這個標題，如果問我什麼是合適的地方，我也不知道，但是如果從日誌的用出來看，那將會有一些答案

  • 遠端呼叫或者第三方API開始與結束：眾所周知，日誌可以作為一個甩鍋利器，當對方告訴你他做了什麼而你認為沒有或者不對的時候,日誌就是最有力的證據
  • 系統API開始與結束：這塊就是自己系統的大門，誰來都得留下影子，別人說沒給的時候，這裡同樣也是證據。另外在日誌排錯、效能分析、鏈路追蹤方面很有幫助
  • 異常塊：所有捕獲的異常軍應該記錄異常內容
  • 應用的啟動、停止日誌
  • 其他日誌：可以根據業務需要，記錄相應的日誌，比如某些SQL查詢的結果

6、在合適的環境使用合適的日誌等級

java生態種可以使用的日誌框架都有日誌級別的概念，常見的日誌級別如下：

  • DEBUG：主要輸出除錯性質的內容，該級別的日誌主要用於在開發、測試階段輸出，該級別的日誌應儘可能的詳細，比如各類除錯資訊、輸入輸出資訊等等。
  • INFO：業務系統記錄日誌的關鍵資訊。開發可以將初始化系統配置，業務狀態變化資訊、流程核心記錄到這個幾倍種，方便運維工作及錯誤回溯時上下問場景復現
  • WARN：主要輸出警告性質的內容，該內容是可以預知，並且有規劃的，比如樂觀鎖更新失敗、方法空參等等
  • ERROR：主要針對一些不可預知的、對應用影響打的錯誤、異常資訊。比如catch程式碼塊抓取的資料通訊異常、檔案異常。在輸出ERROR級別的日誌時，儘量的多輸入方法引數，方法過程中產生的物件、錯誤、異常物件資料。

不同的環境應當使用不同日誌級別，這樣可以過濾掉級別過低的訊息我通常使用的配置如下：
-生產：自己編寫的程式碼的Info級別和第三方庫的warn級別
-開發、測試：自己編寫的程式碼的debug級別和第三方庫的warn級別

7、在提交之前刪除僅僅提供幫助功能的日誌程式碼

在開發、測試期間，通常會列印很多的日誌來記錄應用過程中發生了什麼，比如：

public void method(String str){
    log.info("method start, str{}", str);
    if("NO".equals(str)){
        log.debug("the param is no");
        // do other
    }
}

這些日誌的主要目的是透過顯示的呼叫及內部的方法數值來跟蹤程式的行為，但是當這些程式碼釋出後，log.debug("the param is no");將沒有什麼意義。所以在開發完成後，在程式碼合併到發版分支之前應當刪除不必要的日誌資訊

8、瞭解日誌框架的核心選取合適的日誌字串構造方式

選取不合適日誌字串構造方式可能會導致額外的開銷，比如下面的兩行程式碼

log.debug(String.formt("name=%s, age=%s", "test", 1));
log.debug("name={}, age={}", "test", 1);

這兩行程式碼的最後日誌輸出都是：

name=test, age=1

但是當日誌輸出級別為INFO的時候卻有巨大的時效差距。

  • 當使用第一種方式構造日誌物件時，會先生成字串name=test, age=1， 並傳參給log.debug()函式，之後判斷出日誌輸出級別為INFO，不再輸出日誌。
  • 使用第二種方式的時候，會先判斷是INFO級別的日誌輸出，從而減少了構造字串的時間。

關於SLF4J的構造方式可以參考https://www.slf4j.org/faq.html#logging_performance

9、 程式可以理解的日誌

我對日誌的要求第一要義是解決生產問題，所以一定是要人能讀懂的日誌。但有時對於大量的日誌，我們需要自動化指令碼進行批處理，那麼我們就需要程式能夠理解。

假設有這樣一行語句

log.info("User {} plays {} in game {}", userId, card, gameId);

他將產生這樣的文字

2013-01-12 17:49:37,656 [T1] INFO  c.d.g.UserRequest  User 1334563 plays 4 of spades in game 23425656

如果想要進行解析，正規表示式可能會是這樣(沒有驗證)/User (d+) plays (.+?) in game (d+)$/
這樣很容易出錯，玩意使用者就叫play怎麼辦呢？

我們可以將語句改成這樣

log.info("User [{}] plays [{}] in game [{}]", userId, card, gameId);

所有的引數值都放在[]之間，這樣就能更好的讓程式分析程式碼

10、符合法律法規

基於各國、各行業的法律法規，不要列印使用者的敏感資訊，例如：銀行卡號、身份證號、手機號

參考檔案：
[1] The 5 Java logging rules
[2] Logging Best Practices: The 13 You Should Know
[3] logging_performance
[4] 日誌粒度總結

相關文章