Pythonでスタックトレースをログ出力するには

Pythonでログを書き出すところのスタックトレースをログに書き出す方法です。

ログを見ながら処理の流れを把握しようとしても、ログだけではどこからどう呼び出されているを把握できないときがあります。ログ書き出し個所のスタックトレースを見れば、呼び出しの関係がわかるはずです。

開発環境などでソースコードをいじれる状況を前提に、2通り書いておきます。

その1

Pythonのloggingでスタックトレースを出力させるには、以下のように stack_info=True と書けばよいです。

import logging
logger = logging.getLogger(__name__)

logger.error(msg, stack_info=True)

ログメッセージの後に続けてスタックトレースが表示されます。

msg
Stack (most recent call last):
  File "/home/ubuntu/test.py", line 35, in <module>
    f()
  File "/home/ubuntu/test.py", line 8, in f
    g()
  File "/home/ubuntu/test.py", line 15, in g
    logger.error("msg", stack_info=True)

上のほうが呼び出し元で、下のほうが呼び出される側、つまりスタックの深いほうです。スタックトレース出力の向きは言語によって異なり、PythonはJavaのスタックトレースと逆向きです。

その2

どちらかというとこの記事で書きたかったのはこちらです。

既存のソースコードにあるすべてのログ出力でスタックトレースを出力させる方法です。ログを書き出しているすべての箇所に stack_info=True を追記するのが現実的でないけど、開発中で一時的に全部のログのスタックトレースを見たい場合です。 stack_info=True の仕組みを使わずに traceback モジュールを使って自力でスタックトレースを出力するようにカスタマイズしてしまいます。

最初に一度だけ実行されるいずれかのファイルに以下のように書いておきます。

import logging
import traceback

class StackLogger(logging.Logger):
    def _log(self, level, msg, args, exc_info=None, extra=None, stack_info=False, **kwargs):
        super()._log(level, str(msg) + "\n" + "".join(traceback.format_stack()), args, exc_info=exc_info, extra=extra, stack_info=stack_info, **kwargs)

logging.setLoggerClass(StackLogger)

あとは各ファイルでいつも通りloggingを呼び出します。

import logging
logger = logging.getLogger(__name__)

logger.debug(...)

ログの量が膨大になるので、注意してください。

出力イメージはその1とほとんど同じです。

その2B

その2の改良バージョンです。ログをちょっと見やすくしました。

• ライブラリのスタックトレースを除外して、自分で書いたコードのスタックトレースのみに絞る
• 各フレームの表示を2行ではなく1行に圧縮（膨大になるログの行数を少しでも絞るため）
• スタックトレースの並び順を逆順にする（どちら順が見慣れているか人によって違うと思います）

import traceback
import logging

def stacktraceLines():
    tb = traceback.format_stack()
    ret = []
    for l in tb:
        p = l.find("\n")
        if p >= 0:
            # l には改行が含まれており、
            # 1行目はファイル名と行番号を含む
            # 2行目はその行のソースコード
            # それらを1行につなげる
            l = l[:p].strip() + ": " + l[p+1:].strip()
        if (
            # ライブラリのスタックトレースを除外して、自分で書いたコードのスタックトレースのみに絞る
            l.startswith("File \"/home/ubuntu/sample/") and
            not l.startswith("File \"/home/ubuntu/sample/initlog.py\"") # stacktraceLinesを定義しているソースを除外
        ):
            ret.insert(0, l) # スタックトレースの並び順をJava方式にするならば
            # ret.append(l) # スタックトレースの並び順をPython方式にするならば
    return ret

class StackLogger(logging.Logger):
    def _log(self, level, msg, args, exc_info=None, extra=None, stack_info=False, **kwargs):
        stacktraces = ["\n  " + l.replace("%", "%%") for l in stacktraceLines()]
        if len(stacktraces) > 0:
            msg = str(msg) + "".join(stacktraces)
        super()._log(level, msg, args, exc_info=exc_info, extra=extra, stack_info=stack_info, **kwargs)

logging.setLoggerClass(StackLogger)

ログ出力は次のようなイメージです。

msg
  File "/home/ubuntu/sample/test.py", line 41, in g: logger.error("msg")
  File "/home/ubuntu/sample/test.py", line 35, in f: g()
  File "/home/ubuntu/sample/test.py", line 43, in <module>: f()

上のほうが呼び出される側、つまりスタックの深いほうで、下のほうが呼び出し元です。つまり、Javaのスタックトレースと同じ順番です。

以上。