技術文章 » 紀錄檔列印的碎碎念總結

紀錄檔列印的碎碎念總結

2023-02-17 18:01:52

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

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

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] 紀錄檔粒度總結