記錄日誌有哪些好的技巧?
一、簡介
在軟體開發中,我們出於各種目的,需要將程式執行中的一些狀態記錄在日誌中。
日誌記錄,並不是越多越好,也不是記錄的越頻繁越好,而是需要我們精心設計記錄日誌的時機、內容、格式(以方便後續解析、查詢日誌)等等。
本文簡單介紹了記錄日誌的一些基本原則和注意事項,更具體的記日誌的技巧、最佳實踐、日誌框架等請參考子文件ofollow,noindex">Go如何記錄日誌 。
二、記錄日誌的目的(why)
開發除錯
目的是開發期除錯程式使用,這種日誌量比較大,且沒有什麼實質性的意義,只應該出現在開發期,而不應該在專案上線之後輸出。
記錄使用者行為
這種型別的日誌,記錄使用者的操作行為,用於大資料分析,比如監控、風控、推薦等等。這種日誌,一般是給其他團隊分析使用,而且可能是多個團隊,因此一般會有一定的格式要求,開發者應該按照這個格式來記錄,便於其他團隊的使用。當然,要記錄哪些行為、操作,一般也是約定好的,因此,開發者主要是執行的角色。
程式執行狀況
記錄程式的執行狀況,特別是非預期的行為、異常情況,這種日誌,主要是給開發、維護人員使用。什麼時候記錄,記錄什麼內容,完全取決於開發人員,開發者具有高度自主性。本文討論的主要也是指這種型別的日誌,因為作為一個服務端開發、運維人員,程式執行日誌往往是解決線上問題的救命稻草。
系統、機器狀況
比如網路請求、系統CPU、記憶體、IO使用情況等等,這種日誌主要是給運維人員使用,生成各種更直觀的展現形式,在系統出問題的時候報警。
三、日誌的要素(what)
每條日誌都可以被當作一個事件(event),紀錄了該事件發生時各個資訊:
時間
日誌的時間可以包含多種含義,不同含義的時間傳遞不同的資訊:
- 指事件發生的時間,而不是日誌被列印的時間。該時間附近範圍內,結合該事件及伺服器的網路、CPU、IO等狀況,可以瞭解他們之間的相關性,有助於分析事件發生的原因。
- 持續時間。例如網路請求的耗時、處理請求的各個階段的耗時等。
- 事件發生的順序。通過時間戳的順序,瞭解到一系列事件的發生順序。對多程序、多執行緒、分散式系統有幫助。
位置
事件發生在哪個模組、哪個檔案、哪個函式、哪一行程式碼裡。
級別
日誌的重要程度。用於:
- 不同的環境(測試、生產)下,列印不同級別的日誌
- 不同級別的日誌產生不同級別的監控報警
內容
簡明扼要的描述發生了什麼樣的事情。目的是通過日誌本身,而不是重新閱讀相關程式碼來搞清楚發生了什麼事情。
例如:logger.warn('user_login failed due to unvalid_username')
唯一標識
不管是面向使用者的服務、面向機器叢集的服務,都需要一個唯一標識作為日誌的主體,以方便查詢該事件主體的其他資訊。(很多元資料是不會記在日誌裡的,只會記一個唯一標識)
例如:logger.warn('user_login failed due to password, username %s', username)
事件上下文
除了時間、位置、級別、內容,其他的一些有用的資訊。
例如:
- logger.warn('user_login failed due to wrong password, username %s', username)
- logger.warn('user_login failed due to invalid password, username %s', username)
-
logger.warn('user_login failed due to
empty
password, username %s', username)
為了獲取更豐富的上下文,有些資料需要從 Nginx 那裡獲取並傳給本服務,然後列印。參考:和日誌相關的Nginx設定
格式化
將上述的各個資訊按照固定的順序打印出來,不僅方便查詢(例如使用grep,sed,awk等),也方便收集日誌的程式(ES)解析日誌。
其他
根據各自的業務特點,還可以在日誌中記錄(包括、不限於):
- 錯誤次數
- 當前正在處理的請求數
- 處理的進度(33%,50%,78%。。。)
- IP
- 問題出現時的請求連結
四、記錄日誌的一些原則和技巧
使用框架或模組
Java :Log4j 、Log4j2 、Commons Logging 、Slf4j 、Logback
Python 內建的 logging 模組
beego 框架裡的 github.com/astaxie/beego/logs 模組
其他的一些Go的框架:
- Logrus:github.com/Sirupsen/logrus (Docker use this)
- github.com/op/go-logging
- github.com/golang/glog (from Google, implementation of their C++ glog library in Go)
- github.com/cihub/seelog
不能出錯
記錄日誌的目的是為了方便發現問題,解決問題,那麼就需要保證記錄日誌本身不能出錯。
尤其是對於 Error、Fatal級別的日誌,出現的概率低,所以要做好單元測試,以保證記錄日誌本身是沒問題的,是不會影響正常業務的。
避免敏感資訊
- 避免記錄使用者密碼。
- 避免記錄使用者個人資訊,如身份證號、手機號等。應該只在日誌裡記錄該使用者的唯一標識,然後根據該唯一標識去其他的系統(例如資料庫)檢視詳細資訊。
記錄“不可能發生”的事件
雖然正常邏輯下,某些情況是永遠都不可能發生的,但是還是需要給這些不可能發生的情況列印一條日誌。
例如 條件語句裡的 else,switch 裡的 default,都需要進行防禦式的程式設計,同時記錄日誌。
Lazy logging
日誌本身是一個字串,可以通過多種方式拼接而成。如果根據log level,該條日誌不應被列印,那麼就應該 避免 拼接這個操作,也應該 避免 字串拼接裡的函式的呼叫。
例如:
#coding=utf-8 import logging logger = logging.getLogger('LazyLogging') logger.setLevel(logging.DEBUG) hander = logging.StreamHandler() formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s') hander.setFormatter(formatter) logger.addHandler(hander) def getUserCount(): logger.info('getUserCount is called') return 1 logger.debug("There are " + str(getUserCount()) + " users logged in now.")
- log level 設定為 DEBUG(第5行),那麼會先列印第12行,再列印第15行
-
log level 設定為 INFO,依然會列印第12行,說明:
- 問題1: 即便沒有列印第15行,依然生成了一個字串
- 問題2: 而且呼叫了 getUserCount 這個函式
- 解決上述的問題1,可以把第15行修改為:
logger.debug("There are %s users logged in now.", getUserCount())
- 為了解決上述的問題2,一個辦法是:
class lazyEval: def __init__(self, f, *args): self.func = f self.args = args def __str__(self): return str(self.func(*self.args)) logger.debug("There are %s users logged in now.", lazyEval(getUserCount))
Java裡的方式:
logger.debug(``"There are {} users logged in now."``, () -> getUserCount());
目前Golang裡也存在這樣的問題,但是還沒找到怎麼做到 lazyLogging。
但是,可以看出上面的方式也不優雅,所以應當 避免 在列印日誌時呼叫函式。
非同步列印日誌
網際網路應用程式中,高併發下的寫日誌會帶來大量的IO操作,從而影響正常服務的效能。這時候的記日誌就需要專門的服務去做,例如把日誌打到訊息佇列裡,然後再寫到磁碟上。
設定快取
預設的日誌是隨時 flush 到console、檔案裡的,通過設定快取進行批量操作,可以一定程度上優化服務效能。
對日誌歸檔、分類
列印到一個檔案裡,會使得該檔案越來越大,不方便查詢。
按日誌屬性分類:access log,error log,
按日期歸檔:lathspell-api.2018-01-17.log,lathspell-api.2018-01-18.log
按大小切分:lathspell-api.2018-01-17.log.1,lathspell-api.2018-01-17.log.2,lathspell-api.2018-01-17.log.3 (避免檔案太大)