Python logging: ルートロガーのデバッグレベルをINFOにしたけど、logger.infoで出力されない理由


# 環境

  * Windows10
  * Python 3.6.6

# やりたいこと

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

[code]

    $ ls
    logger-main.py
    fuga.py
    logging.yaml
    
[/code]

### logger-main.py

[code]

    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()
    
[/code]

### fuga.py

[code]

    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")
    
    
[/code]

### logger.yaml

[code]

    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]
    
[/code]

### 問題

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

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

[code]

    loggers:
      other:
        level: DEBUG
      hoge:
        level: DEBUG
    
[/code]

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

[code]

    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
    
[/code]

### 質問

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




> なぜ最初の状態では、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のログ設定の説明](https://docs.djangoproject.com/ja/2.1/topics/logging/#configuring-
logging)でもFalseに指定するように書かれています。
<https://docs.python.org/ja/3.6/library/logging.config.html#logging.config.fileConfig>
によると、 `disable_existing_loggers=True` がデフォルト値なのは、後方互換性のためのようです。

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




> なぜ最初の状態では、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のログ設定の説明](https://docs.djangoproject.com/ja/2.1/topics/logging/#configuring-
logging)でもFalseに指定するように書かれています。
<https://docs.python.org/ja/3.6/library/logging.config.html#logging.config.fileConfig>
によると、 `disable_existing_loggers=True` がデフォルト値なのは、後方互換性のためのようです。

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

