PythonのloggingにTRACEレベルを増やす

# はじめに

前回「[最初に覚えて欲しいPythonのロギング](https://qiita.com/utkamioka/items/d43b01fe28aab9364da5)」で、ログを使うまでの最低限の手順を説明しました。

loggingモジュールは標準機能だけあって、必要最低限というか、贅沢は言えない感じなんですが、それでも気になることがありました。
それは「**ループの最深部などのログはDEBUGよりも低いレベルで出力したい**」ということです。

という訳で、PythonのloggingモジュールにTRACEレベルを作ろうというのが、今回の趣旨です。

# とりあえずTRACEレベルで出力

`logging/__init__py`の中でログレベルは数値で定義されているので、
DEBUGの10より小さい値を指定すれば実現できます。

```python
from logging basicConfig, getLogger, DEBUG, NOTSET

basicConfig(level=NOTSET)  # 全てのレベルを出力対象にする

logger = getLogger(__name__)
logger.debug('this is debug')
logger.log(DEBUG-1, 'this is trace')
```

レベル`NOTSET`は0と定義されていて、これが設定された場合、階層構造の親ロガーの設定に従い、ルートまで辿った上で全て`NOTSET`だった場合は全てのログが出力対象となります。
実行すると以下のように出力されます。

```:実行結果
DEBUG:__main__:this is debug
Level 9:__main__:this is trace
```

`basicConfig(level=DEBUG)`とした場合は、目的通り、`"this is trace"`は出力されず、`"this is debug"`だけ出力されます。
しかし、この例ではいくつか気になる点があります。

1. 他が`debug(msg)`とか`info(msg)`とかなのに、TRACEのところだけ`log(level, msg)`になっている。コードが浮いているし、毎回`DEBUG-1`を指定するのは面倒。
2. 出力されたログの表記が`"Level 9"`になっている。妙なところに空白が混ざると、ログ解析のパース処理で間違えそう。
3. そもそも、`DEBUG-1`が何を意味するのかわかりにくい。

# 改訂版

前回のDogクラスを例に説明します。

```python:animals/dog.py
from functools import partial
from logging import getLogger, DEBUG

class Dog(object):
    def __init__(self, name):
        self.name = name
        self.logger = getLogger(__name__)
        self.logger.trace = partial(self.logger.log, DEBUG-1)  # <= trace()作成

    def run(self, distance):
        for n in range(distance):
            self.logger.trace('%s is running', self.name)  # <= trace()でログ出力
        self.logger.info('%s is tired', self.name)
```

```python:main.py
from animals.dog import Dog
from logging import basicConfig, addLevelName, DEBUG, NOTSET

if __name__ == '__main__':
    basicConfig(level=NOTSET)
    addLevelName(DEBUG-1, 'TRACE')  # <= TRACEレベルの表記指定
    dog1 = Dog('pochi')
    dog1.run(3)
```

```:実行結果
TRACE:animals.dog:pochi is running
TRACE:animals.dog:pochi is running
TRACE:animals.dog:pochi is running
INFO:animals.dog:pochi is tired
```

これで、`info(level, msg)`の隠蔽と、`"Level 9"`表記の切り替えは可能となりました。

要点は以下の通り。

* Dogクラスの`__init__()`で、loggerオブエクトに新しい関数`trace()`を追加しています。`functools.partial`は指定した引数があらかじめ指定されたかのように振る舞う、新しい関数を作成します。
* mainの中の`addLevelName()`で、指定したレベル（`DEBUG-1`）のレベル名（`"TRACE"`）を追加しています。

# 残りの問題について

* `DEBUG-1`は何とかならないのか？

たとえば、以下のような書き方をすれば、loggingモジュールにTRACEの定義を追加することができます。
（`import logging`と`from logging import *`が混在している問題については、とりあえず目をつぶってください。）

```python
from functools import partial
from logging import basicConfig, addLevelName, DEBUG
import logging

# animals/dog.py
class Dog(object):
    def __init__(self):
        self.logger = getLogger(__name__)
        self.logger.trace = partial(self.logger.log, logger.TRACE)

# main.py
if __name__ == '__main__':
    logging.TRACE = DEBUG - 1  # <= TRACEを定義
    addLevelName(logging.TRACE, 'TRACE')
```

しかし問題があります。

`main.py`を通さずDogクラスを使おうとした場合（例えばUnitテストとか）、`logging.TRACE`が定義されていないので、参照した瞬間にエラーになります。
かと言って、Dogクラスで「`logging.TRACE`が無い場合は定義する」とした場合、Catクラス担当者とTRACEに何を定義するのか、意識合わせをしておく必要があります。
animalsモジュールに定義するのも手ですが、その場合`logging.DEBUG`など標準の定義と使い勝手が揃えられません。

「[Logging HOWTO](https://docs.python.jp/3/howto/logging.html#custom-levels)」のカスタムレベルにも書いてありますが、ライブラリとして提供するコードでTRACEのような独自のレベルを定義するのは悪いアイデアだ、という意見に納得出来ます。

# まとめ

締まりが無いですが、

* TRACEレベルは作れる。ただしプログラムコード全体をコントロールできる場合にのみ実施することが望ましい。

という感じでしょうか。

もっと良いアイデア・マサカリ、お待ちしています！