nikkie-ftnextの日記

イベントレポートや読書メモを発信

Pythonでライブラリのロガーを使ったロギングをLogging Flowに沿って、かつフィルタやハンドラの設定にも注意を払って説明する

Python標準ライブラリ

はじめに

ななこぷりこれす かわいい。nikkieです。

「Pythonのloggingは難しすぎる！」と感じてから1年以上。
ついに主な構成要素の動きを完全に理解できたんじゃないかと思います！

目次

自作ライブラリの中でのロギングの実装をもっと理解したい

現在の私は、自作ライブラリの中でのロギングは以下のようにしたいと考えています1。

ライブラリ

import logging

logger = logging.getLogger(__name__)
logger.addHandler(logging.NullHandler())

ライブラリのロガーを用意します2

  • NullHandlerを設定（最終手段ハンドラの出番にしない）
  • ライブラリのロガーのレベルはNOTSET（＝ルートロガー（親）のレベル参照）
  • ちなみに、ハンドラのレベルもNOTSET

アプリケーション（ライブラリを使うコード）

import logging

logging.basicConfig(
    format="%(asctime)s | %(levelname)s | %(name)s:%(funcName)s:%(lineno)d - %(message)s",
)

ルートロガーを設定します。
ルートロガーのレベルはWARNINGですね3

これをロギングの構成要素に可能な限り注意を払った上で、Logging Flowに沿って説明してみようという試みです。

ロギングの構成要素

  • ロガー
  • ロギングレベル
  • フィルタ
  • ハンドラ
  • フォーマッタ

PyCon JP 2021のTsutsumiさんのトークに挙げられた「主な要素」から、ログレコードを除きました。
今回はフローを流すのに関わる要素を対象とします（ログレコードはフローを流れていくもの）。

1つのロガーはこのように構成されます

  • ロギングレベル
  • フィルタ（0個以上）
  • ハンドラ（0個以上）
    • ロギングレベル
    • フォーマッタ（1個）
    • フィルタ（0個以上）

ライブラリでNullHandlerを設定したロガーのロギングの流れ

Logging Flowは過去にも読みました。再訪ですね4

ライブラリのロガーでロギング（logger.warning()）

Logger enabled for level of call?

の部分。
ライブラリのロガーのレベルはNOTSET。
親にあたるルートロガーのレベルを見て、WARNINGとなります。
（場合によってはライブラリの中にも親ロガーがあるかもしれませんが、今回はこのネストは考えないことにしました）

WARNINGレベルのロガーのwarningメソッドが呼び出されたので、enabled?への回答は「Yes」

ログレコードが作られました。

その後

Does a filter attached to logger reject the record?

今回ライブラリのロガーにフィルタは設定されていないので、回答は「No」。

発見💡：アプリケーションコードでライブラリのロガーにフィルタを追加すれば、フィルタで除くこともできるのか！5
フィルタにはロガーの名前を渡します。
https://docs.python.org/ja/3/library/logging.html#filter

例えば、'A.B' で初期化されたフィルタは、ロガー 'A.B', 'A.B.C', 'A.B.C.D', 'A.B.D' 等によって記録されたイベントは許可しますが、'A.BB', 'B.A.B' などは許可しません。

さて、ログレコードがロガーのハンドラに渡りました

propagate（ログレコードを祖先のハンドラへも）

ロガーのpropagate属性を参照するフローを見ます。

Is propagate true for current logger?

ロガーインスタンスが作られたとき、propagate属性はデフォルトでTrueです。
https://docs.python.org/ja/3/library/logging.html#logging.Logger.propagate
よって、回答は「Yes」

Is there a parent logger?

ライブラリのロガーには、親ロガーとしてルートロガーがあります。
よって、回答は「Yes」

親ロガーをcurrent loggerとし（whileループ感）、そのハンドラに同じログレコードを渡します。
ルートロガーのハンドラにも、ライブラリのハンドラに渡ったのと同じログレコードが渡りました！

ここで注意したいのは、親ロガーのレベルやフィルタは見ないということですね。
親ロガーのレベル未満のログレコードや、親ロガーのフィルタが除くログレコードであっても、propagateでは親ロガーのハンドラに渡ります。

ハンドラでログレコードの処理

ライブラリのロガーのハンドラ（NullHandler）から見ていきます。

Handler enabled for level of record?

このNullHandlerのレベルはNOTSET（一番下のロギングレベル）です6。
ログレコードはWARNINGレベルですから、回答は「Yes」

Does a filter attached to handler reject the record?

このNullHandlerにはフィルタは取り付けられていません。
回答は「No」

以上より、NullHandlerはログレコードを処理します。
何もしないハンドラなので、処理をしても何もしていないわけですが

続いて、propagateによりログレコードが渡っている、ルートロガーのハンドラです。
basicConfig()によりStreamHandlerです。

Handler enabled for level of record?

このStreamHandlerも初期化しただけ7ですから、レベルはNOTSET。
回答は「Yes」

Does a filter attached to handler reject the record?

このStreamHandlerにはフィルタは取り付けられていません。
回答は「No」

以上より、StreamHandlerはログレコードを処理します。
basicConfig()で設定したフォーマッタが使われるわけですね

💡propagateしたログレコードにハンドラのレベルとフィルタが適用されるので、カスタマイズの余地があるんだなと認識しました。
ただ、ハンドラのレベルは、レベルごとに出力先を変える用途が多いんじゃないかと思っています。
https://docs.python.org/ja/3/howto/logging.html#handlers

例として、あるアプリケーションがすべてのログメッセージをログファイルに、 error 以上のすべてのログメッセージを標準出力に、 critical のメッセージはすべてメールアドレスに、それぞれ送りたいとします。この場合、 3 つの個別のハンドラがそれぞれの深刻度と宛先に応じて必要になります。

終わりに

loggingの構成要素にできるだけ注意を払って、ライブラリのロガー + アプリケーションコードでロギングするときのLogging Flowの理解を深めました。
やってみての気づきは以下です。

  • ライブラリのロガーのレベルやフィルタをアプリケーションコードから操作する余地がある
  • propagateは親ロガーのレベルやフィルタは見ない
  • ハンドラにログレコードがpropagateされても、ハンドラのレベルやフィルタで除ける

完全に理解したぞ！！
（ちなみに1年半ぶり2回目です8）

  1. こちらの記事内の追記内容採用版です ↩
  2. 最終手段ハンドラやNOTSETレベルは、この記事も踏まえています ↩
  3. 「ルートロガーは WARNING レベルで生成されることに注意してください。」https://docs.python.org/ja/3/library/logging.html#logging.Logger.setLevel↩
  4. 理解には時間がかかる ↩
  5. ライブラリのロガーを操作した過去記事 ↩
  6. 「ハンドラが生成された際、レベルは NOTSET (すべてのメッセージが処理される) に設定されます。」https://docs.python.org/ja/3/library/logging.html#logging.Handler.setLevel↩
  7. https://github.com/python/cpython/blob/v3.12.5/Lib/logging/__init__.py#L2122↩
  8. 前回 ↩