本記事はキャディ株式会社のアドベントカレンダーに寄稿しています。 adventar.org
こんにちは。
CADDi の Analysis PlatformチームでMLOps エンジニアを務めているcdi-amaniです。
普段は図面データ活用クラウド「CADDi Drawer」のエンジニアとして、機械学習のプラットフォームの開発を行っています。
本記事はアドベントカレンダー22日目の記事として、Pythonのログ改善をテーマに書きました。
それでは、早速本題に入りましょう。
Python開発者の皆さんはログ出力において、こんな課題ありませんか？
- 処理対象を特定するために、
request_idなどのコンテキスト情報を全てのログメッセージに含めたいが、ログメッセージ毎に記述するのは手間で、メンテナンス性も低下してしまう。 - アプリケーションの深い部分（コールスタックの奥にある関数やモジュール）では、スコープ的にこれらの情報を直接参照することができない。関数の引数として渡すのも冗長で避けたい。
これらの課題を解決するために、この記事ではcontextvarsを活用してログを改善する方法を紹介します。
問題の背景: contextvars導入前の状態
チームが担当する一部のアプリケーションでは、共通のログモジュールを使って、ログをJSON形式で構造化して出力しています。
このログには、timestampやログを出力した関数名など、さまざまな共通の基本情報に加えて、request_idやclient_idなどの処理対象に関連する情報も含めています。
以下は、contextvarsを使う前のログモジュールを簡略化したサンプルです。
# logger_setup.py import logging from logging import Logger from pythonjsonlogger import jsonlogger from datetime import UTC, datetime class CustomJsonFormatter(jsonlogger.JsonFormatter): def format(self, record: logging.LogRecord) -> str: record.func_name = record.funcName record.timestamp = datetime.now(UTC).isoformat(timespec="milliseconds") record.severity = record.levelname return super().format(record) class LoggerSetup: def __init__(self, module_name: str, log_level: int): self.log_level = log_level self.logger_base: Logger = logging.getLogger(module_name) self.logger_base.setLevel(self.log_level) def setup_handler(self) -> logging.Handler: """handlerの設定""" handler = logging.StreamHandler() handler.setLevel(self.log_level) return handler def setup_formatter(self, handler: logging.Handler) -> None: """handlerでJSON formatterを設定""" formatter = CustomJsonFormatter() handler.setFormatter(formatter) self.logger_base.addHandler(handler) def get_logger(self) -> Logger: handler = self.setup_handler() if handler: self.setup_formatter(handler) return self.logger_base
それを各種アプリから以下のように使っていました。この記事ではapp1.pyというアプリを例として使います。
app1.pyはリクエストメッセージを受け付けたあと、それを処理するための関数を呼び出して、処理段階ごとのログメッセージを出力するものです。
app1.pyで共通ログモジュールを使ってloggerをセットアップする部分：
# app1.py import logging from logger_setup import LoggerSetup logger_setup = LoggerSetup(module_name=__file__, log_level=logging.INFO) logger = logger_setup.get_logger()
リクエストメッセージを受け取る関数：
共通情報以外に、request_idのようなコンテキスト情報は、各logger文でextra={"request_id": message.request_id}として明示的に渡していました。
# app1.py def receive_message(RequestMessage message): # マルチスレッド対応のメッセージ受信関数 logger.info( "receive_messageのログだよ。request_idは毎回extraで渡してくれなければわからないよ", extra={"request_id": message.request_id} ) # メッセージ処理スタート process_request(message.request_data)
リクエストを処理する関数:
以下の例にあるprocess_requestやdeep_functionのようなコールスタックの奥にある関数のスコープでは、messageに含まれていたrequest_idを参照できないため、そのような関数ではコンテキスト情報をログメッセージに含めていませんでした。
# app1.py def deep_function(): logger.info("deep_functionのログだよ。request_idなどはスコープ外なので、ここではextraとして渡せない...") # 実際の処理コード ... def process_request(RequestData data): logger.info("process_requestのログだよ。request_idなどはスコープ外なので、ここではextraとして渡せない...") # 実際の処理コード ... deep_function() ...
このセットアップで出るログは以下のようなログになります。
{"message": "receive_messageのログだよ。request_idは毎回extraで渡してくれなければわからないよ", "request_id": "12345", "func_name": "receive_message", "timestamp": "2024-12-16T12:33:24.205+00:00", "severity": "INFO"} {"message": "process_requestのログだよ。request_idなどはスコープ外なので、ここではextraとして渡せない...", "func_name": "process_request", "timestamp": "2024-12-16T12:33:24.205+00:00", "severity": "INFO"} {"message": "deep_functionのログだよ。request_idなどはスコープ外なので、ここではextraとして渡せない...", "func_name": "deep_function", "timestamp": "2024-12-16T12:33:24.206+00:00", "severity": "INFO"}
この方法には以下のような問題がありました：
情報が参照可能なスコープの中でも、コンテキスト情報を毎回
extra={}で渡す必要があるコールスタックの奥にある関数では
request_idを参照できないため、ログに記載できず、どのrequest_idに対応するログなのかがわからなくなってしまう。特にエラーログの場合、この点が重要な課題でした。
上記のような問題を解決するために、pythonのcontextvarsを導入しました。
解決策: contextvarsでコンテキスト情報を管理
contextvarsはPython 3.7で追加されたモジュールで、スレッドローカルのように各実行スレッドごとに独立したデータを管理できます。
これを利用すると、一度だけ設定したコンテキスト情報をどこからでも参照できるようになります。
基本的な使い方は以下の通りです。
- ステップ1: contextvarsの初期設定：まず、コンテキスト変数を定義します。
import contextvars # コンテキスト変数を定義 request_id_context = contextvars.ContextVar("request_id", default=None)
- ステップ2: コンテキスト変数を設定
request_id_context.set("12345")
- ステップ3: コンテキスト変数を参照
request_id = request_id_context.get()
以上の3ステップが基本的な使い方になります。
logger_setup.py と app1.pyへのcontextvarsの適用
先ほど説明したcontextvarsの基本的な使い方を、実際にlogger_setup.pyとapp1.pyに適用してみます。
logger_setup.pyにあるCustomJsonFormatterクラスを、contextvarsを活用して次のように改善します。
# logger_setup.py import logging from logging import Logger from pythonjsonlogger import jsonlogger from datetime import UTC, datetime import contextvars from typing import Any # コンテキスト変数を定義 request_id_context = contextvars.ContextVar("request_id", default=None) client_id_context = contextvars.ContextVar("client_id", default=None) class CustomJsonFormatter(jsonlogger.JsonFormatter): def format(self, record: logging.LogRecord) -> str: record.func_name = record.funcName record.timestamp = ... ... # コンテキスト情報 record.request_id = request_id_context.get() record.client_id = client_id_context.get() ... return super().format(record)
さらに、LoggerSetupというクラスの中で、context情報をsetするための関数を以下のように実装します。
def set_context_data(self, **kwargs: Any) -> None: """ContextVarにデータを設定する""" context_mapping = { "request_id": request_id_context, "client_id": client_id_context, } for key, value in kwargs.items(): if key in context_mapping: # 定義済みのContextVarのみ設定 context_mapping[key].set(value) else: raise KeyError(f"Unknown context key: {key}")
次に、app1.py側の対応をします。
リクエストメッセージを受け取る関数receive_message: context情報の設定およびログの出力は、以下のように行います。
なお、loggerの初期化や必要なimportは、導入前の例と同じです。
def receive_message(RequestMessage message): # 受け取ったメッセージをベースに一度だけcontext情報を設定します。 logger_setup.set_context_data(request_id=message.request_id, client_id=message.client_id) #extra={}を使わなくても上記で設定した情報が自動的にログに入るようになります。 logger.info("receive_messageのログだよ。extra使わなくてもコンテキスト情報がcontextvarsから自動的に入るよ！") # 処理スタート process_request(message.request_data)
リクエストを処理する関数に関しては、ログメッセージの内容以外特に変更なしです。
def deep_function(): #こちらの関数のスコープ的に参照できない情報も、contextvarsとして設定すれば自動的にログメッセージに入るようになります。 logger.info("deep_functionのログだよ。request_idがcontextvarsから自動的に入るよ") # 実際の処理コード ... def process_request(RequestData data): #こちらの関数のスコープ的に参照できない情報も、contextvarsとして設定すれば自動的にログメッセージに入るようになります。 logger.info("process_requestのログだよ。request_idがcontextvarsから自動的に入るよ") # 実際の処理コード ... deep_function()
これで、ログメッセージ毎にextraで情報を渡さなくても、スコープ的にその情報にアクセスできなくても、以下のように全てのログにコンテキスト情報が入ります。
{"message": "receive_messageのログだよ。extra使わなくてもコンテキスト情報がcontextvarsから自動的に入るよ！", "func_name": "receive_message", "timestamp": "2024-12-16T12:41:40.265+00:00", "severity": "INFO", "request_id": "12345", "client_id": "client-11"} {"message": "process_requestのログだよ。request_idがcontextvarsから自動的に入るよ", "func_name": "process_request", "timestamp": "2024-12-16T12:41:40.265+00:00", "severity": "INFO", "request_id": "12345", "client_id": "client-11"} {"message": "deep_functionのログだよ。request_idがcontextvarsから自動的に入るよ", "func_name": "deep_function", "timestamp": "2024-12-16T12:41:40.265+00:00", "severity": "INFO", "request_id": "12345", "client_id": "client-11"}
実際の効果
contextvarsを導入することで、以下の効果が得られました：
- コードが簡潔に: コンテキスト情報を毎回ログメッセージで渡さなくてもよくなりました。
- スコープを超えた情報共有: 深い関数でも、request_idがログメッセージに自動的に埋め込まれるようになりました。
- 管理の一元化: contextvarsによって、コンテキスト情報の管理がより直感的になりました。
さらに、機械学習チームでは、ログを通じて得られる情報を基に、各リクエストの処理時間や、処理ステージごとの実行状況を監視ツールで分析しやすくなりました。 これにより、モデル推論やデータ前処理のボトルネックを特定しやすくなって、運用の改善・最適化に役立っています。
まとめ
contextvarsを使うことで、ログ向けのコンテキスト情報の管理を大幅に改善することができました。特に、一度設定した情報をどこでも簡単に参照可能にする点が非常に便利です。 Pythonのログ対応で同じような課題を感じている方は、ぜひcontextvarsの導入を検討してみてください。
