ライブラリ開発者に贈る「ロギングで `NullHandler` 以外はいけません」

2024/08/31に PyCon mini Shizuoka 2024 が開催予定でしたが、台風10号のために延期となりました
発表準備をしていたので、手元で収録して公開しています（振替開催版は別に用意します）

ライブラリ開発者に贈る「ロギングで `NullHandler` 以外はいけません」

Event:: PyCon mini Shizuoka 2024（延期）
Presented:: 2024/08/31 nikkie

お前、誰よ

nikkie ／ @ftnext ／ブログ連続 650 日突破
機械学習エンジニア・自然言語処理（We're hiring!）
Python歴は6年。PyConで登壇多数

アンケート（何度でも挙げよう）

logging.warning() や logging.error() したことある🙋‍♂️
logging.basicConfig() したことある🙋‍♀️
logging.getLogger() したことある🙋

本トークの対象者

Pythonのloggingモジュール 触ったことがある
loggingモジュールの中身はよく分からなくて全然OK👌

皆さんに質問です

あなたはPythonで import して使いたいコードを書いています（例：ライブラリ）
その中で ロギング 、どう実装しますか？

結論：「`NullHandler` 以外はいけません」

import logging

logger = logging.getLogger("mylib")
logger.addHandler(logging.NullHandler())

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

すべて公式ドキュメントに書いてあります！

しかし、観測範囲ではPython使いに気づかれていない印象...😫
📄の付いたリンクは、公式ドキュメントへのリンク
（別のemoji：🏃‍♂️は本編では飛ばします）

本トークのメッセージ（Takeaway）

ライブラリ開発者は ロガー を用意し、 何もしないハンドラ を設定しよう
アプリケーション開発者は ルートロガー を設定し、 propagate を利用してログを表示しよう

斜体はこのトークで解説します

これらはオススメしません（ぶっぶー🙅‍♂️） 🏃‍♂️

logging.basicConfig()

logging.warning()

logger = logging.getLogger("mylib")
logger.addHandler(logging.StreamHandler())

import して使いたいコードでの話です

Logging クックブックの「避けるべきパターン」の1つ

ライブラリ内でロガーに NullHandler 以外のハンドラーを追加する 📄

(略) ログ出力をカスタマイズするのはライブラリ開発者ではなく、アプリケーション開発者の責務です。

本トークの構成

ライブラリ開発者へ
アプリケーション開発者へ
落ち穂拾い

1️⃣ライブラリ開発におけるロギングの実装

あなたが作るライブラリにロギングをどう仕込むか

ライブラリのためのロギングの設定 📄の2点

logging.getLogger(...) （ロガー）
logger.addHandler(...) （ハンドラ）

logging.getLogger("mylib").addHandler(logging.NullHandler())

先行発表：loggingの構成要素（🎥 ）

1️⃣-1️⃣ logging.getLogger(...) 📄

Return a logger with the specified name (略)

「指定された名前のロガーを返す」

ロガー

ロガーは、アプリケーションコードが直接使うインターフェースを公開します。

上級ロギングチュートリアル 📄

ロギングのためのインターフェース

You can access logging functionality by creating a logger via logger = getLogger(__name__), and then calling the logger's debug(), info(), warning(), error() and critical() methods.

「基本 logging チュートリアル」📄の「logging を使うとき」

開発者はロガーを操作すればOK

getLogger(...) でロガーインスタンスを得る
ロガーインスタンスのメソッドを呼び出してロギング

logger.warning("ちょっとヤバいよ")
logger.error("ヤバイよ。マジヤバイよ")

そもそも、なぜロギングする？

ロギングのイメージ

try:
    大事な処理()
except Exception as ex:
    logger.warning("Raised %s", repr(ex))

開発者はイベントの発生を記録する

ソフトウェアの開発者は、特定のイベントが発生したことを示す logging の呼び出しをコードに加えます。

基本 logging チュートリアル 📄

イベントにはレベル（重要性）も含む

イベントには、開発者がそのイベントに定めた重要性も含まれます。重要性は、レベル (level) や重大度 (severity) とも呼ばれます。

基本 logging チュートリアル 📄

ロギングレベル 5つ

DEBUG
INFO
WARNING
ERROR
CRITICAL

logging を使うとき 📄（基本 logging チュートリアル）

ロガーもレベルを持つ

ロガーはメソッドを持っていた（＝ロギングのインターフェース）
ログが記録されるのは、 ロガーの持つレベル以上 の重要性のイベント

level よりも深刻でないログメッセージは無視されます（Logger.setLevel 📄）

例：ログが記録される場合

WARNING レベルのロガー logger は

logger.warning() は記録する
logger.info() は記録しない

ログレコード 🏃‍♂️

LogRecord インスタンスは、何かをログ記録するたびに Logger によって生成されます。

LogRecord オブジェクト 📄

ロガーの名前について

getLogger に渡す引数の話

ドット（ピリオド）区切り

ロガー名は、何でも望むものにでき、ロギングされたメッセージが発生した場所を指し示します。（上級ロギングチュートリアル 📄）

logging.getLogger("spam")
logging.getLogger("spam.ham")

ロガーの親子関係

logger = logging.getLogger("spam.ham")

spam.ham ロガーの親にあたるのが spam ロガー
すべてのロガーの親 ルートロガー （logging.getLogger()）

ロガーの親子関係

`logging.getLogger(name)` 🏃‍♂️

__name__ はモジュールの名前（3.2.9. モジュール 📄）
このコードで モジュールレベルのロガー インスタンスを得た

ロガー名だけで、どこでイベントのログが取られたか、直感的に明らかになります。（上級ロギングチュートリアル 📄）

同名のロガー 🏃‍♂️

与えられた名前に対して、この関数はどの呼び出しでも同じロガーインスタンスを返します。 (logging.getLogger(...) 📄)

シングルトンなので都度 getLogger ！（避けるべきパターン 📄も参照）

>>> logging.getLogger("mylib") is logging.getLogger("mylib")
True

ロガーまとめ🥟 ここまででロギングできます

import logging

logger = logging.getLogger("mylib")

logger.warning("ちょっとヤバいよ")

ちょっとヤバいよ

1️⃣-2️⃣ `logger.addHandler(...)`

ハンドラは、(ロガーによって生成された) ログ記録を適切な送信先に送ります。（上級ロギングチュートリアル 📄）

ロガーはハンドラを持つ

1つのロガーが 0個以上のハンドラを持つ
ハンドラはログレコードを出力先に振り分ける

ハンドラ（上級ロギングチュートリアル） 📄

ログメッセージの流れ 🏃‍♂️

logger.warning("<ログメッセージ>")

開発者はロガーのメソッドを呼び出してイベントを記録
ロガーの持つレベル以上の呼び出しのとき、ロガーは ログレコード を作成
ロガーはハンドラにログレコードを渡し、ハンドラがログを出力

ログの出力先に応じたハンドラ

ストリーム StreamHandler
ファイル FileHandler
まだまだあります：便利なハンドラ 📄（ログファイルのローテーションなど）

先のコードはなぜロギングできたか

import logging

logger = logging.getLogger("mylib")

logger.warning("ちょっとヤバいよ")

ハンドラを指定しないとき

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

環境設定が与えられないとどうなるか 📄

最終手段ハンドラによるログ出力

ちょっとヤバいよ

warning以上のログメッセージが、標準エラー出力に表示される
フォーマットはなし

常に最終手段ハンドラを使わなきゃいけない？

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

ライブラリのためのロギングの設定 📄

`NullHandler`

何もしない ハンドラ

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

最終手段ハンドラの出番にはしたくない

ライブラリのロガーになにかハンドラを持たせよう
何もしないハンドラ （NullHandler）の出番！

ライブラリのためのロギングの設定 📄

最終手段ハンドラの出番はなく、ログ出力はない

import logging

logger = logging.getLogger("mylib")
logger.addHandler(logging.NullHandler())

logger.warning("ちょっとヤバいよ")

まとめ🥟 ライブラリ開発におけるロギングの実装

logging.getLogger("mylib").addHandler(logging.NullHandler())

あなたのライブラリ用のロガーインスタンスを得よう
最終手段ハンドラを望まない場合、 NullHandler を持たせよう

2️⃣アプリケーション開発におけるロギングの実装

ロギングが仕込まれたライブラリをどう使うか

アプリケーション開発者がログ出力をカスタマイズ！

ハンドラーやフォーマッター (略) を追加してログ出力をカスタマイズするのは (略)、アプリケーション開発者の責務です。

ライブラリ内でロガーに NullHandler 以外のハンドラーを追加する 📄（再掲）

ログ出力のカスタマイズ 2通り

ルートロガーを設定 （👈主な話題）
ライブラリのロガーを触る

ルートロガーを設定する

アプリケーション開発者に提供される手段が logging.basicConfig()

logging.basicConfig() 📄

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

`logging.basicConfig()` に関わる概念

ロギングレベル
フォーマッタ

他の要素は公式ドキュメントをどうぞ

ルートロガーのレベルを設定

logging.basicConfig(level=logging.WARNING)

loggingでは、ロガーの持つレベル以上の重要性のイベントがログに記録される（再掲）

フォーマッタ

logging.basicConfig(format="%(levelname)s:%(name)s:%(message)s")

ハンドラは1つのフォーマッタを持つ
ハンドラの出力に適用される 書式の設定

書式設定に使える属性名 🏃‍♂️

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

LogRecord 属性 📄

ルートロガーをカスタマイズ

アプリケーション開発者 （ライブラリを使う側）が好きに 決められます

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

ルートロガーを設定してライブラリのログを出力

propagate （伝播）

ロガーの propagate 属性📄

この属性が真と評価された場合、このロガーに記録されたイベントは、このロガーに取り付けられた全てのハンドラに加え、上位 (祖先) ロガーのハンドラにも渡されます。

ロガーの親子関係（再び）

../_images/logger-ancestors-part.drawio.png

propagate（伝播）

spam ロガーのロギングレベル以上のメソッドが呼ばれた
- 例：ロガーのレベルは WARNING で、 warning() メソッドが呼ばれた
そのログレコードは 親のロガーに伝播 し、親のハンドラにも渡る

📌 `NullHandler` + `basicConfig` + propagate

mylib ロガーのロギングレベル以上のメソッドが呼ばれた
mylib ロガーのハンドラ（NullHandler）が処理（するが出力はない）
親のルートロガーに伝播し、 ルートロガーのハンドラで処理して出力される

ドキュメント propagate の注釈📄より

一般的なシナリオでは、ハンドラをルートロガーに対してのみ接続し、残りは propagate にすべて委ねます。

ロガー 📄（上級ロギングチュートリアル）🏃‍♂️

子ロガーはメッセージを親ロガーのハンドラに伝えます。(略) トップレベルのロガーのためのハンドラだけ設定しておいて必要に応じて子ロガーを作成すれば十分です。

待って🤚 ライブラリのロガーのレベルって？

今一度 ライブラリ開発者向け の話になります

`NullHandler` 以外はいけません（結論・再掲）

import logging

logger = logging.getLogger("mylib")
logger.addHandler(logging.NullHandler())

ライブラリのロガーに ロギングレベルは設定していない

ロギングレベル `NOTSET`

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

Logger.setLevel 📄より

`NOTSET` とは

もしロガーのレベルが NOTSET ならば、祖先ロガーの系列の中を NOTSET 以外のレベルの祖先を見つけるかルートに到達するまで辿っていく

Logger.setLevel 📄より（「親ロガーに委譲」）

ライブラリのロガーにロギングレベルを設定したいとき

親をそのまた親へとたどっていき、最初に見つかった NOTSET 以外のレベルになる、ということ（ロギングレベル 📄）
mylib ロガーは、親の ルートロガーに設定したレベル となる！

拙ブログよりロギングレベル `NOTSET` 🏃‍♂️

propagate まとめ🥟 ライブラリのロギング

import logging

logger = logging.getLogger("mylib")
logger.addHandler(logging.NullHandler())


def awesome():
    logger.info("想定通り")

例：ルートロガーのロギングレベルが `WARNING` だと出力されない

import logging

from mylib import awesome

logging.basicConfig(level=logging.WARNING)

awesome()

mylib ロガーも WARNING レベル

例：ルートロガーのロギングレベルが `DEBUG` だと出力される

import logging

from mylib import awesome

logging.basicConfig(level=logging.DEBUG)

awesome()

INFO:mylib:想定通り

mylib ロガーも DEBUG レベル

違いはルートロガーのロギングレベル

ライブラリのコードは同じ
ライブラリのロガーはレベル NOTSET で、ルートロガーのレベルを参照
ライブラリを利用するアプリケーションコードでカスタマイズした

まとめ🥟 アプリケーション開発におけるロギングの実装

logging.basicConfig(level=logging.DEBUG, format="%(levelname)s:%(name)s:%(message)s")

ライブラリを使う側の都合で、ルートロガーを設定
ライブラリのロガーはルートロガーのレベルを参照し、propagateで ルートロガーのハンドラでログ出力

propagateは親ロガーのレベルによらない 🏃‍♂️

メッセージは、祖先ロガーのハンドラに直接渡されます - 今問題にしている祖先ロガーのレベルもフィルタも、どちらも考慮されません。

propagate

propagateで祖先ロガーのレベルが考慮されない例 🏃‍♂️

import logging

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

logger = logging.getLogger("mylib")
logger.setLevel(logging.INFO)

logger.info("想定通り")

2024-08-29 21:42:01,945 | INFO | mylib:<module>:11 - 想定通り

ライブラリのロガーを触ってログ出力をカスタマイズ 🏃‍♂️

アプリケーションコードで getLogger("mylib") し、レベル・ハンドラ・フォーマッタを設定
拙ブログ Pythonのライブラリに用意されたロガーを設定してログを出力する（httpxを例に）

3️⃣落ち穂拾い

ライブラリで NullHandler を使わない（アンチパターン）
Logging Flow

3️⃣-1️⃣ ライブラリのロギングのアンチパターン

なぜ「NullHandler 以外はいけません」なのか

⚠️ `NullHandler` 以外のハンドラを設定してみる

import logging

logger = logging.getLogger("mylib")
logger.addHandler(logging.StreamHandler())

2重出力😱

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

想定通り
2024-08-31 14:16:34,968 | INFO | antipattern_logging.add_non_nullhandler:awesome:8 - 想定通り

2重出力の裏にpropagate

mylib ロガーのロギングレベル以上のメソッドが呼ばれた
mylib ロガーのハンドラ（StreamHandler）が処理して出力
親のルートロガーに伝播し、 ルートロガーのハンドラでも処理 して出力

ライブラリのためのロギングの設定の注釈📄

ライブラリのロガーには、 NullHandler 以外のハンドラを追加しないことを強く推奨します。これは、ハンドラの設定が、あなたのライブラリを使うアプリケーション開発者にも伝播するからです。

もう1例：ライブラリがルートロガーを触る

これもやってはいけません

⚠️ ライブラリで `basicConfig()`

import logging

logging.basicConfig(
    level=logging.DEBUG, format="%(levelname)s:%(name)s:%(message)s"
)

`basicConfig()` がルートロガーを設定するのは「一度だけ」

(略) ルートロガーに設定されたハンドラがあれば何もしません。(logging.basicConfig() 📄)

ライブラリがルートロガーにハンドラを設定してしまうと、 アプリケーションコードで呼び出しても何も起こらない 😭（詳しくはブログ記事に）

ライブラリではルートロガーは触らない

あなたのライブラリからルートロガーへ直接ログを記録しないことを強く推奨します。

ライブラリのためのロギングの設定 📄

`logging.warning()` なども全部 `basicConfig()` を呼んでます

if the root logger has no handlers, then basicConfig() is called, prior to calling debug on the root logger. (📄 logging.debug())

basicConfig() 同様にライブラリで使ってはいけません

3️⃣-2️⃣ Logging Flow

Logging Flow 📄を読み解く

Pythonのloggingの構成要素

ロガー
ロギングレベル
ハンドラ
フォーマッタ
フィルタ （👉 Appendix）

ロガーを構成する要素

ロギングレベル
ハンドラ（0個以上）
フィルタ （0個以上）

ハンドラを構成する要素

ロギングレベル （👉 Appendix）
フォーマッタ（1個）
フィルタ （0個以上）

なぜこんなに構成要素がある？

柔軟なロギング を提供
例：ロガーに複数のハンドラを設定。ハンドラのロギングレベルを使って、レベルごとに異なる出力先へ出し分ける

それぞれのハンドラで設定されるレベルは、そのハンドラがどのメッセージを転送するべきか決めます。(ハンドラ（上級ロギングチュートリアル） 📄)

Logging Flow

構成要素がどのように組み合さって動くかを示す

一例：propagate（ただし抜粋）

ライブラリのロガーのレベル以上の呼び出し
そのロガーのハンドラがログレコードを処理
ライブラリのロガーの親のハンドラにもログレコードが渡る（親のレベルは見ない）

まとめ🌯 ライブラリ開発者に贈る「ロギングで `NullHandler` 以外はいけません」

import logging

logger = logging.getLogger("mylib")
logger.addHandler(logging.NullHandler())

📣ライブラリのユーザが自由にロギングをカスタマイズできるようにしよう

そのための NullHandler
propagateを使って、 ユーザが設定するルートロガーのハンドラでログ出力

メッセージ（Takeaway）再掲 🏃‍♂️

ライブラリ開発者はロガーを用意し、 何もしないハンドラを設定 しよう
アプリケーション開発者はルートロガーを設定し、 propagateを利用してログを表示 しよう

ご清聴ありがとうございました

Enjoy Python logging❤️

Appendix

ハンドラのロギングレベル

結論のコード、NullHandler のレベルは NOTSET

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

Handler.setLevel 📄

フィルタ

ロガーやハンドラに取り付けられる

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

フィルタは何をするのか

(略) name はロガーの名前を表します。指定されたロガーとその子ロガーのイベントがフィルタを通過できるようになります。(logging.Filter() 📄)

ロガーの階層構造が関係

例： `logging.Filter("A.B")`

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

フィルタオブジェクト 📄

環境設定（このトークではスコープアウト）

logging.config 📄
dictConfig や fileConfig
最初に読むなら『Python実践レシピ』17.4

これまでのlogging関連アウトプット

2023年3月みんなのPython勉強会（資料公開のみ）

拙ブログより、logging関連エントリ 1/4

拙ブログより、logging関連エントリ 2/4

拙ブログより、logging関連エントリ 3/4

拙ブログより、logging関連エントリ 4/4

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

お前、誰よ（詳細版）

@ftnext ／登壇 2024 2023
PyCon JP 2021 座長
毎月のみんなのPython勉強会スタッフ
代表作：Sphinx拡張 sphinx-new-tab-link

ライブラリ開発者に贈る「ロギングで NullHandler 以外はいけません」