loggingによるログ出力でtracebackの表示が欲しいときにはstac_info,exc_infoを使うと便利

はじめに

loggingのloggerを使ってログ出力をする際に、発生した場所を把握するために位置情報も一緒に出力したい時がある。有り体に言えば、tracebackが欲しい。
このtracebackをログに含める時にどうすると良いかという話。

愚直な方法

もちろん自分でtracebackをログに付加してあげれば良いという話もある。以下のように。

import logging
import traceback
logger = logging.getLogger("sample")


def foo():
    bar()


def bar():
    logger.info("bar")
    logger.info("tb: %s", "".join(traceback.format_stack()))


if __name__ == "__main__":
    logging.basicConfig(level=logging.INFO)
    foo()

一応tracebackは表示される。

INFO:sample:bar
INFO:sample:tb:   File "qr_64852sBQ.py", line 18, in <module>
    foo()
  File "qr_64852sBQ.py", line 8, in foo
    bar()
  File "qr_64852sBQ.py", line 13, in bar
    logger.info("tb: %s", "".join(traceback.format_stack()))

とは言えわざわざ自分でtracebackを取ってくると言うのは面倒ではあるし。そもそもログ出力のためだけにpythonの知識(import traceback)を要求するのはおかしい。

stack_info

実際、上のようにtracebackを自分で付与する必要はなく、loggerでログ出力する時に stack_info=True をつけてあげれば良い。

--- 00sample.py	2017-07-13 08:06:10.000000000 +0900
+++ 01sample.py	2017-07-13 08:09:06.000000000 +0900
@@ -1,6 +1,5 @@
 # -*- coding:utf-8 -*-
 import logging
-import traceback
 logger = logging.getLogger("sample")
 
 
@@ -9,8 +8,7 @@
 
 
 def bar():
-    logger.info("bar")
-    logger.info("tb: %s", "".join(traceback.format_stack()))
+    logger.info("bar", stack_info=True)

実行してみると Stack (most recent call last) 以降にtracebackが表示される。

INFO:sample:bar
Stack (most recent call last):
  File "qr_64852GWc.py", line 16, in <module>
    foo()
  File "qr_64852GWc.py", line 7, in foo
    bar()
  File "qr_64852GWc.py", line 11, in bar
    logger.info("bar", stack_info=True)

exc_info

ログの出力時の位置ではなく例外の発生位置のtracebackを表示したいこともある。例えば logger.exceptipn() などを使った場合と同様の形式。
これには stack_info の代わりに exc_info を渡せば良い。

import logging
logger = logging.getLogger("sample")


def foo():
    bar()


def bar():
    logger.info("bar")
    1 / 0


if __name__ == "__main__":
    logging.basicConfig(level=logging.INFO)
    try:
        foo()
    except:
        logger.info("hmm", exc_info=True)

zero division errorの発生位置のtracebackは例外オブジェクトから抽出され自動で併記してくれるようになる。

INFO:sample:bar
INFO:sample:hmm
Traceback (most recent call last):
  File "qr_64852t0u.py", line 18, in <module>
    foo()
  File "qr_64852t0u.py", line 7, in foo
    bar()
  File "qr_64852t0u.py", line 12, in bar
    1 / 0
ZeroDivisionError: division by zero