nikkie-ftnextの日記

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

Pythonの対話モードで確認できるロガーのレベルは、ロガーが持つレベルそのものではなく、実効（effective）レベル

Python標準ライブラリ

はじめに

ミリオンライク展、集まった俺たちの列も展示物だったんだ... nikkieです。

今回は以下のコードを理解していきます。

>>> import logging
>>> logging.getLogger("foo")
<Logger foo (WARNING)>

Pythonのバージョンは 3.12.3 です。

目次

対話モードに出力されたのは、ロガーのレベルそのものではない？

logging.getLogger()は渡した名前のロガーを返します1。
https://docs.python.org/ja/3/library/logging.html#logging.getLogger
ここではfooロガーを返しました。

ロガーにはレベルを設定できます。
ドキュメントによると、
https://docs.python.org/ja/3/library/logging.html#logger-objects

  • level属性があり
  • setLevel()メソッドで設定できます

レベルの一覧はこちら（「ロギングレベル」）
https://docs.python.org/ja/3/library/logging.html#levels

  • NOTSET (0)
  • DEBUG (10)
  • INFO (20)
  • WARNING (30)
  • ERROR (40)
  • CRITICAL (50)

さて、logging.getLogger("foo")と生成したロガーのレベルはどうなっているのでしょうか？
私たちは特にレベルを指定していませんよね。
https://docs.python.org/ja/3/library/logging.html#logging.Logger.setLevel

ロガーが生成された際、レベルは NOTSET (略) に設定されます。

生成時はNOTSET、変えたい場合はsetLevel()で変更します。
NOTSETは一番下のレベルですね。

でも待ってください！
対話モードに出力されたレベルはWARNINGですよね？
これはどういうことなのでしょう？

対話モードに出力されているのは__repr__の返り値

https://docs.python.org/ja/3/library/functions.html#repr

オブジェクトの印字可能な表現を含む文字列を返します。

>>> repr(logging.getLogger("foo"))
'<Logger foo (WARNING)>'

この表現を返している、logging.Loggerクラスの__repr__を確認します。
https://github.com/python/cpython/blob/v3.12.5/Lib/logging/__init__.py#L1850-L1852

class Logger(Filterer):
    def __repr__(self):
        level = getLevelName(self.getEffectiveLevel())
        return '<%s %s (%s)>' % (self.__class__.__name__, self.name, level)

levelはロガー自身のレベル（self.level）ではなく、getEffectiveLevel()メソッドの返り値です！

ロガーのgetEffectiveLevel()メソッド

getEffectiveLevel()メソッドは、ロガー自身のレベル（0＝NOTSET）ではなく、WARNINGレベル（＝30）を返しています。

>>> import logging
>>> foo_logger = logging.getLogger("foo")
>>> foo_logger.level
0
>>> foo_logger.getEffectiveLevel()
30

https://docs.python.org/ja/3/library/logging.html#logging.Logger.getEffectiveLevel

このロガーの実効レベルを示します。

NOTSET 以外の値が setLevel() で設定されていた場合、その値が返されます。
そうでない場合、 NOTSET 以外の値が見つかるまでロガーの階層をルートロガーの方向に追跡します。見つかった場合、その値が返されます。

  • fooロガーのレベルはNOTSETです
    • 「そうでない場合」に該当します
  • ロガーの階層をルートロガーの方向に、すなわち親のロガーを追跡します

つまり、fooロガーのgetEffectiveLevel()メソッドは、ロガーの階層構造の中で有効なレベルを返したのです！

素振りコーナー

ここまでの理解が正しいか確認のために手を動かします。

(1) ルートロガーのレベルを変更したら、fooロガーの実効レベルは変わるはず

>>> import logging
>>> logging.getLogger().setLevel(logging.DEBUG)
>>> foo_logger = logging.getLogger("foo")
>>> foo_logger.level
0
>>> foo_logger.getEffectiveLevel()
10
>>> foo_logger
<Logger foo (DEBUG)>

fooロガーの実効レベルはルートロガーと同じDEBUGと出力されています。
仮説通り！

※logging.getLogger()とname引数を渡さないと、ルートロガー（への参照）が返ります

(2) ロガーの階層構造がもう少し深い例

階層構造を少し深くします。

  • ルートロガー
    • aロガー
      • a.bロガー
>>> import logging
>>> logger = logging.getLogger("a.b")
>>> logger
<Logger a.b (WARNING)>

a.bロガーの実効レベルは

  • a.bロガーのレベルはNOTSET
  • 親のaロガーのレベルもNOTSET
  • ルートロガーのレベル（WARNING）が返される

続くコードで、親のaロガーのレベルを変更すると

>>> logging.getLogger("a").setLevel(logging.INFO)
>>> logger
<Logger a.b (INFO)>

a.bロガーの実効レベルはINFOに変わりました！

終わりに

fooロガーを作ったときに、レベルはNOTSETであるのに、対話モードへの出力はレベルがWARNINGである疑問を解き明かしました。
対話モードに出力されたのは、ロガーのgetEffectiveLevel()メソッドが返す実効レベルです。

実効レベルは

  • そのロガーがNOTSET以外にsetLevelされていたらそのレベルが返る
  • NOTSETだったら、親について実効レベルを同様に調べる
    • 一番の親ルートロガーは、何もしていなければWARNINGレベル2

というロジックで決まります。

この記事は対話モードに印字されたレベルの出所を追うものでした。
ロガーのレベル、特にNOTSETのときの実効レベルがログ出力にどのように関わるかは別の記事としたいと思います3。

おまけ：getEffectiveLevel()メソッドの実装

getEffectiveLevel()メソッドは、whileループでレベルを親へ親へと確認していく実装でした。
https://github.com/python/cpython/blob/v3.12.5/Lib/logging/__init__.py#L1776-L1788

def getEffectiveLevel(self):
    logger = self
    while logger:
        if logger.level:
            return logger.level
        logger = logger.parent
    return NOTSET

NOTSETレベルが0、すなわち真理値としてはFalseと評価されることをうまく使ったコードです。

  1. 名前が同一のロガーはシングルトンと理解しています。「与えられた名前に対して、この関数はどの呼び出しでも同じロガーインスタンスを返します。したがって、ロガーインスタンスをアプリケーションの各部でやりとりする必要はありません。（getLogger()のドキュメントより）」↩
  2. このあたり？ https://github.com/python/cpython/blob/v3.12.5/Lib/logging/__init__.py#L2013↩
  3. NOTSETを除いて、レベルについて扱っている過去記事 ↩