Python の logging について

# この文について

これから説明することの主旨は、単に Python のドキュメント [16.6. logging — Python 用ロギング機能](https://docs.python.jp/3/library/logging.html) の初めの方にさらっと全部書いてあります。

ただ、なぜかあまり浸透していないようなので、説明する順番と表現のしかたを変えて、自分なりに例示をしてみようとおもいます。

Python の実行環境が手元にある状態で、試しながら読むとよいかもしれません。

# 1. どこから呼んでも同じ

`logging.getLogger` で取得できる `logger` は、名前が同一ならば Python プロセス内を通して常に同一となります。

例を示すと `getLogger('x')` を 2 回呼んで別々の変数に代入したとしても、比較してみると同じオブジェクトであることがわかります。

```python3
import logging


logger1 = logging.getLogger('x')
logger2 = logging.getLogger('x')
assert logger1 == logger2  # => True
assert id(logger1) == id(logger2)  # => True
```

# 2. アプリケーションコードとログハンドラ設定の分離

1. の性質を使うと、アプリケーションコードとログハンドラの設定箇所を依存関係なしで分離することができます。

例として `app.py` と `log_setting.py` 、それらに依存する `main.py` で示します。

## 良い例

以下の例では `app.py` と `log_setting.py` は同じ `logger` を扱っていますが、たがいに依存していません。

```python:main.py
import app
import log_setting


log_setting.example_log_setting()
app.example_application_code()
```


```python3:app.py
import logging


logger = logging.getLogger('app')


def example_application_code():
    logger.error('Hello, World!')
```

```python3:log_setting.py
import logging


logger = logging.getLogger('app')


def example_log_setting():
    h = logging.StreamHandler()
    h.setLevel(logging.DEBUG)
    logger.addHandler(h)
```

## ちょっと良くない例

`app.py` と `log_setting.py` が同じ logger をあつかうためには import が必要だと思って書いてしまっている例です。 `app` が `log_setting` を `import` します。

```python3:main.py
import app
import log_setting


log_setting.example_log_setting()
app.example_application_code()
```

```python3:app.py
import log_setting

logger = log_setting.logger


def example_application_code():
    logger.error('Hello, World!')
```

```python3:log_setting.py
import logging


logger = logging.getLogger('app')


def example_log_setting():
    h = logging.StreamHandler()
    h.setLevel(logging.DEBUG)
    logger.addHandler(h)
```

せっかくファイルを分けているので、ログ出力の設定と、アプリケーションのコードは依存しない方が嬉しいでしょう。

# 3. 階層をもつ名前空間

`logging.getLogger` の引数に与える名前に含まれる `.` によって、 logger は階層関係を持つことができます。

例では `aaa`, `aaa.bbb`, `aaa.bbb.ccc` の 3 つの名前で logger を作り、
aaa.bbb や aaa.bbb.ccc の logger が aaa に追加したログハンドラーにも伝播していることを示します。

追加するログハンドラーは違いが際立つように、 formatter を工夫して、
 `say_twice_stream_handler` というメッセージを 2 倍にくりかえして出力するハンドラーにしてみます。

```python3
import logging


logger_aaa = logging.getLogger('aaa')
logger_aaa_bbb = logging.getLogger('aaa.bbb')
logger_aaa_bbb_ccc = logging.getLogger('aaa.bbb.ccc')

say_twice_stream_handler = logging.StreamHandler()
fmt = logging.Formatter('{message} {message}', style='{')
say_twice_stream_handler.setFormatter(fmt)
logger_aaa.addHandler(say_twice_stream_handler)

logger_aaa_bbb.error('Hi!')
logger_aaa_bbb_ccc.error('Yay!')
```

```:出力結果
Hi! Hi!
Yay! Yay!
```

`logger_aaa` にだけ addHandler をしていますが、ちゃんと `logger_aaa_bbb` や `logger_aaa_bbb_ccc` から伝播しています。


# 4. 名前は `__name__` で

3. で logger の名前空間に階層構造を持たせることが可能だとわかりました。
logger の名前とモジュールの完全修飾名と一致させておくことのがベストプラクティスとされています。
モジュールと同じ粒度でロギングを扱うことができるからです。

logger の名前とモジュールの完全修飾名と一致させるのは全く難しくありません。
[`__name__`](https://docs.python.jp/3/reference/import.html#__name__) がモジュールの完全修飾名になっているので、
単に

```python3
import logging


logger = logging.getLogger(__name__)
```

とすればモジュールの完全修飾名と同じ名前を持つ logger が得られます。

# 5. 階層の一番上、ルートロガー

名前には階層があるので、階層を辿っていくとただ 1 つの親が存在します。
それがルートロガー (root logger) です。

せっかくロギングを名前ごとに区別し、階層化して取り扱う方法があるのに、わざわざルートロガーを使うメリットは少ないです。

書き捨ての 1 ファイルの Python スクリプトでもない限り、ルートロガーはなるべく使わない方が良いでしょう。

しかし、 Python にはうっかりとルートロガーを触ってしまう可能性のある箇所がいくつかあります。
それを説明します。

## 5-1. `logging.debug`, `logging.info`, `logging.warning`, `logging.error`, `logging.critical`

これらに与えたメッセージはルートロガーに伝播してしまいます。
`logging.debug` は `logger.debug` と字面がよく似ているので間違えてしまうかもしれません。気をつけましょう。

## 5-2. 引数なしの `getLogger()`

引数無しで `logging.getLogger()` を呼び出すと、直接 root logger を得ることができます。

```python3
>>> logging.getLogger()
<RootLogger root (WARNING)>
```

うっかりと `__name__` を引数に与え忘れると、これをやってしまうかもしれません。