More than 5 years have passed since last update.

PythonにTRACEログレベルを追加する……？

Python

Last updated at 2014-05-01Posted at 2014-05-01

一言で言うと: やめよう

以下はネタとしてお読みください。

そもそもそれはどういう要望？

log4j (http://ja.wikipedia.org/wiki/Log4j) にはDEBUGの下にTRACEというレベルがあります。
これ自体は、まぁアリな機能かなぁと思ってます。

例えば関数の冒頭とラストに「はじまった！」「おわった！」って
TRACEログレベル、というかLOG.trace()等で書いておき、中途の過程をDEBUGで書いておくと、
-v に対する -vv (sshの場合) みたいな多段を少し意味のあるレベルで定義できる、そういう感じです。
バグってくると、草不可避。

開発中のときには「どの関数の最後まで動いたか」はログレベルで分かると嬉しいケースがあります。
いつも全編においてデバッガ実行出来るわけでもないですし、なんやかやで「printfデバッグ」使っちゃうん。助けて。

TRACE的なものを設定することは「出来ないことはない」ように見える

Pythonのログレベルはそもそも数値でして、DEBUG, INFOとかはそれぞれ実際には数字にマッピングされます

CRITICAL 50
ERROR 40
WARNING 30
INFO 20
DEBUG 10
NOTSET 0

例えばログ吐くときは以下のように書きます

logging.debug('こんな書き方するべきではない')
logging.log(logging.DEBUG, 'だからー！')

(実際にはLogger使えって話になります)

logging.DEBUGは単純に 10 なので、上記の記法は事実上、以下の記法と同じログレベルでの出力を表します。

logging.log(10, 'んもー！')

NOTSET (0) はちょっと特殊なので置いておくとして、1〜9の数字を使っても、ログ関数は文句言いません。
むしろ逆で、DEBUGやINFOはシンプルに数値へのエイリアス的に扱われます。

＃後述しますが、一部の機構では現時点では数字しか受け取りません (例: logging.log(lvl, msg)のlvlは数値であって'DEBUG'等は受け入れません)

ですので、5といった数字を指定してlogging.log(5, 'わふー')などと書けば、setLevel(logging.DEBUG)された状態のLoggerでは表示されなくなります。

仮にTRACE的なものを数値指定でやると以下のような感じに。

from logging import getLogger, StreamHandler, DEBUG
logger = getLogger(__name__)
handler = StreamHandler()
logger.setLevel(DEBUG)
handler.setLevel(DEBUG)
logger.addHandler(handler)
logger.log(5, '開始するよ')
..
logger.debug('これはでばっぐだよ')
..
logger.log(5, '終わるよ')

上の例では「開始するよ」と「終わるよ」は表示されません。
「これはでばっぐだよ」だけです。
本当に開発者にとってしか価値のないデバッグログを入れる手段としては、
個人的には酷いものだとは思いません。
というか便利な。

logging.trace()とかlogger.trace()も欲しいな！

ここで、loggingにはaddLevelName()という機能があります。
(https://docs.python.org/3.4/library/logging.html#logging.addLevelName)

おお、これでlogger.trace()がつｋ

作られません :-)

logging.trace()やlogger.trace()は作られませんし、ましてやlogging.log('TRACE', 'はろー')とも出来ません。そもそもlogging.log('INFO', '貼ろう')すら許されてません。

＃ logger.setLevel('INFO')といった指定は「出来ます」 (正確には3.2以降の最近のバージョンのみらしい。何故か2.7も含むのだけど)。argparseで--log=DEBUGとか指定して直にsetLevel()にぶち込むことも可能。

多分ですが、これってFormatterが"Level 5"ではなくて"TRACE"って表示してくれるだけの機能ですよね、と。

(ipythonとかで)
> import logging
> logger = logging.getLogger('test')
> logger.setLevel(1)
> handler = logging.StreamHandler()
> handler.setLevel(1)
> formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s')
> handler.setFormatter(formatter)
> logger.addHandler(handler)
>  logger.debug('hello')
2014-05-01 11:02:12,743 - DEBUG - hello
> logger.log(5, 'hoge')
2014-05-01 11:02:20,599 - Level 5 - hoge
> logging.addLevelName(5, 'TRACE')
> logger.log(5, 'hoge')
2014-05-01 11:02:43,173 - TRACE - hoge

正確に言えば、むりくりloggingの中身をいじってしまえばlogging.trace()等も追加「は」出来るかもしれません。Pythonだし。

ただ、デフォルトでナイスでセーフな実装としては存在しませんし、多分今後もそういう方向性に向かうことはないと思うわけです。

仮にできても、単に超困るのは目に見えますけどね。
各関数やらが受け取ったloggerが常にそれを持っているとは言えないわけなので。特にライブラリとして提供していれば、外からtraceを知らないloggerが来るのは目に見えてます。
たまにtrace持ってたり持ってなかったりするからgetattrとかで確認しつつ使うのでしょうか。
便利さが微塵もありません。

そもそも公式は「やるなよ」的なことを言ってる。

Defining your own levels is possible, but should not be necessary, as the existing levels have been chosen on the basis of practical experience. However, if you are convinced that you need custom levels, great care should be exercised when doing this, and it is possibly a very bad idea to define custom levels if you are developing a library. That’s because if multiple library authors all define their own custom levels, there is a chance that the logging output from such multiple libraries used together will be difficult for the using developer to control and/or interpret, because a given numeric value might mean different things for different libraries.

結論

やめよう

使うとして、開発者がどうしても分からないバグに対する「デバッグ」ログとして、超verboseログを吐きまくる特定のhandlerを一個用意して、そのhandlerだけログレベル1とかにして、他はDEBUGでお茶濁すとか、そういう多段階の対応をする程度に留めておくくらいでしょうか。

「やめよう」と主張している最後の最後で「ああ、それなら許せるな」と自分の中で納得してきたところで、おしまい。

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up