53483


# 環境

  * 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ログが出力されなかったのでしょうか？  
私は「ルートロガー」の使い方を勘違いしているのでしょうか？


CC BY-SA 4.0
2019-03-16T07:27:10.583
53467
2019-03-16T22:38:36.643
19524
question
python
Python logging: ルートロガーのデバッグレベルをINFOにしたけど、logger.infoで出力されない理由


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

\--

`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
ドキュメント](https://docs.python.org/ja/3/library/logging.html#logging.getLogger)


CC BY-SA 4.0
2019-03-16T11:54:50.203
53474
2019-03-16T22:38:36.643
2019-03-16T22:38:36.643
12561
12561
53467
answer


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

[code]

    disable_existing_loggers: False
    
[/code]

の行がない場合、`logging.conf.dictConfig`を実行した時点で **それ以前に生成されていたロガーはすべて無効にされます** 。  
[ここ](https://docs.python.org/ja/3.6/library/logging.config.html#incremental-
configuration)の少し上、disable_existing_loggers の項を参照してください。

* * *

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

[code]

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

と

[code]

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

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

* * *

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


CC BY-SA 4.0
2019-03-16T14:14:58.987
53481
2019-03-16T14:14:58.987
12274
53467
answer


> なぜ最初の状態では、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インスタンスを組み立てる場合、このような制約はありません。


CC BY-SA 4.0
2019-03-16T15:03:25.257
53483
2019-03-16T15:03:25.257
806
53467
answer