Python Log 從小白到入門
Tags: python, logging
Published: 2021-11-23 03:48:42

我們有時會有要在程式執行時輸出一些後台訊息的需求，用於顯示程式當下的行為，這樣的訊息我們稱為 log。

在開發階段我們會用 log 來協助除錯，而在正式環境也會留下一些必要的 log 以便日後追蹤，例如記下用戶登入的時間／地點／裝置等資訊，讓我們可以利用這些 log 來檢測出不尋常的登入行為。

與 `print()` 大法不同的是，log 除了把訊息顯示在螢幕外，還有有更豐富的設定選項，例如輸出到檔案，以及設定檔案的保留週期等等，這些都是 `print()` 大法難以實現的特性，因此對於記錄程式行為的需求，建議還是老老實實地用專門的 log 套件來實現。

在 Python 的世界，標準函式庫就有內建 log 模組 `logging`。

## Python 的 logging

因為是內建在標準函式庫內，所以可以直接引入：

```python
import logging

logging.debug('debug message')
logging.info('info message')
logging.warning('warning message')
logging.error('error message')
logging.critical('critical message')
```

上面的範例是最簡單的用法，引入 `logging` 後可以直接調用，直接調用會把訊息顯示在螢幕上，上面我們調用了五個函式，他們代表的是訊息的重大程度，在 Python 文件內的定義如下：

<div class="wide">

<table>
    <thead>
        <tr><th>級別</th><th align="center">級別數字</th><th>何時使用</th></tr>
    </thead>
    <tbody>
        <tr><td><code>DEBUG</code></td><td align="center">10</td><td>細節信息，僅當診斷問題時適用。</td></tr>
        <tr><td><code>INFO</code></td><td align="center">20</td><td>確認程序按預期進行。</td></tr>
        <tr><td><code>WARNING</code></td><td align="center">30</td><td>表明有已經或即將發生的意外（例如：磁盤空間不足）。程序仍按預計進行。</td></tr>
        <tr><td><code>ERROR</code></td><td align="center">40</td><td>由於嚴重問題，程序的某些功能已經不能正常運行。</td></tr>
        <tr><td><code>CRITICAL</code></td><td align="center">50</td><td>嚴重的錯誤，表明程序已不能繼執行。</td></tr>
    </tbody>
    <caption>來源：〈<a href="https://docs.python.org/zh-tw/3/howto/logging.html">如何使用 Logging 模組</a>〉</caption>
</table>
</div>

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

```
WARNING:root:warning message
ERROR:root:error message
CRITICAL:root:critical message
```

注意到 debug 和 info 訊息不見了！

因為 `logging` 預設只輸出 warning 及比 warning 更嚴重（即級別 ≥ 30）的訊息，這樣的預設配置較符合正式環境的需求，避免過多無謂的 info、debug 訊息輸出的 IO 作業把效能拖垮，或把空間灌爆。

在開發階段一般我們會把所有的訊息級別都打開方便我們除錯，因此我們把上面的範例修改一下：

```python
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 行為。

<figure>

![我能感覺出來 你裡面變了](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/ekewbpflu8r6qq0mn3qk.jpg)
<figcaption>來源：網路</figcaption>
</figure>

而那句 `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。

再把範例加工一下：

```python
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 機制，還需要考慮這幾點：

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 納為己用，那我在此為您加油！祝您好運！

<figure>

![加油，好嗎](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/jdoe5lb20ekoldbfbbzl.jpg)
<figcaption>來源：《超級星光大道》</figcaption>
</figure>

## 結語

這篇介紹了 `logging` 模組的基礎用法，有些特性是本文並未涉及的，特別是組態檔的部份，`logging` 可以從外部的組態檔讀入配置，這樣的特性讓我們可以更好的把專案內的 log 設定與程式邏輯分離，並把所有的 logger 組織在一份獨立的檔案內，也更符合[關注點分離](https://zh.wikipedia.org/wiki/%E5%85%B3%E6%B3%A8%E7%82%B9%E5%88%86%E7%A6%BB)的原則，或許未來可以再寫一篇來騙稿費。:p