nikkie-ftnextの日記

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

自作のPythonライブラリでloggingを使うとき、ロガーにsetLevelしない？ ログレベルNOTSETのロガーの動きを理解する

Python標準ライブラリ

はじめに

トトロって、サツキがかわいいからメイ探しのお手伝いしたらしい。俺らと同類じゃん！ nikkieです。

先日書いたPython自作ライブラリにおけるロギングの積み残しの解消に着手します。
この記事では、ロガーのNOTSETレベルについて見ていきます。

目次

出発点：自作ライブラリの中でのロギング

ライブラリのコード（src/awesomelib/__init__.py）

import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.WARNING)  # <- この記事の主な話題
logger.addHandler(logging.NullHandler())


def awesome() -> None:
    logger.info("想定通り")
    logger.warning("ちょっとヤバいよ")
    print("Awesome ✨")
  • ライブラリのロガーの設定
    • レベルをWARNINGに（※この記事の主な話題です）
    • ハンドラをNullHandlerに
  • ライブラリの中のログ出力
    • レベルWARNING以上で、ハンドラ呼び出し
    • しかし、ハンドラは何もしない
    • propagateで親のロガーに伝播（ルートロガーまで）
      • ライブラリのユーザがルートロガーを設定（例：logging.basicConfig）したら、ルートロガーのハンドラによってログ出力される

ドキュメント「ライブラリのためのロギングの設定」

https://docs.python.org/ja/3/howto/logging.html#configuring-logging-for-a-library

ライブラリにはNullHandlerを設定するよう指南する箇所です。
ここのコードですが、ライブラリのロガーにレベルを設定していません。

import logging
logging.getLogger('foo').addHandler(logging.NullHandler())

レベルを設定しないときの動きを理解していきます。
Python 3.11.8で動作を確認しました。

ライブラリのロガーの設定を検証

ライブラリのロガーにレベルやハンドラを設定しない、かつ、ルートロガーも設定しない

ライブラリ

import logging

logger = logging.getLogger(__name__)
-logger.setLevel(logging.WARNING)
-logger.addHandler(logging.NullHandler())


def awesome() -> None:
    logger.info("想定通り")
    logger.warning("ちょっとヤバいよ")
    print("Awesome ✨")

ライブラリを使うコード

from awesomelib import awesome

awesome()

出力結果

ちょっとヤバいよ
Awesome ✨

この振る舞いは「環境設定が与えられないとどうなるか」で説明されます。

ロギング環境設定を与えられないと、ロギングイベントを出力しなければならないのに、イベントを出力するハンドラが見つからないことがあります。

イベントは、 lastResort に格納された「最終手段ハンドラ」を使用して出力されます。

最終手段ハンドラは

  • 標準エラー出力（sys.stderr）に書くStreamHandler（のように動作）
  • フォーマットは行われない
    • -> 「ちょっとヤバいよ」とメッセージだけ出力した
  • ハンドラのレベルはWARNING
    • -> INFOは出力されていない

となります。

ライブラリのロガーにレベルのみ設定しない、かつ、ルートロガーも設定しない

ライブラリ

import logging

logger = logging.getLogger(__name__)
-logger.setLevel(logging.WARNING)
logger.addHandler(logging.NullHandler())


def awesome() -> None:
    logger.info("想定通り")
    logger.warning("ちょっとヤバいよ")
    print("Awesome ✨")

ライブラリを使うコード（1つ前と同じ）

from awesomelib import awesome

awesome()

出力結果

Awesome ✨

NullHandlerが与えられているので、最終手段ハンドラの出番はないわけですね。

「ライブラリのためのロギングの設定」の以下は、最終手段ハンドラのことを言っていたのか〜

何らかの理由で、ロギング設定がなされていないときにメッセージを表示 させたくない なら、あなたのライブラリのトップレベルロガーに何もしないハンドラを取り付けられます。

ライブラリのロガーにレベルのみ設定しない、かつ、ルートロガーのレベルを設定

ライブラリ（1つ前と同じ）

import logging

logger = logging.getLogger(__name__)
-logger.setLevel(logging.WARNING)
logger.addHandler(logging.NullHandler())


def awesome() -> None:
    logger.info("想定通り")
    logger.warning("ちょっとヤバいよ")
    print("Awesome ✨")

ライブラリを使うコードでは、ルートロガーをWARNINGレベルに設定します

import logging

from awesomelib import awesome

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

awesome()

出力結果

2024-08-24 10:36:27,696 | WARNING | awesomelib:awesome:9 - ちょっとヤバいよ
Awesome ✨

propagateによりログ出力されていますね。
ここをもう少し見ていきます。

ログレベルNOTSETと実効レベル

では、ライブラリのロガーのsetLevel()の有無で何が違うのでしょうか？
setLevel()を呼び出していないと、レベルはNOTSETとして扱われます。
違いはINFOレベルのログです。

ライブラリでlogger.setLevel(logging.WARNING)しているとき、ルートロガーをDEBUGレベルに指定しても、INFOレベルのログは出力されません。

2024-08-24 10:37:59,478 | WARNING | awesomelib:awesome:10 - ちょっとヤバいよ
Awesome ✨

これは、ライブラリのロガーがWARNINGレベル以上を処理するように設定されているためですね。
INFOレベル（＝WARNINGレベル未満）のログはロガーが処理しません。
ロガーが処理するWARNING以上がハンドラに渡り、また、親のロガーへもpropagateされます

ライブラリでロガーをsetLevel()していない（すなわち、NOTSETレベルのまま）のとき、ルートロガーをDEBUGレベルに指定すると、INFOレベルのログが出力されます。

2024-08-24 10:39:00,471 | INFO | awesomelib:awesome:8 - 想定通り
2024-08-24 10:39:00,471 | WARNING | awesomelib:awesome:9 - ちょっとヤバいよ
Awesome ✨

ライブラリのロガーのレベルがNOTSETのとき、どのようにログが処理されているかはドキュメントに記載があります。
https://docs.python.org/ja/3/library/logging.html#logging.Logger.setLevel

「親ロガーに委譲」という用語の意味は、もしロガーのレベルが NOTSET ならば、祖先ロガーの系列の中を NOTSET 以外のレベルの祖先を見つけるかルートに到達するまで辿っていく、ということです。

もし NOTSET 以外のレベルの祖先が見つかったなら、その祖先のレベルが探索を開始したロガーの実効レベルとして扱われ、ログイベントがどのように処理されるかを決めるのに使われます。

ライブラリのロガー

  • レベルはNOTSET
  • 2つのレベルで呼び出されている
    • INFO
    • WARNING

親ロガー（ここではルートロガー）

  • もともとWARNINGレベル
    • ライブラリのロガーの実効レベルはWARNINGとなる
    • WARNINGレベルのログのみ処理する
  • DEBUGレベルに指定（logging.basicConfig(level=logging.DEBUG)）
    • ライブラリのロガーの実効レベルはDEBUGとなる
    • INFOレベル・WARNINGレベル、両方を処理する

ロガーのレベルNOTSETとは、親のレベルを参照ということなのですね。
今回は階層構造が浅いのでルートロガーの設定に応じて、ライブラリのロガーのレベルが変わりました。
a.bロガーのように階層を少し深くした場合は、ライブラリのユーザがaロガーのレベルを設定することで、a.bロガーのレベルを変えることもできますね。

ロガーのレベルNOTSETが親のレベルを参照というのは、ロガーのgetEffectiveLevel()メソッドで確認できますね1。
python -i <script.py>として対話モードに入って

>>> logging.getLogger("awesomelib")  # WARNINGはgetEffectiveLevel()の返り値
<Logger awesomelib (WARNING)>
>>> logging.getLogger("awesomelib").level
0

ライブラリのロガー自体のレベルはNOTSETですが、実効レベルはルートロガー（親）のレベルです

終わりに

公式ドキュメントに書かれた、ライブラリのロガーにNullHandlerを設定するコードで、ロガーのレベルを設定していない点を見てきました。

  • ライブラリのロガーはNOTSETレベルとなっています
  • これは親ロガーのレベルを参照して振る舞います（実効レベル）
    • ルートロガーの設定に応じて詳細なログ出力をすることが可能です

実はハンドラにもレベルが設定されるのですが、こちらのNOTSETは直感的でした2。
https://docs.python.org/ja/3/library/logging.html#logging.Handler.setLevel

ハンドラが生成された際、レベルは NOTSET (すべてのメッセージが処理される) に設定されます。

今回のソースコードはこちらです。

  1. 姉妹編 ↩
  2. 別記事が生まれるかも（確度低め）↩