Webアプリケーションやバッチジョブを運用していくにあたって、エラーの影響範囲の調査のため、APIへのアクセスIDやバッチのジョブIDのついたログは欠かせないです。 このような類のIDをログとして残す場合には、そのIDの影響下にある全部の処理に対して該当のIDを渡したいです。 この類の処理をフルスクラッチで書こうとする場合、下記事項を考慮する必要があります。 ログのために既存のコードの引数を変えることはしたくないため、IDをロガー経由で渡す必要がある IDを渡されるロガーは処理の間はIDを保持してほしい、それ故ロガーはシングルトンインスタンスか、それに相当するモジュールになる asyncの入ったコードに対応するにはasyncio コルーチン間の割り込みを考慮する必要がある また、ログレベル、ログの出力時刻等の個々のログに付随する属性を解析する際にmachine readableになっていてほしいという要望もあります。 これらを考慮した処理を実現してくれるライブラリが今回紹介する structlog になります。 www.structlog.org Tomcatライクなロゴが印象に残ります。 導入 毎度おなじみpipです pip install structlog 処理IDが絡んだログのサンプル structlogを用いて処理IDをロガーにどのように出力させるか見ていきます。 まずユーザIDをログに出力するサンプルコードとして以下を考えます。 from structlog import get_logger log = get_logger() def some_other_function(): log.info('other event') def main(): some_response = {'user_id': 12, 'user_agent': 'Chrome'} # some_response = {'user_agent': 'Chrome'} if 'user_id' in some_response: log.info('some event', user_id=some_response['user_id']) some_other_function() else: log.info('exceptional prec') some_other_function() if __name__ == '__main__': main() structlogはロガーのdebug, info等のメソッドに任意のフィールドを追加して出力することができます。(l.14) この実装の場合だと以下のようなログ出力になり、冒頭で想定した「IDの影響下にある処理のログにすべてIDがついてほしい」という要件を満たせません。 2021-05-25 19:04.28 [info ] some event user_id=12 2021-05-25 19:04.28 [info ] other event ログコンテキストの構築 IDの影響下にある処理のログすべてにIDを持たせるには、次のように書きます。 import structlog from structlog.threadlocal import ( bind_threadlocal, clear_threadlocal, merge_threadlocal ) from structlog import configure configure( processors=[ merge_threadlocal, structlog.processors.add_log_level, structlog.processors.StackInfoRenderer(), structlog.dev.set_exc_info, structlog.processors.format_exc_info, structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M.%S", utc=False), structlog.dev.ConsoleRenderer() ] ) log = structlog.get_logger() def some_other_function(): log.info('other event') def main(): some_response = {'user_id': 12, 'user_agent': 'Chrome'} # some_response = {'user_agent': 'Chrome'} if 'user_id' in some_response: bind_threadlocal(user_id=some_response['user_id']) log.info('some event') some_other_function() else: log.info('exceptional prec') some_other_function() clear_threadlocal() if __name__ == '__main__': main() structlog.threadlocal モジュールはスレッド単位でログに出力される属性を管理します。 merge_threadlocal : ログの設定のprocessorにかませることでスレッドに固有の変数をログに出力するよう設定が行われます bind_threadlocal : スレッドに固有の変数のロードを行います clear_threadlocal : スレッドに固有の変数をクリアします このケースでは以下のログが出力され、user_id が見つかった後の処理すべてにIDが付与されることがわかります。 2021-05-25 20:30.50 [info ] some event user_id=12 2021-05-25 20:30.50 [info ] other event user_id=12 Python3.7 より導入されたcontextvarsモジュール関連の機能で structlog.contextvars モジュールもあります。これは asyncio を用いるようなサーバサイドAPIにおける、ID情報を付加したロギングに有効です。 構造化ログについて もう一点、structlogがサポートする構造化ログについても見ていきます。下記のログはpythonを開発していればよく出力する形式のログです。 2021-04-02 10:47:02 [INFO] some precessing log この類のログはhuman readableではありますが、ログの解析を行う際にはmachine readableではないので不便です。 構造化ログとはログの出力として頻繁に出される時刻、ログレベル、ログ本体等の情報がmachine readableな構造化データ(Json, TSV)にされたものを指します。 { "message": "some processing log", "lineno": 1590, "pathname": "/app/job/src/apiclient.py", "job_id": 20, "timestamp": "2021-04-02 10:47:02", "level": "info" } このような形式のログもstructlogはサポートしています。 Json形式のログ設定サンプル Jsonのログ出力用設定のサンプルです import sys import structlog from structlog.threadlocal import ( bind_threadlocal, clear_threadlocal, merge_threadlocal ) import logging structlog.configure( processors=[ merge_threadlocal, structlog.stdlib.filter_by_level, structlog.stdlib.add_logger_name, structlog.stdlib.add_log_level, structlog.stdlib.PositionalArgumentsFormatter(), structlog.processors.TimeStamper(fmt="iso"), structlog.processors.StackInfoRenderer(), structlog.processors.format_exc_info, structlog.processors.UnicodeDecoder(), structlog.processors.JSONRenderer() ], context_class=dict, logger_factory=structlog.stdlib.LoggerFactory(), wrapper_class=structlog.stdlib.BoundLogger, cache_logger_on_first_use=True, ) logging.basicConfig( format="%(message)s", stream=sys.stdout, level=logging.INFO, ) log = structlog.get_logger() def some_other_function(): log.info('other event') def main(): some_response = {'user_id': 12, 'user_agent': 'Chrome'} # some_response = {'user_agent': 'Chrome'} if 'user_id' in some_response: bind_threadlocal(user_id=some_response['user_id']) log.info('some event') some_other_function() else: log.info('exceptional prec') some_other_function() clear_threadlocal() if __name__ == '__main__': main() ロガーの出力を標準入出力に吐く設定がstructlog経由で行えないのは謎ですが、標準ライブラリのロガーを生成するようにstructlog経由で設定でき(l.25)、標準ライブラリのロガーに対して標準入出力に出力するように設定しています(l.29) 以下出力です {"user_id": 12, "event": "some event", "logger": "__main__", "level": "info", "timestamp": "2021-05-26T03:16:44.301541Z"} {"user_id": 12, "event": "other event", "logger": "__main__", "level": "info", "timestamp": "2021-05-26T03:16:44.301945Z"} 構造化されたログが出力されました。 参考記事 標準ライブラリの範囲で構造化ログで出力するようにしてみる - podhmo's diary この記事を書いた人 yad ビリヤニ食べたい