我們有時會有要在程式執行時輸出一些後台訊息的需求，用於顯示程式當下的行為，這樣的訊息我們稱為 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
Top comments (0)