Leon
Posted on November 23, 2021
我們有時會有要在程式執行時輸出一些後台訊息的需求,用於顯示程式當下的行為,這樣的訊息我們稱為 log。
在開發階段我們會用 log 來協助除錯,而在正式環境也會留下一些必要的 log 以便日後追蹤,例如記下用戶登入的時間/地點/裝置等資訊,讓我們可以利用這些 log 來檢測出不尋常的登入行為。
與 print()
大法不同的是,log 除了把訊息顯示在螢幕外,還有有更豐富的設定選項,例如輸出到檔案,以及設定檔案的保留週期等等,這些都是 print()
大法難以實現的特性,因此對於記錄程式行為的需求,建議還是老老實實地用專門的 log 套件來實現。
在 Python 的世界,標準函式庫就有內建 log 模組 logging
。
Python 的 logging
因為是內建在標準函式庫內,所以可以直接引入:
import logging
logging.debug('debug message')
logging.info('info message')
logging.warning('warning message')
logging.error('error message')
logging.critical('critical message')
上面的範例是最簡單的用法,引入 logging
後可以直接調用,直接調用會把訊息顯示在螢幕上,上面我們調用了五個函式,他們代表的是訊息的重大程度,在 Python 文件內的定義如下:
級別 | 級別數字 | 何時使用 |
---|---|---|
DEBUG |
10 | 細節信息,僅當診斷問題時適用。 |
INFO |
20 | 確認程序按預期進行。 |
WARNING |
30 | 表明有已經或即將發生的意外(例如:磁盤空間不足)。程序仍按預計進行。 |
ERROR |
40 | 由於嚴重問題,程序的某些功能已經不能正常運行。 |
CRITICAL |
50 | 嚴重的錯誤,表明程序已不能繼執行。 |
上面的範例執行後輸出如下:
WARNING:root:warning message
ERROR:root:error message
CRITICAL:root:critical message
注意到 debug 和 info 訊息不見了!
因為 logging
預設只輸出 warning 及比 warning 更嚴重(即級別 ≥ 30)的訊息,這樣的預設配置較符合正式環境的需求,避免過多無謂的 info、debug 訊息輸出的 IO 作業把效能拖垮,或把空間灌爆。
在開發階段一般我們會把所有的訊息級別都打開方便我們除錯,因此我們把上面的範例修改一下:
import logging
dev_logger: logging.Logger = logging.getLogger(name='dev')
dev_logger.setLevel(logging.DEBUG)
handler: logging.StreamHandler = logging.StreamHandler()
dev_logger.addHandler(handler)
dev_logger.debug('debug message')
dev_logger.info('info message')
dev_logger.warning('warning message')
dev_logger.error('error message')
dev_logger.critical('critical message')
這個範例引入了 logging
的其它概念,下面一一說明。
Logger
在第一個範例未做任何設定的 logging
我們操作的是一個稱為 root
的 logger,而現在這個範例我們用 getLogger()
函式建立了另一個 dev_logger
,後面的設定也都是基於這個新的 dev_logger
,我們可以利用 logger 的機制建立無數個 logger,每個 logger 都可以有自己的組態,例如儲存到不同的檔案,或者不同的輸出的格式等等,雖然 root
logger 也是可以被做設定的,但個人建議另外建立自己的 logger 再把它變成自己喜歡的形狀,而不要去更動 root
logger 的行為,避免無意中改掉專案內依賴套件的 logger 行為。
而那句 setLevel(logging.DEBUG)
自然就是設定 logger 輸出級別的函式,裡面的 logging.DEBUG
也很單純,就是整數 10
,意即輸出 debug 及比 debug 更嚴重(即級別 ≥ 10)的的訊息。
Handler
在 logging
模組的 handler 負責處理 log 訊息的輸出工作,例如輸出到螢幕上或者某個檔案內,而我們這邊使用了 logging.StreamHandler()
這個 logging
模組內預帶的 handler。StreamHandler()
在不加任何參數的情況下,會把訊息輸出到 stderr,在作業系統未做額外的配置下,stderr 可以簡單的理解為顯示到螢幕上。
而 addHandler()
就望文生義了。
值得一提的是,一個 logger 可以加上數個 handler,意即 dev_logger
除了加入一個 StreamHandler
外,還可以再定義其他的 handler,例如一個 FileHandler
,如此一則 log 訊息就會被顯示在螢幕上以及被存到某個 log 檔內。
把上面的範例程式跑出來會輸出這些訊息:
debug message
info message
warning message
error message
critical message
回頭和第一個範例的結果比較一下,會發現訊息的格式不太一樣,因為我們並未對 dev_logger
設定它的訊息格式,而原始的 root
logger 是有預設它的訊息格式的。
Formatter
在此我們再引入另一個 logging
設定 log 訊息格式的特性 formatter。
再把範例加工一下:
import logging
dev_logger: logging.Logger = logging.getLogger(name='dev')
dev_logger.setLevel(logging.DEBUG)
handler: logging.StreamHandler = logging.StreamHandler()
formatter: logging.Formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)
dev_logger.addHandler(handler)
dev_logger.debug('debug message')
dev_logger.info('info message')
dev_logger.warning('warning message')
dev_logger.error('error message')
dev_logger.critical('critical message')
先看輸出結果:
2005-03-19 15:10:26,618 - dev - DEBUG - debug message
2005-03-19 15:10:26,620 - dev - INFO - info message
2005-03-19 15:10:26,695 - dev - WARNING - warn message
2005-03-19 15:10:26,697 - dev - ERROR - error message
2005-03-19 15:10:26,773 - dev - CRITICAL - critical message
這裡的格式是由程式內的 formatter
定義的,它是一個 logging.Formatter
物件,在實例化時餵入的字串定義了這個 formatter 的格式。除了範例內的代號,完整的格式代號如下:
格式 | 描述 |
---|---|
%(asctime)s |
建立 log 時間 |
%(created)f |
建立 log 的 Unix 時間 |
%(filename)s |
發出 log 的程式檔名 |
%(funcName)s |
發出 log 的函式名 |
%(levelname)s |
log 的級別 |
%(levelno)s |
log 的級別數字 |
%(lineno)d |
發出 log 的行號 |
%(message)s |
log 的訊息內容 |
%(module)s |
發出 log 的模組名稱 |
%(msecs)d |
建立 log 時間的毫秒部份 |
%(name)s |
發出 log 的 logger 名稱 |
%(pathname)s |
發出 log 的程式的路徑 |
%(process)d |
發出 log 的程序的 ID |
%(processName)s |
發出 log 的程序名稱 |
%(relativeCreated)d |
log 從創建到發出的毫秒時間差 |
%(thread)d |
發出 log 的線程 ID |
%(threadName)s |
發出 log 的線程名稱 |
格式代號這麼多,而在設定 log 格式時也並沒有所謂的最佳實踐格式,該怎麼設可以參考下面的原則:
- 足夠的資訊量,但不要一股腦的全塞進去,追求的是穠纖合度的平衡,爆量的 log 只會把機台的 IO 和空間塞爆。
- 人機皆可讀,log 除了給人看之外,也可以餵給外部的 log 分析服務,做到提醒或警報的功能。
- 不易混淆的分隔符號,讓不論是人讀或機讀都可以快速的解析出訊息的區段,而不會在茫茫 log 海中迷失。
- 適度的分類與分級,利用前面提到的 logger 與級別的機制,對 log 做分類與分級,debug 用的訊息不要流到別的層級;critical 的訊息不要放到 warning 而被忽略。
綜合以上,範例內的 '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
就是個頗不錯的格式。
專案內的 Log 模組
上一個部份談的是 logging
本身的用法,若要在專案內導入 log 機制,還需要考慮這幾點:
- 專案內的其它套件是否也有定義自己的 log?
- 要如何讓自己的 log 與其他套件的 log 和平共存而不互相干擾?
- 或者是如何依自己的需求魔改其他套件的 log 行為?
以 uvicorn 這個 ASGI server 來說,它就有自己的 log 機制,每當它跑起來就會開始吐訊息:
INFO: Started server process [20870]
INFO: Waiting for application startup.
INFO: Application startup complete.
INFO: Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
不只 uvicorn,大多數的 HTTP server 也都會吐出類似的 log,內容有啟動資訊以及訪客的請求資訊等等。
如果你不想和它的 log 互相干擾,那比較好的方式是建立自己的 logger,並設定自己的 handler 和 formatter,就如同前一部分的範例那樣。
另外由於你的 logger 有可能會在多個其他的 Python 模組內被引入,建議也把 logger 寫成獨立的模組便於使用。
如果你想魔改其它套件的 log 納為己用,那我在此為您加油!祝您好運!
結語
這篇介紹了 logging
模組的基礎用法,有些特性是本文並未涉及的,特別是組態檔的部份,logging
可以從外部的組態檔讀入配置,這樣的特性讓我們可以更好的把專案內的 log 設定與程式邏輯分離,並把所有的 logger 組織在一份獨立的檔案內,也更符合關注點分離的原則,或許未來可以再寫一篇來騙稿費。:p
Posted on November 23, 2021
Join Our Newsletter. No Spam, Only the good stuff.
Sign up to receive the latest update from our blog.
Related
November 26, 2024