はじめに
前回「最初に覚えて欲しい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クラスを例に説明します。
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)
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レベルは作れる。ただしプログラムコード全体をコントロールできる場合にのみ実施することが望ましい。
という感じでしょうか。
もっと良いアイデア・マサカリ、お待ちしています！