Python logging で「警告は一度でいい」の制御

教育的にビミョーなんで、書くか迷ったんだけれど…まぁいつものごとく「但し書きだらけ」スタイルで書いときゃいいかと。

ロギングの中でも、「警告」が厄介なのはそう、「処理続行可能な扱いであるがために、同一警告を何度でも喰らいうる」からだ。そして「そうなった場合」、大量の警告の山に大事な情報が埋もれることとなる。

「すわ、警告は一度でいい、ねば!」

まぁ待ちなはれ。なぜ「警告は一度だけ」という制御を行うアプリケーションが少ないのか、まずは考えてみたほうがいい。

考えてみれば非常に当たり前のことなのだけれど、ロギングは根本的に「動いた歴史のその時」に「今デショ」と逐次出さなきゃ、価値がない。元はと言えば「追跡」が動機なんだから、足跡をアプリケーションが勝手な判断で証拠隠滅するようでは、ロギングの信頼性に関わるのだ。すなわち、「起こったコト」だけでなく、「いつ、どこで」自体もロギングの大事な情報なのだ。

「多くのアプリケーションが、同一警告を何度出そうが無頓着」であるのは、単に無頓着なのではなく、多くはこうした判断に基づくものだ。実際には「アプリケーション自身はそうしてるつもり」でそうならないケースがあるが、もちろんそれは「子プロセスを呼び出す」タイプのものだ…、が、まぁ今回はその話はほっとく。

すなわち、少なくとも「ロギングをしたい場所」で「既知なので揉み消す」ということはすべきではなく、どうしてもやりたければ、「出来るだけエンドユーザに近い層にフィルタリングを委ねるべきである」てこと。

てのがまず「基本中の基本の話」、ね。

やっとこ本題。

そもそも「なぜにそこまで一気に大量の「同じ警告」が出ちゃうのよ」てのは、こんな構造の処理では頻発する:

擬似コード

1 for 文脈 in 文脈達:
2     doc = load("aaa.json", ctx=文脈)
3     for アイテム in doc:
4         if not 存在してる?(アイテム):  # ctx 依存だったりそうでなかったり
5             _logger.warn(...)

上の擬似コードで「アイテム」が、ctx をどう切り替えようが一緒であれば、これは「毎度 xxx.txt が存在しない」と、文脈達数分警告を喰らうハメになる一方で、ctx 依存のアイテムもあるため、処理としては「毎度警告」するのが素直だし、前置きでの検討の通り、勝手に揉み消すのはそもそも良くない、たとえ「大量に出しちゃう」ハメになろうとも。

そうはいってもね、というわけだ。いくらなんでも一気に同じものが20も30も出ちゃうんではねぇ、と。さすがに限度があるだろ、って話。じゃぁこれは「どうしてもやりたい」ケースだよね、「出来るだけエンドユーザに近い層にフィルタリングを委ねる」ことは可能か?

これがまぁ、少々のこだわりがあると思ったより厄介で。少々のこだわり、は以下たった二つ:

Python 2.7 でも Python 3.x でも同じコードで動く
basicConfig への少しの味付け、だけでいいのよそれ以上はいらない

ところがこの両方がまさに「うげぇ」なのな。後者は結局のところ「便利関数を手放して全部自力でやったほうが案外簡単」になっちゃいうる、まさに典型で、All or Nothing 的な。前者はさりげなく logging のインターフェイスが全体的に結構変更されている、てこと。

1時間ほどの試行錯誤の結果、どうもこんなんしかなさそう:

 1 import logging
 2 
 3 
 4 if __name__ == '__main__':
 5     #
 6     class _QuietStreamHandler(logging.StreamHandler):
 7         def __init__(self, stream=None):
 8             logging.StreamHandler.__init__(self, stream)
 9             self._dejavwarn = set()
10 
11         def emit(self, record):
12             if record.levelno == logging.WARN:
13                 if (record.msg, record.args) in self._dejavwarn:
14                     return
15                 self._dejavwarn.add((record.msg, record.args))
16             logging.StreamHandler.emit(self, record)
17 
18     #
19     thresh = logging.INFO
20     h = _QuietStreamHandler(sys.stdout)
21     h.setLevel(thresh)
22     h.setFormatter(logging.Formatter(fmt=logging.BASIC_FORMAT))
23     logging.basicConfig(stream=sys.stdout, level=thresh)
24     logging.root.handlers[0] = h

そもそも Python の logging モジュールは java の logging からの輸入なので、java のソレと共通の部分は多く、LogRecord をごにょごにょしたり、emit をオーバライドしたり、といったことは java のそれと多分一緒。

問題は「basicConfig がやってくれちゃう色んなこと」に「ちょっとだけ手を加えたい」こと自体が、ご覧のようにちぃと不愉快なことになるのね。具体的には「basicConfig が自動で追加する StreamHandler、を後から上書き」するという点と、「basicConfig が自動で追加する StreamHandler に自動で追加するフォーマッタとレベル、を自前でゴニョる」てこと。こうしたことをしないと、ログが二重化しちゃったり、フォーマットが basicConfig で気楽に作ったのと全然違ったり、などアレコレ起こる。

要するに「だったら basicConfig せずに全部自分で設定しちゃった方がマシなんでは?」となりかねなくて、実際そうした方が簡単かもしんない。ただ、これがダメなのよ:

basicConfig を捨ててしまおうと…

1     h = _QuietStreamHandler(sys.stdout)
2     h.setLevel(thresh)
3     h.setFormatter(logging.Formatter(fmt=logging.BASIC_FORMAT))
4     logging.root.addHandler(h)
5     #logging.basicConfig(stream=sys.stdout, level=thresh)
6     #logging.root.handlers[0] = h