Python
logger

python logger の初期化タイミングの罠

先に結論

disable_existing_loggers: False

にしておきましょう。

問題・原因

以下のような簡単なコードで、 cls.logger.info() が表示されません。

これは次の2つのことが原因と考えられます。

  • logging.config を行うとそれ以前に作成された logger インスタンスは disable: True になる
  • logger は同じ名前のものは(おそらく)キャッシュが働き、同じインスタンスが返される
    • よって logging.config 以前に作ってしまった名前の logger は後で getLogger しても disable: True になり出力されない
import logging.config


class Hoge:
    logger = logging.getLogger('hoge')

    @classmethod
    def print_log(cls):
        logging.getLogger('hoge').info('new hoge logger')  # 表示されない!
        logging.getLogger('fuga').info('new fuga logger')  # 表示される
        cls.logger.info('class hoge logger')               # 表示されない

        print('')
        print('new hoge disabled?:', logging.getLogger('hoge').disabled)  # True
        print('new fuga disabled?:', logging.getLogger('fuga').disabled)  # False
        print('class hoge disabled?:', cls.logger.disabled)               # True

        print('')
        print('new hoge instance:', id(logging.getLogger('hoge')))  # cls.logger と同じインスタンス
        print('new fuga instance:', id(logging.getLogger('fuga')))
        print('class hoge instance:', id(cls.logger))


if __name__ == '__main__':
    logging.config.dictConfig({
        'version': 1,
        'formatters': {
            'myFormatter': {
                'format': '%(asctime)s:%(message)s',
            }
        },
        'handlers': {
            'default': {
                'class': 'logging.StreamHandler',
                'level': 'DEBUG',
                'stream': 'ext://sys.stdout',
                'formatter': 'myFormatter',
            }
        },
        'root': {
            'level': 'DEBUG',
            'handlers': ['default'],
        },
        # 'disable_existing_loggers': False,  # このコメントを消すと解決
    })
    Hoge.print_log()

これは logger に対して logging.config で設定を行うと、過去に作られた logger が disable になるためです。
処理の順序は以下の様になります。

  1. class 直下が実行される
    1. cls.logger が作成される
  2. if __name__ == '__main__' 内が実行される
    1. logger が設定される(ここで cls.logger が disable: True になる)
    2. Hoge.print_log() が実行される
      1. getLogger('hoge') は cls.logger と同じ名前なので 値がキャッシュされており(?) これも disalbe: True になってしまう。よって出力されない。
      2. getLogger('fuga') は新規に作成される logger なので disalbe: False であり出力できる。
      3. cls.logger は disable: True なので出力されない。

同じ名前の logger が getLogger でキャッシュされるのかはわかりませんが、同じ名前の logger は同じインスタンスになるということは確認しています。
また、実用上はこの Hoge クラスは別のファイルに定義されており、 import で呼び出されることが多いと思いますが、 import がファイルの最上部にかかれていれば同じ現象がおきます。

解決策

disable_existing_loggers: False にするとこの問題は解決します。
上のコメントになっている行を復活させるだけ。

logging.config 以前に作成された logger に対しても、 logging.config で指定した新しい設定が適用されるようです。