Python loggingモジュールの内部構造

はじめに

Pythonの標準ライブラリである logging モジュールは強力かつ柔軟なロギングツールですが、複雑な内部構造ゆえに予期しない挙動や問題に直面することがあります。本記事では、loggingモジュールの内部構造を理解することを目指します。

コンポーネント

loggingモジュールは複数のコンポーネントから構成されていて、それぞれが特定の役割を担っています。以下では Manager, Logger, Handler, Filter, Formatter および LogRecord について説明します。

Manager

Manager は Logger の取得と管理を担当する中心的なコンポーネントです。Manager はすべての Logger を名前で辞書管理し、名前がドットで区切られた階層構造を形成します。例えば、"a", "a.b", "a.b.c" という名前の Logger を生成すると、"a" が "a.b" の親、"a.b" が "a.b.c" の親となります。さらに、最上位の親として "root" という名前の Logger が存在します。階層構造を形成することで子で発生したイベントを親に伝播させたり、親子間で一貫した設定が可能になります。
ユーザーが直接 Manager を操作することは基本ありませんが、logging.getLogger を通じて Logger を取得する際に裏で Manager が動作しています。logging.getLogger を呼び出すと Manager の getLogger メソッドが実行されます。指定された名前の Logger が既に存在するかを確認し、存在しなければ新規に生成します。新しく生成された Logger には適切な親子関係が設定され、全体の階層構造が更新されます。
Manager の getLogger メソッドの実装を見てみましょう。指定された名前が loggerDict に存在すればその Logger を返し、存在しなければ新規に Logger を作成して返します。

https://github.com/python/cpython/blob/v3.11.5/Lib/logging/__init__.py#L1327-L1359

Logger

Logger はloggingモジュールの中核をなすコンポーネントであり、LogRecord の生成と送信を担当します。各 Logger には名前がつけられていて、名前空間に基づいて階層構造が形成されます。Logger はログレベルを持ち、そのレベル未満のログは出力されません。また、複数の Handler や Filter を設定することができ、ログの出力先やフィルタリング条件を細かく制御することができます。
LogRecord の送信は callHandlers メソッドに実装されています。LogRecord のレベルが各 Handler のログレベル以上であれば、その LogRecord を Handler に渡しています。さらに、すべての Handler への送信が完了した後、親の Logger に対して LogRecord を伝播させます。

https://github.com/python/cpython/blob/v3.11.5/Lib/logging/__init__.py#L1690-L1710

Handler

Handler は LogRecord を特定の出力先に送信する役割を担っています。Logger に複数の Handler を設定することで同時に複数の場所（例えばコンソールやファイル、メールなど）にログを出力することができます。Handler にはログレベルが設定されていて、そのレベル以上の LogRecord を処理します。このとき Formatter を使用して LogRecord を人間が読みやすい形式に変換します。
Handler にはさまざまな種類が存在し、代表的なものとしてコンソール出力用の StreamHandler、ファイル出力用の FileHandler、メール送信用の SMTPHandler、HTTPリクエストを使用してログを送信する HTTPHandler などがあります。これらの Handler は出力先に適した方法で LogRecord を処理します。独自の Handler クラスを実装することも可能で、その emit メソッドをカスタマイズすることで任意の場所へログを送信できます。

https://github.com/python/cpython/blob/v3.11.5/Lib/logging/__init__.py#L955-L963

Filter

Filter は LogRecord をフィルタリングするためのコンポーネントであり、特定の条件に基づいて LogRecord の出力を制御します。例えば、特定のキーワードを含むログのみを出力したり、特定のモジュールからのログのみを記録したりすることができます。Filter は Logger および Handler の両方に複数設定することができます。
Filter を継承したサブクラスの filter メソッドを実装することでフィルタリングの条件を定義することができます。

class MyFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        return "danger" in record.getMessage()


logger.addFilter(MyFilter())
logger.warning("danger")  # "danger" を含むため出力される
logger.warning("safe")  # "danger" を含まないため出力されない

Formatter

Formatter は LogRecord を人間が読みやすい形式に変換する役割を担います。ログの見た目をカスタマイズするために使用され、タイムスタンプ、ログレベル、メッセージ内容など、LogRecord が持つさまざまな要素を含めることができます。Formatter は Handler に設定され、Handler を通じて出力されるすべてのログに適用されます。

formatter = logging.Formatter("%(asctime)s - %(levelname)s - %(filename)s - %(lineno)d - %(message)s")
handler.setFormatter(formatter)

LogRecord

LogRecord は発生したイベントの情報を保持するオブジェクトです。Logger の内部で生成され、Handler や Filter、Formatter で処理されます。LogRecord にはログメッセージだけでなく、時刻、ログレベル、発生したファイルや行番号、関数名、スレッドID、プロセスIDなどのメタデータが含まれています。これにより、ログメッセージの追跡やデバッグが容易になります。

https://github.com/python/cpython/blob/v3.11.5/Lib/logging/__init__.py#L292-L338

ログが出力されるまで

先ほど紹介したコンポーネントが連携し、ログが出力されるまでの一連のプロセスを見てみましょう。シーケンス図に示すように、複雑な処理が行われています。

大まかに説明すると、以下のような流れになっています。

1. logging.getLogger() を通して Manager から Logger を取得する
2. Logger のログ出力メソッド info を呼び出す
3. Logger に設定されたレベルとINFOレベルを比較する
4. LogRecord を作成する
5. Logger に設定した Filter でフィルタリングする
6. Handler に設定されたレベルとINFOレベルを比較する
7. LogRecord を Handler に渡す
8. Handler に設定した Filter でフィルタリングする
9. LogRecord を Formatter で文字列に変換する
10. 指定した場所に出力する

実際には、処理が終わった後に親の Logger に対してログが伝播され、手順3以降が繰り返されます。

落とし穴と原因

loggingモジュールを使っていてよく直面する落とし穴とその原因について具体例を交えて紹介します。

ログレベルの設定ミス

ログレベルを設定し忘れるとログが出力されないことがあります。以下のサンプルコードを実行しても何も出力されません。Logger のログレベルの設定を忘れたために RootLogger のログレベル WARNING が引き継がれてしまいログが出力されていません。Logger および Handler にはログレベルを適切に設定するようにしましょう。

logger = logging.getLogger("app")
handler = logging.StreamHandler()
handler.setLevel(logging.DEBUG)
logger.addHandler(handler)
logger.info("This is an info message")

ハンドラーの重複設定

ハンドラーの重複設定により同じログが複数行出力されます。

import logging


# 問題のあるsetup_logger
def setup_logger() -> logging.Logger:
    logger = logging.getLogger("app")
    logger.setLevel(logging.DEBUG)
    handler = logging.StreamHandler()
    handler.setFormatter(logging.Formatter("%(levelname)s: %(message)s"))
    logger.addHandler(handler)
    return logger


# 初回のlogger設定
first_logger = setup_logger()

# 再度setup_loggerを呼び出すことでハンドラーが重複
second_logger = setup_logger()
second_logger.debug("This is a debug message")

$ python main.py
DEBUG: This is a debug message
DEBUG: This is a debug message

1回目に setup_logger を実行した時には "app" という名前の Logger が生成され、Handler が追加されます。2回目の実行時には "app" という名前の Logger が Manager の辞書から返されます。その Logger に対して再度 Handler を追加してしまうので Handler が複数設定され、ログが複数行出力されます。
Handler が設定済みかどうかのチェックを入れることで、Handler の重複登録を防ぐことができます。

# 対応版
def setup_logger() -> logging.Logger:
    logger = logging.getLogger("app")
    logger.setLevel(logging.DEBUG)
    if not logger.handlers:
        handler = logging.StreamHandler()
        handler.setFormatter(logging.Formatter("%(levelname)s: %(message)s"))
        logger.addHandler(handler)
    return logger

階層構造によるログの伝播

Logger の階層構造によってログが複数行出力される場合もあります。

app_logger = logging.getLogger("app")
app_logger.addHandler(logging.StreamHandler())

sub_logger = logging.getLogger("app.sub")
sub_logger.addHandler(logging.StreamHandler())

sub_logger.warning("This is a sub logger")

$ python main.py
WARNING: This is a sub logger
WARNING: This is a sub logger

Logger の階層構造により、"app.sub" のログは親である "app" に伝播します。その結果、同じログが複数回出力されます。このように、Logger は名前による階層構造を持ち、下位のログは上位へと伝播するため、問題調査の際にはこの構造を意識しておくと役立ちます。

おわりに

本記事では、Pythonのloggingモジュールの主要コンポーネントとログが出力されるまでの流れについて解説しました。また、loggingモジュールを使っていてよく直面する落とし穴とその原因について具体例を交えて紹介しました。各コンポーネントの役割や連携の仕組みを理解することで、loggingモジュールを正しく使用できるようになると思います。