menu Chancel's blog
rss_feed
Chancel's blog
有善始者实繁，能克终者盖寡。

FastAPI为每一个请求生成唯一标识符

作者：Chancel Yang， 创建：2024-06-27， 字数：7482， 已阅：325， 最后更新：2024-06-27

使用 FastAPI 开发 Web 应用，在并发高的时候进行logging的日志跟踪非常困难

如果可以实现一个日志类似于：

TEXT
"%(asctime)s - %(unique_id)s - %(name)s - %(levelname)s - %(message)s"

其中 unique_id 由请求入口处生成

这样在日志跟踪中只要搜索 unique_id 的值就可以跟踪完一次请求的内容，非常方便

代码实现如下：

Python
import asyncio
import logging
import random
import uuid
import time
import uvicorn

from fastapi import FastAPI, Request, Depends
from contextvars import ContextVar


app = FastAPI()

# Create a context variable for unique_id
unique_id_context: ContextVar[str] = ContextVar("unique_id", default="")

# Custom filter to add unique_id to log records
class UniqueIDFilter(logging.Filter):
    def filter(self, record):
        record.unique_id = unique_id_context.get()
        return True

# Configure logging
formatter = logging.Formatter("%(asctime)s - %(unique_id)s - %(name)s - %(levelname)s - %(message)s")
handler = logging.StreamHandler()
handler.setFormatter(formatter)
logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
logger.addHandler(handler)

# Add the custom filter to the logger
logger.addFilter(UniqueIDFilter())

@app.middleware("http")
async def add_process_time_header(request: Request, call_next):
    unique_id = str(uuid.uuid4())
    request.state.random_int = random.randint(1,10)
    unique_id_context.set(unique_id)

    start_time = time.time()
    response = await call_next(request)
    process_time = time.time() - start_time
    response.headers["X-Process-Time"] = str(process_time)
    response.headers["X-Unique-Id"] = unique_id
    logger.info(f"unique_id {unique_id} progress time {process_time}")
    return response

@app.get("/")
async def index(r:Request):
    logger.info(f"sleep {r.state.random_int} second")
    await asyncio.sleep(r.state.random_int)
    return {"message": f"sleep {r.state.random_int} second"}


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

代码说明：

  1. 在路由处理函数中预先使用 str(uuid.uuid4()) 来生成一个唯一请求的ID，并在请求结束后将请求的唯一ID放入 headers 方便与调用者确认请求ID
  2. 使用上下文管理器 ContextVar 和 logging.Filter 子类来实现每一次日志输出时检查上下文并提取 unique_id 打印到日志中
  3. 为了方便测试，添加了 request.state.random_int 随机数，在 index 路由中休眠线程模拟业务 1-10 秒

测试一下 20 个并发，然后查看日志是否每个请求ID的处理时间与休眠时间对的上：

Bash
siege -c 20 -r 1 http://127.0.0.1:8000

日志输出如下

TEXT
INFO:     Started server process [1868536]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
2024-06-28 11:28:50,966 - a5b9f9bf-ee66-4fd4-b214-5f41ebd2a8bc - root - INFO - sleep 7 second
2024-06-28 11:28:50,968 - 6957301f-4cf5-455e-873a-d6bda54e2353 - root - INFO - sleep 10 second
2024-06-28 11:28:50,969 - fceb6f9e-d321-4b88-9eb1-53799501ff19 - root - INFO - sleep 4 second
2024-06-28 11:28:50,970 - e82b371a-52dd-495b-bdbc-1ff3de229c6b - root - INFO - sleep 3 second
2024-06-28 11:28:50,971 - 6d19bb0a-b2c5-48a7-b1a0-b6bbeefc5223 - root - INFO - sleep 1 second
2024-06-28 11:28:50,972 - fca657f0-4cdf-43e6-b0d6-8d7a664f459a - root - INFO - sleep 7 second
2024-06-28 11:28:50,973 - ad150e7c-7f43-4362-9378-11ebb023b0a1 - root - INFO - sleep 4 second
2024-06-28 11:28:50,974 - 8dc07f24-933f-4f90-bbee-362aed360db2 - root - INFO - sleep 8 second
2024-06-28 11:28:50,975 - ea9ef6b3-edc5-4899-9997-cbcb95afd245 - root - INFO - sleep 2 second
2024-06-28 11:28:50,976 - 8c07e01b-759a-4b97-a974-ef1bef6515a8 - root - INFO - sleep 7 second
2024-06-28 11:28:50,977 - 5dff95b0-76b9-4419-870a-e09efe945768 - root - INFO - sleep 8 second
2024-06-28 11:28:50,978 - 284f465b-a967-4a7d-85f7-ae26e83aee94 - root - INFO - sleep 9 second
2024-06-28 11:28:50,980 - 0dab1f58-b660-466e-929b-5048acd1d0d2 - root - INFO - sleep 5 second
2024-06-28 11:28:50,981 - 5ad2bcba-b7dc-42fe-b8b4-37c49d82063b - root - INFO - sleep 6 second
2024-06-28 11:28:50,982 - 98abd862-af54-4019-9495-087b14b11d8b - root - INFO - sleep 7 second
2024-06-28 11:28:50,983 - 718945ee-725a-4a05-af40-231ca1f61852 - root - INFO - sleep 1 second
2024-06-28 11:28:50,983 - a20dd350-d5a4-40ca-bcd9-e2ddbd5c2347 - root - INFO - sleep 6 second
2024-06-28 11:28:50,984 - 019b2a6b-1297-49cb-be5f-b64aba7929f7 - root - INFO - sleep 8 second
2024-06-28 11:28:50,985 - bcb4f670-c7fc-42a0-95b9-52db1b6bc9bf - root - INFO - sleep 4 second
2024-06-28 11:28:50,986 - 25b3e2a3-3138-4989-9392-f730e26fa408 - root - INFO - sleep 8 second
2024-06-28 11:28:51,973 - 6d19bb0a-b2c5-48a7-b1a0-b6bbeefc5223 - root - INFO - unique_id 6d19bb0a-b2c5-48a7-b1a0-b6bbeefc5223 progress time 1.0021953582763672
2024-06-28 11:28:51,983 - 718945ee-725a-4a05-af40-231ca1f61852 - root - INFO - unique_id 718945ee-725a-4a05-af40-231ca1f61852 progress time 1.00124192237854
2024-06-28 11:28:52,977 - ea9ef6b3-edc5-4899-9997-cbcb95afd245 - root - INFO - unique_id ea9ef6b3-edc5-4899-9997-cbcb95afd245 progress time 2.0021045207977295
2024-06-28 11:28:53,971 - e82b371a-52dd-495b-bdbc-1ff3de229c6b - root - INFO - unique_id e82b371a-52dd-495b-bdbc-1ff3de229c6b progress time 3.0014114379882812
2024-06-28 11:28:54,970 - fceb6f9e-d321-4b88-9eb1-53799501ff19 - root - INFO - unique_id fceb6f9e-d321-4b88-9eb1-53799501ff19 progress time 4.001139402389526
2024-06-28 11:28:54,974 - ad150e7c-7f43-4362-9378-11ebb023b0a1 - root - INFO - unique_id ad150e7c-7f43-4362-9378-11ebb023b0a1 progress time 4.001373291015625
2024-06-28 11:28:54,987 - bcb4f670-c7fc-42a0-95b9-52db1b6bc9bf - root - INFO - unique_id bcb4f670-c7fc-42a0-95b9-52db1b6bc9bf progress time 4.002241134643555
2024-06-28 11:28:55,980 - 0dab1f58-b660-466e-929b-5048acd1d0d2 - root - INFO - unique_id 0dab1f58-b660-466e-929b-5048acd1d0d2 progress time 5.001380920410156
2024-06-28 11:28:56,981 - 5ad2bcba-b7dc-42fe-b8b4-37c49d82063b - root - INFO - unique_id 5ad2bcba-b7dc-42fe-b8b4-37c49d82063b progress time 6.000994682312012
2024-06-28 11:28:56,984 - a20dd350-d5a4-40ca-bcd9-e2ddbd5c2347 - root - INFO - unique_id a20dd350-d5a4-40ca-bcd9-e2ddbd5c2347 progress time 6.001128673553467
2024-06-28 11:28:57,968 - a5b9f9bf-ee66-4fd4-b214-5f41ebd2a8bc - root - INFO - unique_id a5b9f9bf-ee66-4fd4-b214-5f41ebd2a8bc progress time 7.003313779830933
2024-06-28 11:28:57,972 - fca657f0-4cdf-43e6-b0d6-8d7a664f459a - root - INFO - unique_id fca657f0-4cdf-43e6-b0d6-8d7a664f459a progress time 7.000568628311157
2024-06-28 11:28:57,976 - 8c07e01b-759a-4b97-a974-ef1bef6515a8 - root - INFO - unique_id 8c07e01b-759a-4b97-a974-ef1bef6515a8 progress time 7.000383138656616
2024-06-28 11:28:57,983 - 98abd862-af54-4019-9495-087b14b11d8b - root - INFO - unique_id 98abd862-af54-4019-9495-087b14b11d8b progress time 7.001266717910767
2024-06-28 11:28:58,975 - 8dc07f24-933f-4f90-bbee-362aed360db2 - root - INFO - unique_id 8dc07f24-933f-4f90-bbee-362aed360db2 progress time 8.001611709594727
2024-06-28 11:28:58,977 - 5dff95b0-76b9-4419-870a-e09efe945768 - root - INFO - unique_id 5dff95b0-76b9-4419-870a-e09efe945768 progress time 8.00078010559082
2024-06-28 11:28:58,986 - 019b2a6b-1297-49cb-be5f-b64aba7929f7 - root - INFO - unique_id 019b2a6b-1297-49cb-be5f-b64aba7929f7 progress time 8.001692533493042
2024-06-28 11:28:58,987 - 25b3e2a3-3138-4989-9392-f730e26fa408 - root - INFO - unique_id 25b3e2a3-3138-4989-9392-f730e26fa408 progress time 8.001523494720459
2024-06-28 11:28:59,979 - 284f465b-a967-4a7d-85f7-ae26e83aee94 - root - INFO - unique_id 284f465b-a967-4a7d-85f7-ae26e83aee94 progress time 9.00178861618042
2024-06-28 11:29:00,969 - 6957301f-4cf5-455e-873a-d6bda54e2353 - root - INFO - unique_id 6957301f-4cf5-455e-873a-d6bda54e2353 progress time 10.000974416732788

检查ID与处理时间，全部符合

[[replyMessage== null?"发表评论":"发表评论 @ " + replyMessage.m_author]]

account_circle
email
web_asset
textsms

评论列表([[messageResponse.total]])

还没有可以显示的留言...
gravatar
[[messageItem.m_author]] [[messageItem.m_author]]
[[messageItem.create_time]]
[[getEnviron(messageItem.m_environ)]]
[[subMessage.m_author]] [[subMessage.m_author]] @ [[subMessage.parent_message.m_author]] [[subMessage.parent_message.m_author]]
[[subMessage.create_time]]
[[getEnviron(messageItem.m_environ)]]