【Python】トラップした例外がロギングされない。

TL;DR

Pythonで例外処理、それもエラーメッセージをログ出力するときは、例外クラス名も一緒に出しましょう。

発端

作ったスクリプトが異常終了するという報告を受けた。

聞いた挙動からして、どうもメモリ不足じゃないかと思い、ログを見てみる。

すると、

20YY-MM-DD HH:MM:SS.nnn [INFO  ] hogehoge
20YY-MM-DD HH:MM:SS.nnn [ERROR ] 
20YY-MM-DD HH:MM:SS.nnn [INFO  ] fugafuga

(ログのイメージ)

エラーメッセージが空っぽじゃないですか！

調査

件のスクリプトは、以下のように実装されていた(イメージ)。

def main():
    try:
        hoge_routine()
    except Exception as e:
        log.error(e)
        return 1
    return 0

訳が分からなかったので、トラップした例外を再度投げてみて、コマンドライン上で確かめてみることに。

ちなみに、公式ドキュメント によればシステム系の例外を除いて、すべての例外はExceptionから継承される。

(ユーザ定義例外も、Exceptionから派生させるようにと書いてある)

except節は、例外クラスの派生元をトラップしないけど、派生先はトラップする仕様(ここ)。

だから、except Exception as eで、ほとんどの例外はトラップできる。

def main():
    try:
        hoge_routine()
    except Exception as e:
        log.error(e)
        # return 1
        raise e
    return 0

$ python hoge.py 1> /dev/null 2> err.log

中身(イメージ)。

Traceback (most recent call last):
  ... 中略 ...
MemoryError

ふぁっ！？

エラーメッセージが出ていない。

ここで、例外をNewするとき、コンストラクターに渡す文字列を変えて簡単な実験をしてみる。

ちゃんとした（？）エラーメッセージ付き例外

このコードは、エラーメッセージを標準エラーに出力する

from logging import getLogger

log = getLogger(__name__)

try:
    raise ValueError('associated value: hoge')
except Exception as e:
    log.error(e)

$ python exception1.py 1> stdout.log 2> stderr.log
$ ls -hl std???.log
-rwxr-xr-x 1 user1 user1 23 Mar 21 14:07 stderr.log
-rwxr-xr-x 1 user1 user1  0 Mar 21 14:07 stdout.log
$ cat stderr.log
associated value: hoge
$ 

ちゃんと出てる。

空文字エラーメッセージ付き例外

このコードは、空文字で定義されたエラーメッセージを標準エラーに出力する。

from logging import getLogger

log = getLogger(__name__)

try:
    raise ValueError('')
except Exception as e:
    log.error(e)

$ python exception2.py 1> stdout.log 2> stderr.log
$ ls -hl std???.log
-rwxr-xr-x 1 user1 user1 1 Mar 21 14:11 stderr.log
-rwxr-xr-x 1 user1 user1 0 Mar 21 14:11 stdout.log
$ cat stderr.log
$ 

エラーメッセージがない。

正確には、空のメッセージが出力されている。

先頭改行エラーメッセージ付き例外

このコードは、先頭に改行文字が定義されたエラーメッセージを標準エラーに出力する。

from logging import getLogger

log = getLogger(__name__)

try:
    raise ValueError("\nhoge\nfuga")
except Exception as e:
    log.error(e)

$ python exception3.py 1> stdout.log 2> stderr.log
$ ls -hl std???.log
-rwxr-xr-x 1 user1 user1 24 Mar 21 14:17 stderr.log
-rwxr-xr-x 1 user1 user1  0 Mar 21 14:17 stdout.log
$ cat stderr.log

hoge
fuga
$ 

一応、エラーメッセージは出てる。

原因

今回の例外クラスが持つエラーメッセージ(正確には、「関連値(associated value)」)が空だった。

使用してるモジュールから投げられた例外だし、 普通、関連値って何かしら定義されているものだという認識だった。

けど、そういうことでもないらしい。

対策

この一件で、何もエラーメッセージだけがエラーの情報じゃないことに気が付いた。

例外もクラスとして定義されているのだから、その例外クラス名も有用なエラー情報なのだと。

だから現状、例外クラスのクラス名も同時に出力したほうが、ログとしてはいいのではないかという結論に至った。

def main():
    try:
        hoge_routine()
    except Exception as e:
        log.error(type(e).__name__)  # 例外クラス名を出力
        log.error(e)
        return 1
    return 0

改良されたログ(イメージ)

20YY-MM-DD HH:MM:SS.nnn [INFO  ] hogehoge
20YY-MM-DD HH:MM:SS.nnn [ERROR ] MemoryError
20YY-MM-DD HH:MM:SS.nnn [ERROR ] 
20YY-MM-DD HH:MM:SS.nnn [INFO  ] fugafuga

何のエラーが起きてるか、わかるようになって、QOLがちょっぴり上がった。