Python: ロギング設定をファイルから読み込むときの注意点

大昔にハマった問題を忘れていて、またやってしまったので備忘録として残しておく。結論から先に書いておくと、まず Python でロギングの設定をファイルから読み込むときは logging.config.fileConfig() という関数を使う。そのとき disable_existing_loggers というオプションに False を指定するのを忘れないようにしましょうね、という話。

使った環境は次の通り。

$ sw_vers 
ProductName:    Mac OS X
ProductVersion: 10.13.4
BuildVersion:   17E199
$ python -V
Python 3.6.5

下準備

次のようにロギングの設定ファイルを用意しておく。出力するときの行フォーマットとかファイルのローテーティングとか色々と設定できる。ログ自体は /var/tmp/example.log というパスに出力されるようになっている。

$ cat << 'EOF' > logging.conf
[loggers]
keys=root

[handlers]
keys=timedRotatingFileHandler

[logger_root]
level=DEBUG
handlers=timedRotatingFileHandler

[handler_timedRotatingFileHandler]
class=logging.handlers.TimedRotatingFileHandler
level=DEBUG
formatter=simpleFormatter
args=('/var/tmp/example.log', 'D', 1, 100)

[formatters]
keys=simpleFormatter

[formatter_simpleFormatter]
format=%(asctime)s %(process)d %(threadName)s %(name)s %(levelname)s %(message)s
datefmt=
EOF

上記設定ファイルの書式については、次の公式ドキュメントに書かれている。

16.7. logging.config — ロギングの環境設定 — Python 3.6.5 ドキュメント

上手くいくパターン

まずは上手くいくパターンについて。 Python の REPL を起動しておく。

$ python

いきなりだけど logging.config.fileConfig() を使ってロギングの設定ファイルを読み込む。

>>> from logging import config
>>> config.fileConfig('logging.conf')

それから logging.getLogger() を使ってロガーを取得する。

>>> import logging
>>> LOG = logging.getLogger(__name__)

取得したロガーを使ってログを書き出す。

>>> LOG.error('something went wrong')

一旦 Python の REPL から抜けよう。

>>> exit()

そして、ログファイルの内容を cat コマンドで確認する。

$ cat /var/tmp/example.log
2018-04-12 23:21:33,273 16027 MainThread __main__ ERROR something went wrong

ちゃんとログが書き出されていることが分かる。

上手くいかないパターン

続いては上手くいかないパターンを確認してみよう。もう一度 Python の REPL を起動する。

$ python

続いては、先ほどと実行するコードの順序を入れ替える。先に logging.getLogger() を使ってロガーを取得しておく。

>>> import logging
>>> LOG = logging.getLogger(__name__)

そして、ロガーを取得した後からロギングの設定を logging.config.fileConfig() を使って読み込む。

>>> from logging import config
>>> config.fileConfig('logging.conf')

それでは、最初に取得したロガーを使ってログを書き出してみよう。

>>> LOG.error('something went wrong')

別のターミナルからログが書き出されるはずのファイルの内容を確認する。

$ cat /var/tmp/example.log 
2018-04-12 23:21:33,273 16027 MainThread __main__ ERROR something went wrong

すると、なんと前回の内容から何も変わっていない！つまりログが書き出されていない。

ここで、試しにロガーを取得し直してみよう。同じ名前を指定すると、同じオブジェクトが返されてしまうので何らか別のものにする。

>>> LOG = logging.getLogger('some.other.name')
>>> LOG.error('something went wrong')

もう一度ログファイルを確認すると、今度はちゃんとログが書き出されている。

$ cat /var/tmp/example.log 
2018-04-12 23:21:33,273 16027 MainThread __main__ ERROR something went wrong
2018-04-12 23:29:32,561 16343 MainThread some.other.name ERROR something went wrong

上記のような現象が起きる理由としては logging.config.fileConfig() のオプションが関係している。この関数には disable_existing_loggers という真偽値のオプションがあって、デフォルトでは True になっている。このオプションが True のままだと、ロギング設定ファイルを読み込むタイミングで過去に取得したロガーが使えなくなってしまう。ロガー自体はロギング設定ファイルを読み込むよりも前にモジュール変数として静的に読み込むことも多い。そのため、この問題にハマってログが出力されず悩むということが起こる。

解決策

この問題の解決策としては logging.config.fileConfig() を呼ぶときに disable_existing_loggers=False を忘れずにつけようね、という点に尽きる。

$ python

先ほどと同じように、先にロガーを取得しておく。

>>> import logging
>>> LOG = logging.getLogger(__name__)

そして logging.config.fileConfig() を呼ぶときに disable_existing_loggers=False を指定する。

>>> from logging import config
>>> config.fileConfig('logging.conf', disable_existing_loggers=False)

最初に取得したロガーでログを書き出してみよう。

>>> LOG.error('something went wrong')

ログファイルを確認すると、今度はちゃんとログが書き出されている。

$ cat /var/tmp/example.log 
2018-04-12 23:21:33,273 16027 MainThread __main__ ERROR something went wrong
2018-04-12 23:29:32,561 16343 MainThread some.other.name ERROR something went wrong
2018-04-12 23:35:46,950 16383 MainThread __main__ ERROR something went wrong