FastAPIリスエストごとのログ識別方法

　
0
このエントリーをはてなブックマークに追加
Python
FastAPI
Daichi Takayama
Daichi Takayama (高山 大地)

以下の文章は執筆者のDavid Lorenzoさんからの許可を得て翻訳したものです。

https://medium.com/gradiant-talks/identifying-fastapi-requests-in-logs-bac3284a6aa

WebアプリケーションをFastAPI（または他のウェブフレームワーク）で開発・保守する際、リクエスト処理の過程を理解するために、リクエスト処理の最も重要な部分にログ記録を実装することが非常に役立ちます。

ただし、アプリケーションが同時に複数のリクエストを処理することが多いため、問題が生じる可能性があります。例えばある失敗したリクエストに対する調査を行いたいとき、並行したリクエスト処理によってログがどのリクエストのものか判別がつかなくなる、といったことです。

1.リクエスト識別なしの例

以下の例を使って問題を説明します：

import random
import uvicorn
from fastapi import FastAPI
from fastapi.responses import JSONResponse

app = FastAPI()

def divide(a, b):
    print(f"Dividing {a} / {b} ...")
    result = a / b
    print(f"Result is {result}")

@app.get("/")
def read_root():
    print("Request started")
    a = 100
    b = random.randint(0, 1)

    try:
        return {"success": True, "result": divide(a, b)}

    except Exception as ex:
        print(f"Request failed: {ex}")
        return JSONResponse(content={"success": False}, status_code=500)

    finally:
        print("Request ended")

if __name__ == "__main__":
    uvicorn.run(app)

この例では、ルートエンドポイントがZeroDivisionErrorをランダムに発生させて失敗します。今は例を単純にするためにprint()ステートメントを使っていますが、実際のロガーを使った場合でも考え方は同じです。各リクエストは以下のような（仮の）ログレコードを出力します：

  • エンドポイントリクエストハンドラ（read_root()）が実行を開始した時点での「Request started」
  • リクエストハンドラから呼び出されたdivide()関数が実行を開始した時点での「Dividing x / y ...」
  • divide()関数が成功した時点での「Result is z」
  • リクエストが失敗した場合の「Request failed: division by zero」
  • リクエスト処理が終了した場合の「Request ended」

以下の非同期クライアントコードを使用してサーバーを実行し、4つの同時リクエストを行うと…

import asyncio
import httpx

async def request():
    async with httpx.AsyncClient() as client:
        await client.get("http://localhost:8000")

async def run():
    await asyncio.gather(*[request() for _ in range(4)])

if __name__ == "__main__":
    asyncio.run(run())

…サーバーの出力には以下のログレコードが表示されます：

Request started
Dividing 100 / 1 ...
Request started
Result is 100.0
Request ended
Dividing 100 / 1 ...
Request started
Request started
Result is 100.0
Request ended
Dividing 100 / 0 ...
Request failed: division by zero
Dividing 100 / 0 ...
Request ended
Request failed: division by zero
Request ended

このように、どのリクエストが失敗し、どのリクエストが成功したかを識別する方法がありません。単一のリクエストをログ全体で追跡することはできません。

2.リクエストごとに一意の識別子を生成し、コンテキスト変数を使用する方法

この問題に対する合理的な解決策は、各ログレコードにそれぞれのリクエストのための何らかの識別子を追加することです。私はこの目的のためにUUID4を生成することを好みます。これは、ランダムな文字と数字で構成される36文字の長い文字列です。生成された各UUID4は一意であると考えられます。

しかし、この解決策にはさらに2つのステップが含まれます：

  1. リクエストの一意の識別子をコンテキスト変数に格納します。簡単に言うと、コンテキスト変数とは、キーによって識別される変数で、それらが作成されたワークフローからいつでも設定して読み取ることができます（同じスレッド内であれば、他の関数にパラメータとして渡す必要はありません）。
  2. FastAPIの機能であるミドルウェア関数を使用します。この関数は、リクエストハンドラの前後でコードを実行するため、ログ目的でリクエストIDを注入するために使用できます。

以前のサーバーコードのスニペットは、次のようになります：

import uuid
import contextvars
import random
import uvicorn
from fastapi import FastAPI
from fastapi.responses import JSONResponse

app = FastAPI()
request_id_contextvar = contextvars.ContextVar("request_id", default=None)

def debug(message):
    request_id = request_id_contextvar.get()
    print(f"({request_id}) {message}")

def divide(a, b):
    debug(f"Dividing {a} / {b} ...")
    result = a / b
    debug(f"Result is {result}")

@app.middleware("http")
async def request_middleware(request, call_next):
    request_id = str(uuid.uuid4())
    request_id_contextvar.set(request_id)
    debug("Request started")

    try:
        return await call_next(request)

    except Exception as ex:
        debug(f"Request failed: {ex}")
        return JSONResponse(content={"success": False}, status_code=500)

    finally:
        assert request_id_contextvar.get() == request_id
        debug("Request ended")

@app.get("/")
async def read_root():
    a = 100
    b = random.randint(0, 1)
    return {"success": True, "result": divide(a, b)}

if __name__ == "__main__":
    uvicorn.run(app)

ここで行われた変更に注目してください：

  1. FastAPIのドキュメントに記載されているように、HTTPミドルウェア（L20）を定義します。簡単に言うと、これは"request"と"call_next"という2つのパラメータを取る非同期関数です。リクエスト処理関数（この場合は"read_root()"）によって生成されたレスポンスであるコルーチン"call_next"の結果を返すことが義務付けられています。
  2. ミドルウェアは、新しいリクエストごとにUUID4文字列を生成し（L22）、グローバルスコープで定義されたコンテキスト変数（L9）にそれを設定します。グローバルスコープで定義されたコンテキスト変数と、ミドルウェア内から設定するその変数の実際の値、つまり一意のリクエストIDを混同しないでください。
  3. try/except/finallyはミドルウェアの一部になっているため、このロジックはエンドポイントには実装されていません。これからは、ミドルウェアがどのエンドポイントへの呼び出しにも実行されます（/docsエンドポイントや存在しないルートも含む）。
  4. 疑似ログ関数（"debug()"）は、コンテキスト変数に設定されたリクエストIDを取得（L12）し、それを印刷されるログレコードに追加します。

これが私たちのサーバーログが今どのように見えるかの例です：

(9897a21a-bd08-4d41-b20b-f4d540a9b5fa) Request started
(9897a21a-bd08-4d41-b20b-f4d540a9b5fa) Dividing 100 / 1 ...
(9897a21a-bd08-4d41-b20b-f4d540a9b5fa) Result is 100.0
(9897a21a-bd08-4d41-b20b-f4d540a9b5fa) Request ended

(06eb98c5-b515-44a6-b4e8-e7c1f1a9c374) Request started
(06eb98c5-b515-44a6-b4e8-e7c1f1a9c374) Dividing 100 / 1 ...
(06eb98c5-b515-44a6-b4e8-e7c1f1a9c374) Result is 100.0
(06eb98c5-b515-44a6-b4e8-e7c1f1a9c374) Request ended

(4edfa9f7-70f5-4f1e-901e-1e73a30019b1) Request started
(4edfa9f7-70f5-4f1e-901e-1e73a30019b1) Dividing 100 / 0 ...
(4edfa9f7-70f5-4f1e-901e-1e73a30019b1) Request failed: division by zero
(4edfa9f7-70f5-4f1e-901e-1e73a30019b1) Request ended

(4cf7a653-ac6b-4cc4-9d04-d970084f33d8) Request started
(4cf7a653-ac6b-4cc4-9d04-d970084f33d8) Dividing 100 / 0 ...
(4cf7a653-ac6b-4cc4-9d04-d970084f33d8) Request failed: division by zero
(4cf7a653-ac6b-4cc4-9d04-d970084f33d8) Request ended

これで、並行して受けた処理を行ったリクエストがあるとき、どのログレコードがどのリクエストの一部であるかを知ることができます。これらをまとめて、各リクエストで正確に何が起こったかを分かりやすくすることもできます。

(9897a21a-bd08-4d41-b20b-f4d540a9b5fa) Request started
(9897a21a-bd08-4d41-b20b-f4d540a9b5fa) Dividing 100 / 1 ...
(9897a21a-bd08-4d41-b20b-f4d540a9b5fa) Result is 100.0
(9897a21a-bd08-4d41-b20b-f4d540a9b5fa) Request ended

(06eb98c5-b515-44a6-b4e8-e7c1f1a9c374) Request started
(06eb98c5-b515-44a6-b4e8-e7c1f1a9c374) Dividing 100 / 1 ...
(06eb98c5-b515-44a6-b4e8-e7c1f1a9c374) Result is 100.0
(06eb98c5-b515-44a6-b4e8-e7c1f1a9c374) Request ended

(4edfa9f7-70f5-4f1e-901e-1e73a30019b1) Request started
(4edfa9f7-70f5-4f1e-901e-1e73a30019b1) Dividing 100 / 0 ...
(4edfa9f7-70f5-4f1e-901e-1e73a30019b1) Request failed: division by zero
(4edfa9f7-70f5-4f1e-901e-1e73a30019b1) Request ended

(4cf7a653-ac6b-4cc4-9d04-d970084f33d8) Request started
(4cf7a653-ac6b-4cc4-9d04-d970084f33d8) Dividing 100 / 0 ...
(4cf7a653-ac6b-4cc4-9d04-d970084f33d8) Request failed: division by zero
(4cf7a653-ac6b-4cc4-9d04-d970084f33d8) Request ended

3.ログ記録にLoguruを使用する技術

以前の例では適切なログツールを使用していませんでした。個人的にはLoguruが好きです。その理由の一つは、ログ目的でコンテキスト変数を扱うことができ、contextualizeコンテキストマネージャとbind修飾子を通じてこれを実現しているからです。

Loguruを使用すると、サーバーのスニペットは次のようになります：

import sys
import uuid
import random
import loguru
import uvicorn
from fastapi import FastAPI
from fastapi.responses import JSONResponse

app = FastAPI()
logger = loguru.logger
logger.remove()
logger.add(sys.stdout, format="{time} - {level} - ({extra[request_id]}) {message} ", level="DEBUG")

def divide(a, b):
    logger.debug(f"Dividing {a} / {b} ...")
    result = a / b
    logger.debug(f"Result is {result}")

@app.middleware("http")
async def request_middleware(request, call_next):
    request_id = str(uuid.uuid4())
    with logger.contextualize(request_id=request_id):
        logger.info("Request started")

        try:
            return await call_next(request)

        except Exception as ex:
            logger.error(f"Request failed: {ex}")
            return JSONResponse(content={"success": False}, status_code=500)

        finally:
            logger.info("Request ended")

@app.get("/")
async def read_root():
    a = 100
    b = random.randint(0, 1)
    return {"success": True, "result": divide(a, b)}

if __name__ == "__main__":
    uvicorn.run(app)

ここでは、デフォルトのLoguruロガーをカスタムロガーに置き換え（L12）、extraログフィールドからのリクエストIDを含むカスタム出力フォーマットを定義しています。また、リクエストミドルウェア（L22）でlogger.contextualizeコンテキストマネージャを使用しており、これは定義されたkwargsをコンテキストマネージャから発生した任意のロガーコールにログフィールドとしてのコンテキスト変数を設定します。

これらの変更により、私たちのサーバーロギング出力は次のようになります：

2021-03-06T21:12:51.218465+0100 - INFO - (a21798b2-0c30-417e-a514-60bb6666a05c) Request started
2021-03-06T21:12:51.219203+0100 - DEBUG - (a21798b2-0c30-417e-a514-60bb6666a05c) Dividing 100 / 0 ...
2021-03-06T21:12:51.219385+0100 - INFO - (5741a3d1-dd0b-4247-9a71-c50f7183b3e9) Request started
2021-03-06T21:12:51.219535+0100 - INFO - (59121820-c4b8-4f66-8d33-09d04333e096) Request started
2021-03-06T21:12:51.219663+0100 - INFO - (a645870a-ca49-4dba-ad5f-6ba0383f3477) Request started
2021-03-06T21:12:51.219771+0100 - ERROR - (a21798b2-0c30-417e-a514-60bb6666a05c) Request failed: division by zero
2021-03-06T21:12:51.219869+0100 - INFO - (a21798b2-0c30-417e-a514-60bb6666a05c) Request ended
2021-03-06T21:12:51.220383+0100 - DEBUG - (5741a3d1-dd0b-4247-9a71-c50f7183b3e9) Dividing 100 / 0 ...
2021-03-06T21:12:51.220550+0100 - DEBUG - (59121820-c4b8-4f66-8d33-09d04333e096) Dividing 100 / 1 ...
2021-03-06T21:12:51.220622+0100 - DEBUG - (59121820-c4b8-4f66-8d33-09d04333e096) Result is 100.0
2021-03-06T21:12:51.221215+0100 - DEBUG - (a645870a-ca49-4dba-ad5f-6ba0383f3477) Dividing 100 / 1 ...
2021-03-06T21:12:51.221320+0100 - DEBUG - (a645870a-ca49-4dba-ad5f-6ba0383f3477) Result is 100.0
2021-03-06T21:12:51.221534+0100 - ERROR - (5741a3d1-dd0b-4247-9a71-c50f7183b3e9) Request failed: division by zero
2021-03-06T21:12:51.221628+0100 - INFO - (5741a3d1-dd0b-4247-9a71-c50f7183b3e9) Request ended
2021-03-06T21:12:51.222045+0100 - INFO - (59121820-c4b8-4f66-8d33-09d04333e096) Request ended
2021-03-06T21:12:51.222192+0100 - INFO - (a645870a-ca49-4dba-ad5f-6ba0383f3477) Request ended

4.レスポンスHTTPヘッダーにリクエストIDを返す方法

ログレコードでリクエストを識別するようになったので、この識別子をレスポンスヘッダーにも送信することができます。これは非常に便利です。リクエストを実行してリクエストIDを知り、そのIDを使ってサーバーログレコードを検索することで、何が起こったのかを正確に知ることができます。

これは、ミドルウェアで生成されたリクエストIDをレスポンスヘッダーの一部として追加することで実行できます：

import sys
import uuid
import random
import loguru
import uvicorn
from fastapi import FastAPI
from fastapi.responses import JSONResponse

app = FastAPI()
logger = loguru.logger
logger.remove()
logger.add(sys.stdout, format="{time} - {level} - ({extra[request_id]}) {message} ", level="DEBUG")

def divide(a, b):
    logger.debug(f"Dividing {a} / {b} ...")
    result = a / b
    logger.debug(f"Result is {result}")

@app.middleware("http")
async def request_middleware(request, call_next):
    request_id = str(uuid.uuid4())
    with logger.contextualize(request_id=request_id):
        logger.info("Request started")

        try:
            response = await call_next(request)

        except Exception as ex:
            logger.error(f"Request failed: {ex}")
            response = JSONResponse(content={"success": False}, status_code=500)

        finally:
            response.headers["X-Request-ID"] = request_id
            logger.info("Request ended")
            return response

@app.get("/")
async def read_root():
    a = 100
    b = random.randint(0, 1)
    return {"success": True, "result": divide(a, b)}

if __name__ == "__main__":
    uvicorn.run(app)

ミドルウェアでのレスポンスの返し方を変更しました。これは「finally」ブロック（L33）で行われ、例外による失敗が発生しても成功したリクエストであっても、常にヘッダーにリクエストIDを追加できるようにするためです。

この代替クライアントスニペットを実行すると、レスポンスヘッダーから取得したリクエストIDを出力します...

import random
import asyncio
import httpx

async def request():
    async with httpx.AsyncClient() as client:
        r = await client.get("http://localhost:8000")
        request_id = r.headers.get("x-request-id")
        status_code = r.status_code
        print(f"Received response {status_code} for request_id={request_id}")

async def run():
    await asyncio.gather(*[request() for _ in range(4)])

if __name__ == "__main__":
    asyncio.run(run())

...結果としてこのような出力が得られます：

Received response 200 for request_id=88f9c19c-4c59-4acb-bf65-f095ebef4e4c
Received response 500 for request_id=0b5f4d5e-412e-44f3-9ff4-788cd819944c
Received response 200 for request_id=19a272af-0f01-415d-8f0e-9fd0bff0c453
Received response 500 for request_id=4e88637c-0e8d-439d-9894-4bf5b3bc1316

これにより、リクエストが成功したか失敗したかに関わらず、各リクエストのリクエストIDをクライアントが確認できるようになります。そして、そのIDを使用してサーバーログを検索し、リクエストの処理中に何が起こったかを正確に把握することができます。

最終的な考慮事項

これらの例は、FastAPIアプリケーションで実行されるリクエストの識別と追跡の主なアイデアをカバーするものです。他にも興味深い点として、以下のようなことが挙げられます：

  1. アプリケーション全体にわたるログの実装を完了させる。
  2. 後でログレコードを見つけることができるように、ログレコードを永続化する。これは、ログレコードのキャプチャ方法、永続化の場所、後での検索方法など、多くの方法で行うことができます。LoguruはログレコードをJSONで出力できることを覚えておいてください（「serialize」パラメータを参照）。
  3. トレーサビリティについて学ぶ。
Python
FastAPI
info-outline

お知らせ

K.DEVは株式会社KDOTにより運営されています。記事の内容や会社でのITに関わる一般的なご相談に専門の社員がお答えしております。ぜひお気軽にご連絡ください。

関連記事

0 ForeignKeyを正しく設定しているのにsqlalchemy.exc.NoReferencedT esrgan-v1-x2plus
ForeignKeyを正しく設定しているのにsqlalchemy.exc.NoReferencedTableErrorが出る
　
Kazuki Moriyama
Kazuki Moriyama (森山 和樹)
SQLAlchemy
Python
0 The alchemist on snakes esrgan-v1-x2plus
SQLAlchemy ORMの宣言的モデル定義でMany to Manyのrelationshipがある際にモデルファイルを複数に分ける
　
Kazuki Moriyama
Kazuki Moriyama (森山 和樹)
Python
SQLAlchemy
0 A python which has a mobile phone esrgan-v1-x2plus
PythonのCallableで関数に型を付ける
　
Kazuki Moriyama
Kazuki Moriyama (森山 和樹)
Python
Pyright
type-hint
0 Hypothesis journey esrgan-v1-x2plus
Hypothesisを用いたテスト最適化の探求
　
Daichi Takayama
Daichi Takayama (高山 大地)
Python
property-based-testing
0 Bubbles sorting esrgan-v1-x2plus
テストパフォーマンスの最適化
　
Daichi Takayama
Daichi Takayama (高山 大地)
Python
property-based-testing
0 integrated shrinking esrgan-v1-x2plus
合成に基づいた縮小処理
　
Daichi Takayama
Daichi Takayama (高山 大地)
Python
property-based-testing