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

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

先に結論

disable_existing_loggers: False

にしておきましょう。

問題・原因

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

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

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