使用 Python 的 logging 模組記錄程式執行過程

用 logging 適時取代 print 函式，看起來更專業！

18 min readJun 19, 2023

🍰 前言

一般而言，寫程式的時候 print 函式很常用來輸出訊息，藉此達到檢視程式碼運作狀態的目的。此方式雖簡單卻存在缺陷，例如開發者往往在 debug 完成後要再把 print 給註解掉或是刪除，如此會增加維護的麻煩。或是有些訊息僅用來通知進度，而有些則是用來通知錯誤，但 print 本身並不會區分訊息的重要程度。因此，本文要介紹 Python 的內建 logging 模組，它能夠更加靈活地設計輸出訊息也讓程式碼更容易管理。

🍫 基本示範

使用 logging 模組最簡單的方法就是使用 logging.basicConfig 進行輸出訊息的設定，如下。

import logging


logging.basicConfig(
    level=logging.WARNING,
    format='%(asctime)s,%(msecs)03d [%(levelname)s] %(name)s: %(message)s',
    datefmt='%Y-%m-%d %H:%M:%S'
)

參數 level 是用來控制輸出層級。在 logging 模組裡，輸出訊息依照重要性區分為五個層級，由低到高依序是 DEBUG 、 INFO 、 WARNING 、 ERROR 、 CRITICAL ，以這個例子來說 level=logging.WARNING 代表往後只輸出包含 warning 以上層級的訊息。

參數 format 代表輸出訊息的格式，詳細的格式說明可以參考官方文件🔗。在這個例子裡，輸出訊息包含了時間 asctime 與 msecs 、層級 levelname 、記錄器名稱 name 及訊息 message 。

參數 datefmt 則是再進一步設定時間 asctime 的格式，其寫法其實就是援用 time.strftime 的標準，詳細說明可以參考官方文件🔗。

接下來我實際定義一段簡單的函式 calculate_length ，這個函式就是國中學過的畢氏定理，它在算三角形的斜邊邊長，希望大家沒有忘記。

def calculate_length(dx: float, dy: float) -> float:
    return (dx**2 + dy**2)**(1/2)

以下試著依照 DEBUG 、 INFO 、WARNING 、 ERROR 、 CRITICAL 這五種情境執行 calculate_length 並示範輸出訊息。

# Level 1: debug
dx, dy = 3.0, 4.0
length = calculate_length(dx, dy)
logging.debug(f'dx: {dx}, dy: {dy}, length: {length}')


# Level 2: info
dx, dy = 3.0, 4.0
length = calculate_length(dx, dy)
logging.info('Calculation is completed.')


# Level 3: warning
dx, dy = 3, 4
if type(dx) != float:
    logging.warning('The type of dx should be float.')
if type(dy) != float:
    logging.warning('The type of dy should be float.')
length = calculate_length(dx, dy)


# Level 4: error
dx, dy = 3.0, 4.0
length = calculate_length(dx, dy)
if length < max(dx, dy):
    logging.error(f'Calculation error!')


# Level 5: critical
dx, dy = '3', 4
try:
    length = calculate_length(dx, dy)
except Exception as e:
    logging.critical(f'{e}', exc_info=True)

執行結果如下，

2023-06-24 11:58:39,467 [WARNING] root: The type of dx should be float.
2023-06-24 11:58:39,467 [WARNING] root: The type of dy should be float.
2023-06-24 11:58:39,467 [CRITICAL] root: unsupported operand type(s) for ** or pow(): 'str' and 'int'
Traceback (most recent call last):
  File "c:/myLocal/myplayground/src/logging/basic/log_to_console.py", line 46, in <module>
    length = calculate_length(dx, dy)
  File "c:/myLocal/myplayground/src/logging/basic/log_to_console.py", line 12, in calculate_length
    return (dx**2 + dy**2)**(1/2)
TypeError: unsupported operand type(s) for ** or pow(): 'str' and 'int'

由於我已在 logging.basicConfig 裡設定 level=logging.WARNING 因此 DEBUG 和 INFO 的訊息就沒有輸出。

訊息裡的 root 是預設記錄器 Logger 的名稱，是 logging 模組在程式執行時默默建立的 Logger 物件。後面篇幅會再提供 Logger 的操作示範。

我在 logging.critical 裡設定 exc_info=True ，表示當程式發生錯誤會輸出完整的 traceback 訊息。若希望程式碼內容不要因為錯誤而外洩，那麼可以拿掉這個參數或是改為 exc_info=False ，則輸出訊息為：

2023-06-24 12:09:38,672 [WARNING] root: The type of dx should be float.
2023-06-24 12:09:38,673 [WARNING] root: The type of dy should be float.
2023-06-24 12:09:38,673 [CRITICAL] root: unsupported operand type(s) for ** or pow(): 'str' and 'int'

若要輸出訊息到外部文字檔，則需要再對 logging.basicConfig 額外指定 filename 和 filemode 參數，如下，

logging.basicConfig(
    filename='info.log',
    filemode='w',
    level=logging.WARNING,
    format='%(asctime)s,%(msecs)03d [%(levelname)s] %(name)s: %(message)s',
    datefmt='%Y-%m-%d %H:%M:%S'
)

如此訊息就會輸出到指定的文字檔當中。

特別注意，當 logging.basicConfig 接收到 filename 後就只會將訊息輸出到文字檔，不會再顯示到終端機，這是 logging.basicConfig 的限制之一。

🍹 多模組示範

一個專案裡同時存在多個不同 .py 檔 (module) 是再正常不過的事，因此這裡要示範多個模組情況下的 logging 使用方式。

我將 calculate_length 這個函式獨立寫在 library.py 當中，再讓 main.py 去 import 使用，檔案架構如下。

.
+-- main.py
+-- library.py

以下是 main.py ，

import logging
from library import calculate_length

logger = logging.getLogger()
logger.setLevel(logging.DEBUG)

file_handler = logging.FileHandler(filename='info.log', mode='w')
file_handler.setLevel(logging.DEBUG)

stream_handler = logging.StreamHandler()
stream_handler.setLevel(logging.DEBUG)

formatter = logging.Formatter(
    fmt='%(asctime)s,%(msecs)03d [%(levelname)s] %(name)s: %(message)s',
    datefmt='%Y-%m-%d %H:%M:%S'
)
file_handler.setFormatter(formatter)
stream_handler.setFormatter(formatter)

logger.addHandler(file_handler)
logger.addHandler(stream_handler)


if __name__ == '__main__':
    logger.info('Start.')
    vectors = [(1, 2), (3, 4), (5, 6)]
    lengths = [calculate_length(*vec) for vec in vectors]
    logger.info('End.')

由於我希望輸出訊息可以同時呈現在終端機與文字檔，因此未採用 logging.basicConfig 這個最陽春的方法，而是透過 logging.getLogger 建立實際 Logger 物件，其他建立的物件包含 FileHandler 、 StreamHandler 、 Formatter 。

首先， FileHandler 用來控制輸出文字檔的相關設定，而 StreamHandler 則是用來控制輸出終端機的相關設定，它們都可以透過 Formatter 來指定格式，最後再將 FileHandler 和 StreamHandler 指定給 Logger 。

以下是 library.py ，

import logging

logger = logging.getLogger(__name__)


def calculate_length(dx: float, dy: float) -> float:
    length = (dx**2 + dy**2)**(1/2)
    logger.info(f'dx: {dx: .3f}, dy: {dy: .3f}, length: {length: .3f}')
    return length

執行 main.py 得到的輸出訊息如下。

2023-06-23 16:46:32,947 [INFO] root: Start.
2023-06-23 16:46:32,948 [INFO] library: dx:  1.000, dy:  2.000, length:  2.236
2023-06-23 16:46:32,948 [INFO] library: dx:  3.000, dy:  4.000, length:  5.000
2023-06-23 16:46:32,948 [INFO] library: dx:  5.000, dy:  6.000, length:  7.810
2023-06-23 16:46:32,949 [INFO] root: End.

注意我在兩個檔案建立 Logger 方式的差異，在 main.py 的指令為：

logger = logging.getLogger()

在括弧中沒有填任何參數表示建立名為 root 的 Logger 。而在 library.py 則是：

logger = logging.getLogger(__name__)

這是一種好的建立 Logger 的慣用方式，能夠讓 library.py 的 Logger 繼承 root 的設定，所以可以發現我就沒有再額外建立 FileHandler 、 StreamHandler 和 Formatter 給 library.py 的 Logger。

若 Logger 的名稱符合句點分隔的階級制度 (period-separated hierarchy) 就能夠讓底層模組的 Logger 往上追朔繼承。

我曾企圖做另一種嘗試，來讓不同 .py 檔的 Logger 可以共用相同的格式設定並輸出到相同的終端機和相同的文字檔，也就是在 library.py 重複建立和 main.py 裡面一樣的FileHandler 、 StreamHandler 和 Formatter 然後再丟給 library.py 的 Logger 。但其實這樣會有問題，因為 main.py 和 library.py 的 Logger 都以寫入模式 'w' 將訊息寫入相同文字檔，那麼 library.py 在輸出訊息到文字檔 info.log 的時候會把 main.py 的訊息給覆蓋掉，反之亦然。

因此還是得藉由 period-separated hierarchical 的方式給不同模組的 Logger 建立名稱，這樣不但可以直接透過同一個終端機或是文字檔辨別每個訊息來自何處，也能避免輸出訊息到相同文字檔會互相覆蓋的狀況。

看到這是否跟我一樣覺得 logging 的學問真深🥲。目前的方法已經可以很靈活也很全面地使用 Logger ，但或許你也察覺這樣要寫很多行指令來設定這些 Logger ，超級佔版面，因此下一節的重點在於如何使用 Logger 又不會讓程式碼髒髒的。

🍬 Config 示範

可以透過另外一個模組 logging.config 讀取你為 logging 所制定的詳細設定。一般來說 logging.config 模組提供兩種讀取設定的方法 (method) ，一個是 fileConfig 另外一個則是 dictConfig ，而官方文件建議使用 dictConfig ，所以這裡就用 dictConfig 示範。

首先，要把關於 logging 的設定用 dict 型態的物件來呈現，然後再讓 logging.config.dictConfig 去讀取它，所以我就把 logging 的設定獨立寫在另外一個檔案 myconfig.py ，之後凡是需要使用 logging 的模組只要去 import 它就可以使用，讓這些真正在執行的程式碼的內容能夠更專注於各自的主要功能。檔案架構如下。

.
+-- main.py
+-- library.py
+-- myconfig.py

除了將 logging 的設定寫在 .py 檔的方法以外，也可以依個人喜好寫成 json 或 yaml 格式，只要再依對應的套件去讀取為 dict 型式即可。

以下是 myconfig.py 的內容。

LOGGING_CONFIG = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'standard': {
            'format': '%(asctime)s,%(msecs)03d [%(levelname)s] %(name)s: %(message)s',
            'datefmt': '%Y-%m-%d %H:%M:%S'
        }
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'level': 'DEBUG',
            'formatter': 'standard',
            'stream': 'ext://sys.stdout'
        },
        'file': {
            'class': 'logging.FileHandler',
            'level': 'DEBUG',
            'formatter': 'standard',
            'filename': 'info.log',
            'mode': 'w'
        }
    },
    'loggers': {
        '': {
            'handlers': ['console', 'file'],
            'level': 'DEBUG',
            'propagate': False
        }
    }
}

在這個 myconfig.py 當中建立了一個名稱是空字串的 Logger ，空字串會直接被 dictConfig 判定為 root ，這是一種常見作法。

另外，參數 disable_existing_loggers 預設值為 True，它會將所有除了 root 以外的既有 Logger 給禁止，在這邊調整為 False ，底下會說明。

補充說明，關於 myconfig.py 裡面寫到的 ext://sys.stdout 簡單講其實就是要求輸出訊息到終端機，其背後的概念是標準串流 ( 可參考維基百科🔗) 。

以下是 main.py 的內容。

import logging
import logging.config

from library import calculate_length
from myconfig import LOGGING_CONFIG


logging.config.dictConfig(LOGGING_CONFIG)
logger = logging.getLogger()


if __name__ == '__main__':
    logger.info('Start.')
    vectors = [(1, 2), (3, 4), (5, 6)]
    lengths = [calculate_length(*vec) for vec in vectors]
    logger.info('End.')

以下是 library.py 的內容。

import logging
import logging.config

from myconfig import LOGGING_CONFIG


logging.config.dictConfig(LOGGING_CONFIG)
logger = logging.getLogger(__name__)


def calculate_length(dx: float, dy: float) -> float:
    length = (dx**2 + dy**2)**(1/2)
    logger.info(f'dx: {dx: .3f}, dy: {dy: .3f}, length: {length: .3f}')
    return length

在 main.py 當中，先進行了 from library import calculate_length 之後才 logging.config.dictConfig(LOGGING_CONFIG) ，所以 library.py 的 Logger 建立在先，若 disable_existing_loggers 為 True ，那麼 library.py 的 Logger 便會失效。因此必須將 disable_existing_loggers 改為 False 。

執行結果如下。

2023-06-24 12:13:15,876 [INFO] root: Start.
2023-06-24 12:13:15,876 [INFO] library: dx:  1.000, dy:  2.000, length:  2.236
2023-06-24 12:13:15,876 [INFO] library: dx:  3.000, dy:  4.000, length:  5.000
2023-06-24 12:13:15,876 [INFO] library: dx:  5.000, dy:  6.000, length:  7.810
2023-06-24 12:13:15,876 [INFO] root: End.

藉由這樣的方法可以明顯觀察出來 main.py 和 library.py 的內容都呈現出相當精要的樣貌，不再髒髒的了。

🍩 結語

我花了不少時間摸索 logging 模組，因為我覺得 Python 官方文件在介紹這個模組時有些凌亂。透過這篇文章，我希望能夠記錄我的摸索過程，並有系統地整理出符合目前自己使用情境的用法。

然而， logging 模組還有很多進階方面的應用，例如在多執行緒 (multiple threads) 、多程序 (multiple processes) 或是網路之間進行 logging 事件傳遞等等，這些方面都還有更多的知識值得學習探索 ~