はじめに

前回「最初に覚えて欲しいPythonのロギング」で、ログを使うまでの最低限の手順を説明しました。

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

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

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

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

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"だけ出力されます。
しかし、この例ではいくつか気になる点があります。

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

改訂版

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

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)

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 *が混在している問題については、とりあえず目をつぶってください。）

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」のカスタムレベルにも書いてありますが、ライブラリとして提供するコードでTRACEのような独自のレベルを定義するのは悪いアイデアだ、という意見に納得出来ます。

まとめ

締まりが無いですが、

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

という感じでしょうか。

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

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

はじめに

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

改訂版

残りの問題について

まとめ