LoginSignup
5
3

More than 5 years have passed since last update.

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

Last updated at Posted at 2018-10-12

先に結論

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 で指定した新しい設定が適用されるようです。

5
3
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
5
3