Python でモジュールごとに logging する。または dictConfig の落とし穴。

Python でちょっと凝ったログの出力をしたい場合 [logging](https://docs.python.org/ja/3/howto/logging.html) というライブラリを使うのが定番です。また設定には [dictConfig](https://docs.python.org/ja/3/library/logging.config.html#logging-config-dictschema) を使います。ただ後方互換性のために落とし穴があるので、意図しない動作になる時は [disable_existing_loggers](https://docs.python.org/3/library/logging.config.html#logging.config.fileConfig) を False にするのがコツです。と、いうような話題を書きます。

logging には２つの主要な要素 Logger と Handler があります。

* [Logger](https://docs.python.org/3/library/logging.html#logger-objects) にアプリやライブラリはログを書き込む。
* [Handler](https://docs.python.org/3/library/logging.html#handler-objects) でメインスクリプトはログの記録方法を指定する。
  * [Formatter](https://docs.python.org/3/library/logging.html#formatter-objects) でログの書式を設定する。

## 基本の使い方

基本の使い方は簡単です。

```python
# 以下の二行はイディオムです。現在のモジュール名が付いた Logger が出来ます。
import logging
logger = logging.getLogger(__name__)

# Logger には debug, info, warning などのメソッドがあるので、重要度に応じて使います。
logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')
```

この例では Handler が指定されていないので、デフォルトの Handler が使われます。デフォルトの Handler は WARNING 以上のログを stderr に書き込みます。というわけでここでは DEBUG や INFO は無視されて、次のように表示します。

```shell
Warn
```

ちょっと深入りしますが、デフォルトの動作の実装を見ます。

ライブラリコードを見ると、ここは [「何も Handler が登録されていない時は lastResort を使う」](https://github.com/python/cpython/blob/3.7/Lib/logging/__init__.py#L1596) となっています。

```python
        if (found == 0):
            if lastResort:
                if record.levelno >= lastResort.level:
                    lastResort.handle(record)
```

lastResort の定義は、[「level が WARNING で stderr に出力する StreamHandler」](https://github.com/python/cpython/blob/3.7/Lib/logging/__init__.py#L1156) です。このハンドラは全くカスタマイズ出来ないので、デフォルト動作はオマケと考えるべきです。

```python
_defaultLastResort = _StderrHandler(WARNING)
lastResort = _defaultLastResort
```

## info や debug を表示する。

WARNING 以下のログも表示したい場合は自分で Handler を用意します。(本当は [basicConfig](https://docs.python.org/ja/3/library/logging.html#logging.basicConfig) でもっと簡単に設定出来ますが、応用が効かないのでここでは触れません。)

```python
import logging
logger = logging.getLogger(__name__)

# ログを stderr に表示する StreamHandler を作る。
handler = logging.StreamHandler()

# logger に StreamHandler を設定する。
logger.addHandler(handler)

# logger の閾値を DEBUG 以上に設定する。
logger.setLevel(logging.DEBUG)

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')
```

`addHandler()` によってデフォルトの lastResort の代わりに指定した Handler を使います。そして `setLevel()` で閾値を設定します。`setLevel()` は Logger 側にも Handler 側にもあり、両方の条件を満たしたログだけ表示します。Logger 側の閾値のデフォルトは WARNING なので DEBUG を表示したい場合は明示的に `setLevel()` する必要があります。Handler 側のデフォルトは NOTSET (閾値なし) なので未設定で良いです。実行結果はこうなります。

```shell
Debug
Info
Warn
```

## Logger の階層構造

Logger には階層構造があります。

* logging.getLogger(): getLogger を引数無しで呼ぶと root logger が得られる。すべての Logger の親。
* logging.getLogger('parent'): getLogger に引数を指定すると、名前付き logger が返る。通常 `logging.getLogger(__name__)` を使う。
* logging.getLogger('parent.child'): 名前は . で区切った階層構造を持つ。'parent.child' の親は 'parent'。

先程、「Logger の閾値のデフォルトは WARNING」と書いたのは嘘です。正確には:

* Logger の閾値のデフォルトは NOTSET。つまり未設定。この場合親の閾値が使われる。
* logger.getLogger() すなわち root logger の閾値はデフォルトで WARNING。
* よって、Logger の実質的な閾値のデフォルトは WARNING。

この動作を確認するために、`logging.getLogger(__name__)` で得られる logger `__main__` の代わりに root logger を設定しても上記と同じ結果になります。

```python
import logging
logger = logging.getLogger(__name__)

# ログを stderr に表示する StreamHandler を作る。
handler = logging.StreamHandler()

# logging.getLogger(__name__) の代わりに root logger に StreamHandler を設定して閾値を DEBUG にする。
logging.getLogger().addHandler(handler)
logging.getLogger().setLevel(logging.DEBUG)

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')
```

## モジュールのログを表示

複数のモジュールで出来ているプログラムのログが必要な時に、モジュールを選んで表示したり閾値を変えたくなります。たとえば module.py という名前のモジュールがあるとします。

```python
# module.py
import logging
logger = logging.getLogger(__name__)

def log():
    logger.debug('Debug')
    logger.info('Info')
    logger.warning('Warning')
```

これ呼び出して、先程と同じように Debug ログを表示してみます。分かりやすいように書式も変更します。

```python
import module
import logging
logger = logging.getLogger(__name__)

# ログを stderr に表示する StreamHandler を作り、書式を設定する。
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter("%(levelname)s:%(name)s:%(message)s"))

# logger に StreamHandler を設定する。
logger.addHandler(handler)

# logger の閾値を DEBUG 以上に設定する。
logger.setLevel(logging.DEBUG)

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

module.log()
```

残念ながら、Debug ログが表示されたのはメインのスクリプトだけで、`module.log()` にはデフォルトの handler が適用されてしまい Debug が表示されません。

```shell
DEBUG:__main__:Debug
INFO:__main__:Info
WARNING:__main__:Warning
Warning
```

モジュール内の　Debug ログも表示したい時は明示的に handler を設定します。

```python
import module
import logging
logger = logging.getLogger(__name__)

# ログを stderr に表示する StreamHandler を作り、書式を設定する。
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter("%(levelname)s:%(name)s:%(message)s"))

# このスクリプトの logger に先程作った Handler を登録して閾値を DEBUG にする。
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)

# module の logger に先程作った Handler を登録して閾値を DEBUG にする。
logging.getLogger('module').addHandler(handler)
logging.getLogger('module').setLevel(logging.DEBUG)

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

module.log()
```

出力

```shell
DEBUG:__main__:Debug
INFO:__main__:Info
WARNING:__main__:Warning
DEBUG:module:Debug
INFO:module:Info
WARNING:module:Warning
```

## モジュールのログを表示 (root logger で手抜き)

もしも利用するモジュール全部のログを同じように表示したいだけなら、root logger で全部まとめて設定出来ます。

```python
import module
import logging
logger = logging.getLogger(__name__)

# 以下の設定は logging.basicConfig(level=logging.DEBUG) と同じです。

# ログを stderr に表示する StreamHandler を作り、書式を設定する。
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter("%(levelname)s:%(name)s:%(message)s"))

# 各 logger の代わりに root logger を設定する。
logging.getLogger().addHandler(handler)
logging.getLogger().setLevel(logging.DEBUG)

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

module.log()
```

実行結果は上と同様です。

## Formatter による書式設定

`"%(levelname)s:%(name)s:%(message)s"` のような記法で書式設定します。非常に分かりづらいですが、`levelname` などの名前は [LogRecord attributes](https://docs.python.org/3/library/logging.html#logrecord-attributes) で定義されています。

時刻の指定はちょっと特殊で (あとで書く)

## dictConfig による設定

このようにすると柔軟にログを設定出来ますが、ややこしくてやってられないと思います。[dictConfig](https://docs.python.org/ja/3/library/logging.config.html#logging-config-dictschema) というのを使うと多少楽になります。

```python
import logging
import logging.config
import module
import yaml
logger = logging.getLogger(__name__)

logging.config.dictConfig(yaml.load("""
version: 1
formatters:
    default: { format: '%(levelname)s:%(name)s:%(message)s' }
handlers:
    console: { class: logging.StreamHandler, level: DEBUG, formatter: default }
loggers:
    module: { level: DEBUG, handlers: [ console ], }
    __main__: { level: DEBUG, handlers: [ console ], }
"""))

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

module.log()
```

出力

```shell
DEBUG:__main__:Debug
INFO:__main__:Info
WARNING:__main__:Warning
DEBUG:module:Debug
INFO:module:Info
WARNING:module:Warning
```

dictConfig 固有の書き方を覚えないといけないので、python 素の python で地道に書くより簡単かどうかは微妙ですが、dictConfig を使った既存のプロジェクトを使う時や、複雑な設定が必要な時には使うしか無いです。

## dictConfig は既存の logger を消してしまう！

ただ、dictConfig には既存の logger を消してしまうという分かりづらい落とし穴があります。例えば上の例をさらにシンプルにして root logger での設定を試みます。

```python
import logging
import logging.config
import module
import yaml
logger = logging.getLogger(__name__)

logging.config.dictConfig(yaml.load("""
version: 1
formatters:
    default: { format: '%(levelname)s:%(name)s:%(message)s' }
handlers:
    console: { class: logging.StreamHandler, level: DEBUG, formatter: default }
root:
    level: DEBUG
    handlers: [ console ]
"""))

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

module.log()
```

これは何も表示されません！ちょっと自分でもよく理解していないのですが、logger の定義(import module を含む)を dictConfig の後ろにするか、`disable_existing_loggers: False` を設定する必要があります。私はこの問題の解決に数日費やしました。悲しい。。。以下正解です。

```python
import logging
import logging.config
import module
import yaml
logger = logging.getLogger(__name__)

logging.config.dictConfig(yaml.load("""
version: 1
formatters:
    default: { format: '%(levelname)s:%(name)s:%(message)s' }
handlers:
    console: { class: logging.StreamHandler, level: DEBUG, formatter: default }
root:
    level: DEBUG
    handlers: [ console ]
disable_existing_loggers: False
"""))

logger.debug('Debug')
logger.info('Info')
logger.warning('Warning')

module.log()
```

参考

* [logging.config.dictConfig()を使った時にログが出力されない](https://ja.stackoverflow.com/questions/29200/logging-config-dictconfig%E3%82%92%E4%BD%BF%E3%81%A3%E3%81%9F%E6%99%82%E3%81%AB%E3%83%AD%E3%82%B0%E3%81%8C%E5%87%BA%E5%8A%9B%E3%81%95%E3%82%8C%E3%81%AA%E3%81%84)