我們有時會有要在程式執行時輸出一些後台訊息的需求,用於顯示程式當下的行為,這樣的訊息我們稱為 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 文件內的定義如下:

級別級別數字何時使用
DEBUG10細節信息,僅當診斷問題時適用。
INFO20確認程序按預期進行。
WARNING30表明有已經或即將發生的意外(例如:磁盤空間不足)。程序仍按預計進行。
ERROR40由於嚴重問題,程序的某些功能已經不能正常運行。
CRITICAL50嚴重的錯誤,表明程序已不能繼執行。
來源:〈如何使用 Logging 模組

上面的範例執行後輸出如下:

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)slog 的級別
%(levelno)slog 的級別數字
%(lineno)d發出 log 的行號
%(message)slog 的訊息內容
%(module)s發出 log 的模組名稱
%(msecs)d建立 log 時間的毫秒部份
%(name)s發出 log 的 logger 名稱
%(pathname)s發出 log 的程式的路徑
%(process)d發出 log 的程序的 ID
%(processName)s發出 log 的程序名稱
%(relativeCreated)dlog 從創建到發出的毫秒時間差
%(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 機制,還需要考慮這幾點:

  1. 專案內的其它套件是否也有定義自己的 log?
  2. 要如何讓自己的 log 與其他套件的 log 和平共存而不互相干擾?
  3. 或者是如何依自己的需求魔改其他套件的 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