nikkie-ftnextの日記

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

Pythonのloggingモジュールのドキュメントの「もっとも単純な例」を説明する 〜logging.warningの裏側で起こっていること〜

Python標準ライブラリ

はじめに

ういっす✌️ nikkieです。

先日、Pythonのloggingモジュールを完全に理解しました。

深まった理解をもとに、ドキュメントの「もっとも単純な例」を説明してみます。

目次

もっとも単純な例

ドキュメントの冒頭にあります。

>>> import logging
>>> logging.warning('Watch out!')
WARNING:root:Watch out!

※Python 3.10.9で動作確認しました

この例が何をしているかを説明していきます。
説明するのはlogging.warning('Watch out!')です。
なぜ「WARNING:root:Watch out!」と出力されているか、今の理解をダンプします。

logging.warningはlogging.basicConfigを呼び出す

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

logging.debugのドキュメントにまとめられています：
https://docs.python.org/ja/3/library/logging.html#logging.debug

ルートロガーにハンドラが接続されていない場合、この関数 (および info(), warning(), error() そして critical()) は basicConfig() を呼び出します。

「もっとも単純な例」では、ルートロガーにハンドラを接続するようなコードを書いていませんから、logging.basicConfigが引数無しで呼び出されています1。

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

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

デフォルトの Formatter を持つ StreamHandler を生成してルートロガーに追加し、ロギングシステムの基本的な環境設定を行います。

デフォルトのFormatterにより、ログメッセージは「WARNING:root:Watch out!」という書式となり、
StreamHandlerによりログが画面に出力されます。

ルートロガー

ルートロガーはログレベルがWARNINGに設定されています。

>>> import logging
>>> logging.warning('Watch out!')
WARNING:root:Watch out!
>>> logging.getLogger()  # ルートロガーを取得
<RootLogger root (WARNING)>

「basicConfigの中で設定したのだろうか？」と実装を追ったところ、ログレベルWARNINGで初期化していました。
https://github.com/python/cpython/blob/v3.10.9/Lib/logging/__init__.py#L1935

root = RootLogger(WARNING)

logging.Formatter

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

fmt が指定されない場合、 '%(message)s' が使われます。

logging.basicConfigではfmt引数を指定しています。
basicConfigを引数無しで呼び出したときの、Formatter呼び出しイメージです。

# https://github.com/python/cpython/blob/v3.10.9/Lib/logging/__init__.py#L516-L520
_STYLES = {
    '%': (PercentStyle, BASIC_FORMAT),
    '{': (StrFormatStyle, '{levelname}:{name}:{message}'),
    '$': (StringTemplateStyle, '${levelname}:${name}:${message}'),
}

# https://github.com/python/cpython/blob/v3.10.9/Lib/logging/__init__.py#L2046-L2052
dfs = kwargs.pop("datefmt", None)
style = kwargs.pop("style", '%')
fs = kwargs.pop("format", _STYLES[style][1])
fmt = Formatter(fs, dfs, style)

basicConfigを引数無しで呼び出したとき、styleは'%'を指します。
このとき_STYLES[style]は(PercentStyle, BASIC_FORMAT)となるので、_STYLES[style][1]はBASIC_FORMATです。
https://github.com/python/cpython/blob/v3.10.9/Lib/logging/__init__.py#L514

BASIC_FORMAT = "%(levelname)s:%(name)s:%(message)s"

LogRecord 属性を参照すると

  • %(levelname)s

    • メッセージのための文字のロギングレベル ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')。

  • %(name)s

    • ロギングに使われたロガーの名前。

  • %(message)s

    • msg % args として求められた、ログメッセージ。

です。
これで「WARNING:root:Watch out!」となる理由が分かりましたね。
basicConfig()という引数なしの呼び出しでは、FormatterにBASIC_FORMAT（ロギングレベル:ロガーの名:ログメッセージ）が設定されるのです！

logging.StreamHandler

https://docs.python.org/ja/3/library/logging.handlers.html#logging.StreamHandler

stream が指定された場合、インスタンスはログ出力先として指定されたストリームを使います; そうでない場合、 sys.stderr が使われます。

basicConfigを引数無しで呼び出したときの、StreamHandler呼び出しイメージです。

# https://github.com/python/cpython/blob/v3.10.9/Lib/logging/__init__.py#L2043-L2044
stream = kwargs.pop("stream", None)
h = StreamHandler(stream)

basicConfigを引数無しで呼び出したとき、StreamHandler(None)なのでsys.stderr（標準エラー出力）が使われるのですね！
ログが標準エラー出力に出力される理由がようやく分かりました。

ルートロガーに設定されたStreamHandlerを見てみると

>>> import logging
>>> logging.warning('Watch out!')
WARNING:root:Watch out!
>>> logging.getLogger().handlers
[<StreamHandler <stderr> (NOTSET)>]

ハンドラのレベルはNOTSETです。

https://docs.python.org/ja/3/library/logging.html#logging.Handler.setLevel

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

ということで、NOTSETになっているようです。

まとめ：もっとも単純な例でやっていること

logging.warningでメッセージを出力する裏ではlogging.basicConfig()が（引数無しで）呼び出されている

  • ルートロガーのログレベルはWARNING
  • FormatterとStreamHandlerを生成して、ルートロガーに追加
    • FormatterはBASIC_FORMAT（"%(levelname)s:%(name)s:%(message)s"）で初期化される
    • StreamHandlerは標準エラー出力、レベルNOTSETで初期化される

終わりに

logging.warningと呼んだだけですが、裏ではルートロガーにフォーマッタやハンドラが設定されているんですね！
仕組みが分からなくてもlogging.warningは使えますが、仕組みが分かると解像度が上がった感じがします。
魔法でなくなった感じです。

Pythonのloggingはlogging.warningから、ロガー・フォーマッタ・ハンドラ（などなど）の登場人物を理解して使えるようになるまでに大きな溝があるように感じます。
logging.warningでルートロガーを無自覚で使っていたのに、いきなりロガーとかフォーマッタとかハンドラとか登場人物増やされてもﾜｹﾜｶﾝﾅｲﾖｰ!
そこの架け橋となるかなと考えているのが、今回説明したようなlogging.warningの裏側の理解です。

裏側を覗くとフォーマッタやハンドラがいました。
この理解があると、いきなり登場人物が増えたと感じずに、それらを組み合わせてloggingを使える一歩目が踏み出しやすいのではないかと今の私は考えています。

  1. 実装を見ると明らかです https://github.com/python/cpython/blob/v3.10.9/Lib/logging/__init__.py#L2115-L2123↩