Edited at

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