root配下の子ロガーをいきなり呼ぶ際の注意

はじめに

Effective Python 第2版 ―Pythonプログラムを改良する90項目 の項目66「contextlibとwith文をtry/finallyの代わりに考える」に掲載されている以下のコードを実行したところ何も表示されませんでした。

wrong_logging.py

import logging
from contextlib import contextmanager


@contextmanager
def log_level(level, name):
    logger = logging.getLogger(name)
    old_level = logger.getEffectiveLevel()
    logger.setLevel(level)
    try:
        yield logger
    finally:
        logger.setLevel(old_level)

with log_level(logging.DEBUG, 'my-log') as logger:
    logger.debug(f'This is a message for {logger.name}!')
    logging.debug('This will not print')

説明を読む限りでは、with句において root 配下に作成された子ロガー my-log のログレベルは DEBUG に設定されているため、本来であればwith句内部の1行目の logger.debug() の出力が期待されるはずです。何が起きてるのでしょう？

因みにgithubで公開されている項目66のコードをダウンロードして実行すると、件のメッセージは表示されます。おや？

結論

最初に結論を言ってしまうと、親ロガー（名前がroot）でログメッセージを出力する前に子ロガーを呼ぶと、最初の一回目は何も表示されない、です。この使い方が正しい使い方なのかわかりませんが、子ロガーをいきなり呼びたい場合には以下のいずれかをする必要があります。

• 子ロガーのためのハンドラーを設定する
• 子ロガーを作成した直後で logging.basicConfig() を実行する

環境

	バージョン
Linux	Ubuntu 20.04.3 LTS
Python	3.10.0

何が起きてた？

ログレベルはちゃんと変更されてる？

念のためにwith句の内外でログレベルが想定どおりになっているか確認してみましょう。

check_loglevel.py

with log_level(logging.DEBUG, 'my-log') as logger:
    print(logging.getLevelName(logger.getEffectiveLevel()))

logger = logging.getLogger('my-log')
print(logging.getLevelName(logger.getEffectiveLevel()))

実行結果

* INSIDE:  DEBUG
* OUTSIDE:  WARNING

さすがに問題はなさそうです。では logging パッケージ内部で何が起きているか見てみましょう。

debugメソッドの確認

debugメソッドの定義によれば、self.isEnabledFor(DEBUG) の場合にのみ _log() にメッセージが渡されています。確認してみましょう。

check_debug.py

with log_level(logging.DEBUG, 'my-log') as logger:
    print(logger.isEnabledFor(logging.DEBUG))

実行結果

True

問題なさそうですね。先に進みましょう。

handleメソッドの確認

_log() メソッドでは、makeRecord() で出力レコードを生成して handle() を呼び出しているだけなのでスキップします。

handleメソッド では self.disabled が偽かつ self.filter(record) が真である場合にのみ callHandlers() が呼ばれています。条件式がどうなってるか確認してみましょう。

check_condition_in_handle.py

with log_level(logging.DEBUG, 'my-log') as logger:
    print(logger.disabled)
    msg = f'This is a message for {logger.name}!'
    fn, lno, func = "(unknown file)", 0, "(unknown function)"
    exc_info = sys.exc_info()
    record = logger.makeRecord(logger.name, logging.DEBUG, fn, lno, msg, None, exc_info, func, None, None)
    print(logger.filter(record))

実行結果

False
True

callHandlers() が呼ばれる条件になっているようですので問題ありませんね。

callHandlersメソッドの確認

callHandlersメソッドを見ると、以下のような処理をしていることがわかります。

1. 子ロガーのハンドラーをチェックし、レコードに設定されているログレベルがハンドラーに設定されているログレベル以上であれば出力する
2. 子ロガーのハンドラーのチェックが終わり、親ロガーへの伝播フラグが真ならば親ロガーに対して 1. を実行する
3. メッセージを出力するためのハンドラーが見つからなかったら、レコードに設定されているログレベルが lastResort（_StderrHandler）に設定されているログレベル（WARNING）以上であれば出力する
4. 最終的にハンドラーが見つからなければ、その旨を通知する

では確認してみましょう。

check_callHandlers.py

with log_level(logging.DEBUG, 'my-log') as logger:
    msg = f'This is a message for {logger.name}!'
    fn, lno, func = "(unknown file)", 0, "(unknown function)"
    exc_info = sys.exc_info()
    record = logger.makeRecord(logger.name, logging.DEBUG, fn, lno, msg, None, exc_info, func, None, None)
    print("handlers(child):", logger.handlers)
    print("handlers(parent):", logger.parent.handlers)
    print("lastResort:", logging.lastResort)
    print(f'levelno = {record.levelno}, lastResort.level = {logging.lastResort.level}')

実行結果

handlers(child): []
handlers(parent): []
lastResort: <_StderrHandler <stderr> (WARNING)>
levelno = 10, lastResort.level = 30

これで logger.debug() で何も出力されなかった原因がわかりました。では、なぜ親（root）ロガーにハンドラーが設定されていないのでしょうか？

rootロガーの critical/fatal/error/warning/info/debug/log メソッド を見てみると、いずれかのメソッドが呼ばれた時にrootロガーのハンドラーを調べ、何も設定されていない場合には basicConfig() が呼ばれていることがわかります。このメソッドをキーワード引数なしで呼び出すと StreamHandler が設定されています。

サンプルプログラムの修正

結局、前述の wrong_logging.py は以下のように修正するとよさそうです。ここでは結論の「子ロガーを作成した直後で logging.basicConfig() を実行する」を採用しています。

correct_logging.py

import logging
from contextlib import contextmanager


@contextmanager
def log_level(level, name):
    logger = logging.getLogger(name)
    if len(logger.parent.handlers) == 0:
        logging.basicConfig()
    old_level = logger.getEffectiveLevel()
    logger.setLevel(level)
    try:
        yield logger
    finally:
        logger.setLevel(old_level)

with log_level(logging.DEBUG, 'my-log') as logger:
    logger.debug(f'This is a message for {logger.name}!')
    logging.debug('This will not print')

これを実行すると期待通りの結果が得られます。

実行結果

DEBUG:my-log:This is a message for my-log!