テックドクターでエンジニアをしている星野です。
弊社では Python と FastAPI を使うことが多く、アプリケーションの実行環境として Cloud Run を利用しています。
Cloud Run で障害調査をしていると、たくさんのログの中でアプリケーションのログが混ざってしまい、どの HTTP リクエストで発生したものなのか分からず苦労することがあります。
Cloud Run のリクエストログは自動でリクエストごとに出力しますが、アプリケーションのログは標準ではリクエストログと紐づきません。
この記事ではその解決策として、
- アプリケーションのログとリクエストを紐づけるには trace が使えること
- ただしFastAPI では
google-cloud-loggingを使うだけでは trace が付かない。OpenTelemetry を追加すれば紐づけ可能であること
の２点を紹介します。
trace でログを紐づける方法
Cloud Run はリクエストを受け取ると、traceparent ヘッダを付与し、その trace ID をリクエストログに記録します。
アプリケーションのログにも同じ trace ID を付与すれば、Cloud Logging でコンテナログとリクエストログが関連付けられ、1 リクエスト分のログをまとめて確認できます。
trace ID はリクエストのヘッダから自前で取り出すこともできますが、google-cloud-logging を使えばライブラリ側で付与してくれます。
google-cloud-logging を試す
依存パッケージの追加
fastapi==0.115.6 uvicorn[standard]==0.34.0 google-cloud-logging==3.11.3
setup_logging() を呼ぶ
基本的な書き方は次の通りです
import logging import google.cloud.logging client = google.cloud.logging.Client() client.setup_logging() logger = logging.getLogger(__name__)
setup_logging() は Python 標準の logging に Cloud Logging 用のハンドラを追加します。出力したログは Cloud Logging で見られるようになります。
こうすることにより、Flask の場合は、setup_logging() を呼ぶだけでアプリケーションのログがリクエストログと同じ trace に紐づきます。
ただし……FastAPI では trace が付かない
次に、FastAPI でも同じように書いてみます。
import logging import google.cloud.logging from fastapi import FastAPI client = google.cloud.logging.Client() client.setup_logging() logger = logging.getLogger(__name__) app = FastAPI() @app.get("/log") def emit_logs(): logger.info("info level log from /log") logger.warning("warning level log from /log") logger.error("error level log from /log") return {"status": "ok"}
これを Cloud Run にデプロイします。
gcloud run deploy cloud-logging-trace-demo \ --source . --region asia-northeast1 --allow-unauthenticated
デプロイしたエンドポイントに /log でリクエストを送り、そのリクエストの trace で Cloud Logging を検索したところ、アプリケーションのログには trace が付いていませんでした。
リクエストログ（GET /log）の下に、アプリケーションのログがぶら下がっていません。リクエストログには trace が付いていますが、アプリケーションのログには付いていないため、リクエストログとアプリケーションのログは紐づきませんでした。
公式ドキュメント Integration with Python Web Frameworks によると、google-cloud-logging がリクエストから trace を自動取得できるのは Flask と Django のみで、FastAPI はサポート対象に含まれていなかったためです。
trace の取得元は次のいずれかです。
- OpenTelemetry のアクティブな span
- Flask または Django のリクエストコンテキスト
FastAPI はどちらにも該当しないため、setup_logging() だけではアプリケーションのログに trace が付きませんでした。
逆に言えば、OpenTelemetry の span を用意すれば trace を取得できます。次は OpenTelemetry で span を生成してみます。
OpenTelemetry で trace を付与する
FastAPI でリクエストごとに OpenTelemetry の span を生成します。setup_logging() はその span から trace を取得します。
依存パッケージの追加
OpenTelemetry 関連を追加します。
opentelemetry-sdk==1.29.0 opentelemetry-instrumentation-fastapi==0.50b0
OpenTelemetry の設定
FastAPIInstrumentor を使って、リクエストごとに span を生成します。traceparent ヘッダはデフォルトで読み込まれるため、追加の設定は不要です。
import logging import google.cloud.logging from fastapi import FastAPI from opentelemetry import trace from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor from opentelemetry.sdk.trace import TracerProvider trace.set_tracer_provider(TracerProvider()) # google-cloud-logging は OpenTelemetry のアクティブな span から trace を取得する client = google.cloud.logging.Client() client.setup_logging() logger = logging.getLogger(__name__) app = FastAPI() FastAPIInstrumentor.instrument_app(app) # リクエストごとに span を生成する @app.get("/log") def emit_logs(): logger.info("info level log from /log") logger.warning("warning level log from /log") logger.error("error level log from /log") return {"status": "ok"}
検証結果
この状態で再デプロイし、/log にリクエストを送ったところ、アプリケーションのログとリクエストログが同じ trace に紐づきました。
リクエストログ（GET /log）の下に、アプリケーションのログがぶら下がって表示されています。アプリケーションのログを JSON で確認すると、trace / spanId / traceSampled が付与されています。
{ "logName": "projects/<project>/logs/run.googleapis.com%2Fstderr", "severity": "INFO", "trace": "projects/<project>/traces/c744c3b23c8f0b9acbff17b154197e73", "spanId": "e3eccc394a71c4d7", "traceSampled": true, "labels": { "python_logger": "app.main" } }
同じ trace のリクエストログは以下の通りです。
{ "logName": "projects/<project>/logs/run.googleapis.com%2Frequests", "httpRequest": { "status": 200 }, "trace": "projects/<project>/traces/c744c3b23c8f0b9acbff17b154197e73", "spanId": "3229e032d02683b5" }
spanId はアプリケーションのログとリクエストログで異なりますが、trace が一致していれば、リクエストログの下にアプリケーションのログをまとめて表示することができます。
なお今回はログに trace を付けるのが目的のため、span を Cloud Trace に送る exporter は設定していません。Cloud Trace のスパンツリーで span の親子関係まで見たい場合は、別途 exporter の設定が必要です。
trace を自前で付与する場合
依存パッケージを増やしたくない場合は、ライブラリを使わず、リクエストの traceparent ヘッダから trace ID を取り出し、ログの logging.googleapis.com/trace フィールドに設定して出力する方法もあります。traceparent がない環境では、フォールバックとして X-Cloud-Trace-Context ヘッダから取り出します。
# traceparent: 00-<trace-id>-<span-id>-<flags> traceparent = request.headers.get("traceparent") if traceparent: trace_id = traceparent.split("-")[1] else: # フォールバック: X-Cloud-Trace-Context は <trace-id>/<span-id>;o=<flags> trace_id = request.headers.get("X-Cloud-Trace-Context", "").split("/")[0] log_entry = { "message": "manual trace example", "logging.googleapis.com/trace": f"projects/{project}/traces/{trace_id}", } print(json.dumps(log_entry)) # 構造化ログとして出力する
まとめ
Flask や Django では setup_logging() だけで trace が付きますが、FastAPI では OpenTelemetry の追加が必要になります。
リクエストログとアプリケーションのログが同じ trace でまとまると、原因のリクエストを見つけやすくなります。
Cloud Run で FastAPI を動かしていてまだ設定されていないなら、今回のように google-cloud-logging と OpenTelemetry を組み合わせる構成を試すのがよさそうです。
補足として、setup_logging() は実行環境を自動判定するため、ローカルで動かすとログはターミナルに出力されず Cloud Logging API へ直接送信しようとします。送信には Application Default Credentials（ADC）による認証が必要で、認証がないとエラーになります。ローカルでターミナルに出力したい場合は、setup_logging() を呼ばないようにする必要があります。
