nikkie-ftnextの日記

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

Pythonのloggingモジュールで、ロガーのフィルタと、ロガーのハンドラのフィルタとで、伝播されたログに対する挙動が違うことにハマりました

Python標準ライブラリ

はじめに

ヲタクに恋は、Python使いにloggingモジュールは、難しい。nikkieです

loggingモジュールのフィルタでハマりまして、少し深まった理解をアウトプットします。
今回の記事の元のツイートがこちら：

目次

きっかけ：時間がかかる処理の開始と終了をDEBUGレベルでログ出力したい！

OpenCALMをCPUで動かしています。

（今回の動作環境は上の記事と共通です。Python 3.10.9です）

文章の生成には30秒くらいかかるので、処理の進行が分かるよう、（最初はprint出力でしたが）DEBUGログとして出力することにしました。
開発中だけログ出力できればよく、アプリケーションとして使う時はログ出力不要なので、DEBUGログにしました。

書いたコードはこちら：
※試行錯誤のサイクルが短くなるようsmallモデルを使っています。

スクリプトを実行すると、ログ出力は以下のようになります。

% python example.py
2023-05-20 19:34:26,968 | DEBUG | urllib3.connectionpool:_new_conn:1048 - Starting new HTTPS connection (1): huggingface.co:443
2023-05-20 19:34:27,647 | DEBUG | urllib3.connectionpool:_make_request:546 - https://huggingface.co:443 "HEAD /cyberagent/open-calm-small/resolve/main/config.json HTTP/1.1" 200 0
2023-05-20 19:34:28,871 | DEBUG | urllib3.connectionpool:_make_request:546 - https://huggingface.co:443 "HEAD /cyberagent/open-calm-small/resolve/main/generation_config.json HTTP/1.1" 200 0
2023-05-20 19:34:29,572 | DEBUG | urllib3.connectionpool:_make_request:546 - https://huggingface.co:443 "HEAD /cyberagent/open-calm-small/resolve/main/tokenizer_config.json HTTP/1.1" 200 0
2023-05-20 19:34:29,635 | DEBUG | __main__:<module>:23 - [Start] generate
2023-05-20 19:34:31,175 | DEBUG | __main__:<module>:31 - [End] generate

私がスクリプトに仕込んだDEBUGログの他にurllib3.connectionpoolのDEBUGログも出力されます1。
ここからurllib3.connectionpoolのログの出力だけを消すことを考えます。

当初書いたコードのまとめ

  • ルートロガーのレベルをDEBUGに設定した（logging.basicConfig）
    • basicConfigによりStreamHandlerがルートロガーに取り付けられている
  • ログ出力できているのはルートロガーのStreamHandlerによる
    • urllib3.connectionpoolのロガーやスクリプトのロガー（logger）にハンドラは設定されていない
    • これらのロガーからルートロガーにログをpropagate（伝播）
      • ルートロガーのハンドラで出力されている！

basicConfigの挙動は以下の記事で整理しています。

logging.basicConfigはルートロガーにフォーマッタとハンドラを設定する

フィルタというものがある！

https://docs.python.org/ja/3/library/logging.html#filter-objects

フィルタ (Filter) は、ハンドラ や ロガー によって使われ、レベルによって提供されるのよりも洗練されたフィルタリングを実現します。

「同じDEBUGレベルのログのうち、__main__のログだけを出力したい」という今回のユースケースに合いそうです。

「これでいけるんちゃうか」と試したコードは、ルートロガーにフィルタを設定するというものでした。

# ルートロガーの設定
log_format = (
    "%(asctime)s | %(levelname)s | %(name)s:%(funcName)s:%(lineno)d"
    " - %(message)s"
)
logging.basicConfig(level=logging.DEBUG, format=log_format)
+root_logger = logging.getLogger()
+module_log_pass_filter = logging.Filter(__name__)
+root_logger.addFilter(module_log_pass_filter)

ところが、この実装だとurllib3.connectionpoolのログも__main__のログも両方出力されたままです（そんな😭）。
かなりハマった末に解決できました！
この記事では、うまくいく方法、なぜうまくいくのかの順で共有していきます。

ルートロガーの「ハンドラ」にフィルタを設定してログをフィルタできた！

basicConfigを使わずに、ルートロガーを設定します。
冒頭のスクリプトからの差分で示します。

# ルートロガーの設定
log_format = (
    "%(asctime)s | %(levelname)s | %(name)s:%(funcName)s:%(lineno)d"
    " - %(message)s"
)
-logging.basicConfig(level=logging.DEBUG, format=log_format)
+root_logger = logging.getLogger()
+root_logger.setLevel(logging.DEBUG)
+handler = logging.StreamHandler()
+formatter = logging.Formatter(log_format)
+handler.setFormatter(formatter)
+module_log_pass_filter = logging.Filter(__name__)
+handler.addFilter(module_log_pass_filter)  # ハンドラにフィルタを設定
+root_logger.addHandler(handler)

% python example.py
2023-05-20 19:49:20,857 | DEBUG | __main__:<module>:30 - [Start] generate
2023-05-20 19:49:22,409 | DEBUG | __main__:<module>:38 - [End] generate

urllib3.connectionpoolのログが消え、__main__のログだけの出力となりました！🙌

basicConfigを使う場合は、こうです：
※ここだけ、ルートロガーにフィルタを設定したコードからの差分で示します

# ルートロガーの設定
log_format = (
    "%(asctime)s | %(levelname)s | %(name)s:%(funcName)s:%(lineno)d"
    " - %(message)s"
)
logging.basicConfig(level=logging.DEBUG, format=log_format)
root_logger = logging.getLogger()
module_log_pass_filter = logging.Filter(__name__)
-root_logger.addFilter(module_log_pass_filter)
+root_logger.handlers[0].addFilter(module_log_pass_filter)

root_logger.handlers[0]がbasicConfigによって設定されたStreamHandlerです。
そのハンドラにフィルタを追加しました。

ルートロガーではなく、ルートロガーのハンドラにフィルタを設定してうまくいく理由

改めてドキュメントを見ると、以下のように書いてあります。
https://docs.python.org/ja/3/library/logging.html#filter-objects

その（※引用注：ロガーの）フィルタがそれら子孫ロガーにも適用されていない限り、子孫ロガーによって生成されたイベントはロガーのフィルタ設定によってフィルタされることはありません。

  • ルートロガーに__main__だけ通すフィルタを設定
    • 子のurllib3.connectionpoolのロガーから伝播したログには、ルートロガーの__main__だけ通すフィルタは適用されない
    • 子の__main__のロガーから伝播したログには、ルートロガーの__main__だけ通すフィルタは適用されない
  • 両方のログが出力されたのは、当然ということですね

ハンドラに対するフィルタはハンドラがイベントを発行する前に試され、

  • ルートロガーのハンドラに__main__だけ通すフィルタを設定
    • 子のurllib3.connectionpoolのロガーから伝播したログ
      • ルートロガーのハンドラの__main__だけ通すフィルタが適用され、出力されない
    • 子の__main__のロガーから伝播したログ
      • ルートロガーのハンドラの__main__だけ通すフィルタが適用され、出力される

ロガーの階層構造によるpropagate（伝播）が絡むと、ロガーのフィルタと、ロガーのハンドラのフィルタとで動きが違うのです。

  • ロガーのフィルタ：子孫ロガーから伝播したログに対しては適用されない
  • ロガーのハンドラのフィルタ：子孫ロガーから伝播したログに対しても適用される

このことは上級ロギングチュートリアルの「Logging Flow」にも図示されています。
https://docs.python.org/ja/3/howto/logging.html#logging-flow

  • 左下の「Pass to handlers of current logger」の先（ループ）がロガーのpropagateを表しています
    • propagateよりも前にロガーのフィルタが来ています
      • 「Does a filter attached to the logger reject the record?」（左の真ん中）
    • なので、伝播したログに対してロガーのフィルタは適用されないわけです
  • ロガーのハンドラは右側に図示されています
    • 「Does a filter attached to handler reject the record?」
    • 伝播したログに対して、ロガーのハンドラのフィルタは適用されるわけですね

終わりに

ロガーのフィルタと、ロガーのハンドラのフィルタとで、伝播されたログに対する挙動が違うことを学びました。
フィルタはロガーにもハンドラにも設定できるとサラッと書いてありますが、結構根本的な違いがあったとは...

Python使いにloggingモジュールは難しい！🤯
ロガー・ハンドラ・フィルタと、これら詳細がどう組み合わさって動くかを理解していないと使いこなせないですね〜😫
歴史的な経緯があってこうなっていて、そこは尊重したいのですが、「カプセル化（中身を知らなくてもカプセルのボタンを押すだけでやりたいことができる状態）からはあまりにもかけ離れている」とも感じます2。
basicConfigがインターフェースを過度に単純にしている気がするんですよね〜（今回はルートロガーのハンドラの設定がポイントだったので）3。
なお、loguruなど、ロギングを圧倒的に簡単（easy）にするサードパーティライブラリの存在は知っていて、loggingを仕組みを知って使っていくよりも、簡単に使える（Python界隈でよく言うfor humansな）方法をおすすめせざるを得ないかな〜という気持ちです4。

  1. このロガー（log）によります。https://github.com/urllib3/urllib3/blob/2.0.2/src/urllib3/connectionpool.py#L60↩
  2. ミノ駆動本で知ったデメテルの法則（＝最小知識の法則）にも反しているように映るんですよね〜↩
  3. 今回basicConfigを使い続けるにはroot_logger.handlers[0].addFilterが必要です。私の審美眼としては、何をやっているかが分かりづらいので、積極的には書きたくありません↩
  4. 私の好みは「loggingモジュールを知り尽くして使いこなす」なのですが、チームでの開発になったときに、それをチームメンバーに強いるのは酷かなとも思うのです。なのでfor humansな方法がおすすめという主張になります。↩