作者:Chancel Yang, 创建:2024-06-27, 字数:7482, 已阅:325, 最后更新:2024-06-27
使用 FastAPI 开发 Web 应用,在并发高的时候进行logging的日志跟踪非常困难
如果可以实现一个日志类似于:
"%(asctime)s - %(unique_id)s - %(name)s - %(levelname)s - %(message)s"
其中 unique_id
由请求入口处生成
这样在日志跟踪中只要搜索 unique_id
的值就可以跟踪完一次请求的内容,非常方便
代码实现如下:
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)
代码说明:
str(uuid.uuid4())
来生成一个唯一请求的ID,并在请求结束后将请求的唯一ID放入 headers
方便与调用者确认请求IDContextVar
和 logging.Filter
子类来实现每一次日志输出时检查上下文并提取 unique_id
打印到日志中request.state.random_int
随机数,在 index
路由中休眠线程模拟业务 1-10 秒测试一下 20 个并发,然后查看日志是否每个请求ID的处理时间与休眠时间对的上:
siege -c 20 -r 1 http://127.0.0.1:8000
日志输出如下
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与处理时间,全部符合