3

環境

  • Windows10
  • Python 3.6.6

やりたいこと

Pythonのlogging機能を使って、コンソールとログファイルにログを出力したいです。
otherという名前のlogger以外は、すべてINFOレベルで出力したいので、ルートロガーのレベルをINFOにしました。

$ ls
logger-main.py
fuga.py
logging.yaml

logger-main.py

import logging
import logging.config
import yaml
from fuga import Fuga


if __name__ == "__main__":
    logging.config.dictConfig(yaml.load(open("logging.yaml").read()))

    f = Fuga()

fuga.py

import logging
import yaml

logger = logging.getLogger(__name__)

class Fuga:
    def __init__(self):
        logger.debug("Fuga Constructor in debug")
        logger.info("Fuga Constructor in info")

logger.yaml

version: 1
formatters:
  customFormatter:
    format: '%(asctime)s : %(levelname)s : %(module)s : %(message)s'
handlers:
  fileRotatingHandler:
    class: logging.handlers.TimedRotatingFileHandler
    level: DEBUG
    filename: logfile/logger.log
    when: 'D'
    formatter: customFormatter
  consoleHandler:
    class: logging.StreamHandler
    level: DEBUG
    formatter: customFormatter
loggers:
  other:
    level: DEBUG
root:
  level: INFO
  handlers: [fileRotatingHandler, consoleHandler]

問題

$ python logger-main.pyを実行しましたが、標準出力とログファイルには何も出力されませんでした。
ルートロガーをINFOレベルに設定したので、fugaのinfoログは出力されると思っていました。

以下のように、logger.yamlのloggers部分にfugaを追加したら、

loggers:
  other:
    level: DEBUG
  hoge:
    level: DEBUG

次のように、標準出力とログファイルに出力されていました。

2019-03-16 16:22:13,791 : DEBUG : fuga : Fuga Constructor in debug
2019-03-16 16:22:13,791 : INFO : fuga : Fuga Constructor in info

質問

なぜ最初の状態では、fugaのinfoログが出力されなかったのでしょうか?
私は「ルートロガー」の使い方を勘違いしているのでしょうか?

3 件の回答 3

4

なぜ最初の状態では、fugaのinfoログが出力されなかったのでしょうか?

dictConfig に渡す設定に disable_existing_loggers': False'loggers': {'fuga': {}} が必要ですが、これが指定されていないためです。

私は「ルートロガー」の使い方を勘違いしているのでしょうか?

rootロガーについては合っています。
fugaロガーが、dictConfigのデフォルト動作によって意図せず無効化されているのが、ログ出力されない原因です。

ロガーの初期化とdictConfigの動作は、以下の順に実行されています。

  1. fuga ロガーは、 from fuga import Fuga した時点で logging.getLogger(__name__) でインスタンスが作成されます。(これはよくある動作です)
  2. このあと、 logging.config.dictConfig でロガー全体を「再初期化」していますが、 fuga ロガーインスタンスは既に作成されています。
  3. dictConfig 関数は「新しい設定で上書きするか、disable_existing_loggers=Trueなら既存のロガーを無効化(削除ではない)」します。
  4. dictConfig に渡した辞書には fuga ロガーの設定がなく、また disable_existing_loggers の指定もないため、(1)で作成済みのfugaロガーを無効化します。
  5. 結果として、 fuga ロガー経由のログ出力は、本来であればpropagateによって親ロガー(rootロガー)に伝搬しますが、(4)で無効化されているため、なにもしません。

dictConfig()fileConfig() でアプリケーション全体のログ出力設定を初期化するには、 disable_existing_loggers=False にします。例えばDjangoのログ設定の説明でもFalseに指定するように書かれています。 https://docs.python.org/ja/3.6/library/logging.config.html#logging.config.fileConfig によると、 disable_existing_loggers=True がデフォルト値なのは、後方互換性のためのようです。

これに対して、 dictConfig()fileConfig() を使わずにプログラムでloggerインスタンスを組み立てる場合、このような制約はありません。

1
  • logging.getLoggerでインスタンスが作成されるんですね。知りませんでした。 >ロガーを直接インスタンス化することはできず、常にモジュール関数 logging.getLogger(name) を介してインスタンス化することに注意してください。 docs.python.org/ja/3/library/logging.html#logger-objects
    – yuji38kwmt
    2019年3月27日 2:06
3

理由は判明したもののベストプラクティスがまだわからない、という状況なのですけれども、ひとまず回答します。
logging.yamlに

disable_existing_loggers: False

の行がない場合、logging.conf.dictConfigを実行した時点でそれ以前に生成されていたロガーはすべて無効にされます
ここの少し上、disable_existing_loggers の項を参照してください。


このことを確認するのに、

import logging.config

import yaml

if __name__ == '__main__':
    logger = logging.getLogger('fuga')
    logging.config.dictConfig(yaml.load(open("logging.yaml").read()))
    logger.debug("do debug")
    logger.info("do info")

import logging.config

import yaml

if __name__ == '__main__':
    logging.config.dictConfig(yaml.load(open("logging.yaml").read()))
    logger = logging.getLogger('fuga')
    logger.debug("do debug")
    logger.info("do info")

の挙動の差を比較してみてください。


この設計(=disable_existing_loggersのデフォルト値がTrueだということ)だと、
ユーザレベルのモジュールのロガーの設定をlogging.configモジュールの関数でおこなうのは、ユーザレベルのモジュールインポートよりでなければならない
ということなのでしょうか??
それが本当に設計者の意図なのか? という疑問でいっぱいですが、ひとまず。

1
-1

追記:この回答は間違っているので他の方の回答を参考にしてください。

--

fuga.pyの中で
logger = logging.getLogger(__name__)
と書いておられますが、__name__はファイル名を表すので、実際に実行されるのは
logger = logging.getLogger('fuga')
となります。

つまり、'fuga'という名前のロガーを取得しています。そして、元のlogging.yamlではその名前のロガーは定義していないのでログは出力されません。(logging.yamlに'fuga'を追記するとログが出力されたのは、プログラム側が呼び出してるロガーが定義されたからです)

「ルートロガー」を利用されたいのであれば、以下のように記載すると良いと思います。
logger = logging.getLogger()

以下、ドキュメントも参考になります。
logging --- Python 用ロギング機能 — Python 3.7.3rc1 ドキュメント

この質問に回答するには、ログインする必要があります。

求めていた回答ではありませんか? のタグが付いた他の質問を参照する。