tanamonの稀に良く書く日記

KEEP CALM AND DRINK BEER

Pythonのloggingでエラーがあった場合だけ遡って出力する

python

クローラーみたいなものを作ってるとログがやたら出て困る。

今日動かしたやつは200MBを超えていた。そして開いたらVSCodeが不安定になった。

再起動したらこのメッセージ。いや、今まで散々Pythonでコード書いてたじゃない。何忘れてるの。

ログは見たいが出力量は減らしたい

ログが出すぎる問題への対処の基本はパッケージ単位で出力ログレベルを上げることだけど、クローラーのような、相手側のデータの都合でこちらの処理の成否が決まるようなプログラムは出力レベルを上げるとエラーを見てもわからないことが多い。必ず入る想定（例えばニュース記事のタイトル）のXPathの結果がNoneなのはなぜ？みたいなのは、UnitTestで先回りして品質を上げるのも難しい。

そうなると、ある程度ざっくりとした想定で作ったプログラムに処理の途中経過のログをDEBUGレベルなどで多めに出すようにしておいて、ひたすら動かして異常データを検出してから、それをテストケースにしながら修正する、という泥臭い作り方になる。当然ログ出力の量は増える。

とはいえ、ほぼ正常なログの中からエラーとなったデータを探すのは面倒なので、ログ出力のコードは書くが実際の出力はログレベルの以外の方法で抑制して欲しい、という要件が出てくる。

こういう、ある種のとんち的な要求に対する実装は検索で探しても見つからない（そもそも検索ワードがわからない）ので、最初から諦めてとりあえず自前で簡単なものを実装してみた。

コード

import logging.config

logger = logging.getLogger(__name__)


class MyMemoryHandler(logging.handlers.MemoryHandler):

    def emit(self, record):
        if self.capacity <= len(self.buffer):
            del self.buffer[0]
        super().emit(record)

    def shouldFlush(self, record):
        return (record.levelno >= self.flushLevel)

    def flush(self):
        # memo: logging.shutdown()からはshouldFlush()を経由せずに呼ばれるので再チェックがいる
        if self.buffer and self.shouldFlush(self.buffer[-1]):
            super().flush()


if __name__ == '__main__':
    if False:
        target_handler = logging.FileHandler(filename='./logtest.log', mode='w')
    else:
        target_handler = logging.StreamHandler()
        target_handler.setFormatter(logging.Formatter("%(asctime)s [%(levelname)s] (%(filename)s) %(message)s"))

    handler = MyMemoryHandler(capacity=3, flushLevel=logging.ERROR, target=target_handler)
    logging.basicConfig(level=logging.DEBUG, handlers=[handler])

    for n in range(25):
        if n % 10 == 9:
            logger.error(n, stack_info=True)
        else:
            logger.debug(n)

    logger.debug('end')  # 出力されない

loggingパッケージのMemoryHandlerからの拡張。このクラスは外部などに非同期でログ出力する用途で、ログ出力を同期から非同期に変えるために一度バッファリングするという目的のものだけど、今回の用途に合ってたので使った。

エラーの時に遡ったログと合わせてSlackに投げるみたいなのもできるので、このクラスのベースでいいと思う。

引数はこれら。

  • capacity: 貯めておくログの行数。flushLevel以上となったログを含むので、この値-1の分だけ遡る
  • flushLevel: ログを出力するトリガーとするエラーレベル
  • target: flushLevel以上のログが出た時に渡すhandler

ちなみに、del self.buffer[0]のところが計算量O(n)と遅いので、capacityはあまり巨大な値にしないほうがいいと思います。

実行結果

2019-07-15 03:39:05,150 [DEBUG] (logtest.py) 7
2019-07-15 03:39:05,150 [DEBUG] (logtest.py) 8
2019-07-15 03:39:05,150 [ERROR] (logtest.py) 9
Stack (most recent call last):
  File "logtest.py", line 35, in <module>
    logger.error(n, stack_info=True)
2019-07-15 03:39:05,150 [DEBUG] (logtest.py) 17
2019-07-15 03:39:05,150 [DEBUG] (logtest.py) 18
2019-07-15 03:39:05,150 [ERROR] (logtest.py) 19
Stack (most recent call last):
  File "logtest.py", line 35, in <module>
    logger.error(n, stack_info=True)

ERROR出力の時に2行遡って出力されます。

参考