Pythonのデフォルトの例外＋トレースバック表示は、主にターミナル表示向けに調整されています。（次のPython 3.13からはカラー表示にも対応する予定です。）
ターミナル表示用にフォーマットされたトレースバックは、（もちろんカラーを使わなければ）非構造化ログに書いても特に問題ありませんでした。しかし、1行に1つのJSONの形で構造化ログを書くときにはあまり適していない気がします。
- SQLAlchemyなどの複雑なライブラリを使うとトレースバックが巨大になり、ログ転送ツール等の1レコードあたり容量制限に気をつけないといけない。
- エラーとエラーの発生元が最後にくるフォーマットはログが上に流れているターミナルでは見やすいが、Web UIから見る時やJSONをそのまま見るときは最初にエラーが来て欲しい。
- 改行やクォートがJSONに入る時はエスケープされるので、なおさら見にくくなる。
試しに、SQLAlchemyでsqliteのファイルを開けなかった時のエラーのスタックトレースは次のようになります。
Traceback (most recent call last):
File "/Users/inada-n/tmp/sample.py", line 74, in main
conn = engine.connect()
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 3280, in connect
return self._connection_cls(self)
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 148, in __init__
Connection._handle_dbapi_exception_noconnection(
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 2444, in _handle_dbapi_exception_noconnection
raise sqlalchemy_exception.with_traceback(exc_info[2]) from e
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 146, in __init__
self._dbapi_connection = engine.raw_connection()
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 3304, in raw_connection
return self.pool.connect()
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/pool/base.py", line 449, in connect
return _ConnectionFairy._checkout(self)
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/pool/base.py", line 1263, in _checkout
fairy = _ConnectionRecord.checkout(pool)
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/pool/base.py", line 712, in checkout
rec = pool._do_get()
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/pool/impl.py", line 179, in _do_get
with util.safe_reraise():
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/util/langhelpers.py", line 146, in __exit__
raise exc_value.with_traceback(exc_tb)
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/pool/impl.py", line 177, in _do_get
return self._create_connection()
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/pool/base.py", line 390, in _create_connection
return _ConnectionRecord(self)
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/pool/base.py", line 674, in __init__
self.__connect()
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/pool/base.py", line 900, in __connect
with util.safe_reraise():
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/util/langhelpers.py", line 146, in __exit__
raise exc_value.with_traceback(exc_tb)
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/pool/base.py", line 896, in __connect
self.dbapi_connection = connection = pool._invoke_creator(self)
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/engine/create.py", line 643, in connect
return dialect.connect(*cargs, **cparams)
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/engine/default.py", line 617, in connect
return self.loaded_dbapi.connect(*cargs, **cparams)
sqlalchemy.exc.OperationalError: (sqlite3.OperationalError) unable to open database file
(Background on this error at: https://sqlalche.me/e/20/e3q8)
そして、実はこれでも短くしている方なのです。このトレースバックは PYTHONNODEBUGRANGES=1 という環境変数を設定して出力しましたが、この環境変数を設定しなかったら次のように行内の例外発生箇所を示すマークが付いて、1フレームごとに2行ではなく3行消費することがあります。
Traceback (most recent call last):
File "/Users/inada-n/tmp/sample.py", line 74, in main
conn = engine.connect()
^^^^^^^^^^^^^^^^
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 3280, in connect
return self._connection_cls(self)
^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/Users/inada-n/tmp/.venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 148, in __init__
また、 chain=False を設定して最終的にキャッチしたエラーのスタックトレースだけを表示していますが、デフォルトでは chain=True なのでsqliteのファイルを開けなかった部分のスタックトレースも表示されて、合計で100行近くになります。
ある程度の見やすさを確保しつつ、構造化ログに入れることを考えたフォーマットを考えてみました。
- エラーとエラーの発生元を最初に持ってくる（標準ライブラリと逆）
- ファイルパスはsys.pathからの相対パスにする
- 行番号だけあれば調査は可能なので、ソースコードは表示しない。ただしヒントとして関数名だけは書いておく。
- トレースバック部分は1フレームに1つのNamedTupleで表現し、好きにカスタマイズできるようにする。
これで作ったトレースバックのサンプルがこれです。
sqlalchemy.exc.OperationalError: (sqlite3.OperationalError) unable to open database file
(Background on this error at: https://sqlalche.me/e/20/e3q8)
Traceback (most recent call first):
sqlalchemy/engine/default.py:617 connect
sqlalchemy/engine/create.py:643 connect
sqlalchemy/pool/base.py:896 __connect
sqlalchemy/util/langhelpers.py:146 __exit__
sqlalchemy/pool/base.py:900 __connect
sqlalchemy/pool/base.py:674 __init__
sqlalchemy/pool/base.py:390 _create_connection
sqlalchemy/pool/impl.py:177 _do_get
sqlalchemy/util/langhelpers.py:146 __exit__
sqlalchemy/pool/impl.py:179 _do_get
sqlalchemy/pool/base.py:712 checkout
sqlalchemy/pool/base.py:1263 _checkout
sqlalchemy/pool/base.py:449 connect
sqlalchemy/engine/base.py:3304 raw_connection
sqlalchemy/engine/base.py:146 __init__
sqlalchemy/engine/base.py:2444 _handle_dbapi_exception_noconnection
sqlalchemy/engine/base.py:148 __init__
sqlalchemy/engine/base.py:3280 connect
sample.py:74 main
JSONにするとこうなります。トレースバックの1行を1文字列にしているのでエスケープ文字が入らないですし、見やすいJSONリーダーなどがあれば十分にそのまま読むことができます。
"exception": ['sqlalchemy.exc.OperationalError: (sqlite3.OperationalError) unable to open database file\n(Background on this error at: https://sqlalche.me/e/20/e3q8)'],
"stacktrace": ["sqlalchemy/engine/default.py:617 connect", "sqlalchemy/engine/create.py:643 connect", "sqlalchemy/pool/base.py:896 __connect", "sqlalchemy/util/langhelpers.py:146 __exit__", "sqlalchemy/pool/base.py:900 __connect", "sqlalchemy/pool/base.py:674 __init__", "sqlalchemy/pool/base.py:390 _create_connection", "sqlalchemy/pool/impl.py:177 _do_get", "sqlalchemy/util/langhelpers.py:146 __exit__", "sqlalchemy/pool/impl.py:179 _do_get", "sqlalchemy/pool/base.py:712 checkout", "sqlalchemy/pool/base.py:1263 _checkout", "sqlalchemy/pool/base.py:449 connect", "sqlalchemy/engine/base.py:3304 raw_connection", "sqlalchemy/engine/base.py:146 __init__", "sqlalchemy/engine/base.py:2444 _handle_dbapi_exception_noconnection", "sqlalchemy/engine/base.py:148 __init__", "sqlalchemy/engine/base.py:3280 connect", "sample.py:74 main"]
とりあえずここまでを minitraceback という名前でPyPIに登録しておきました。
また次回の記事で structlog で利用する方法などを紹介します。
