一、引言
在项目开发中，日志记录是必不可少的工具，帮助我们排查问题、监控系统状态。然而，在处理并发请求时，日志信息常常显得杂乱无章，尤其是在分布式服务系统中，各节点的日志分散在不同位置，缺乏完整的日志链路，导致查询和分析日志信息变得异常繁琐。
为了解决这一问题，本文将通过 FastAPI 对请求日志链路追踪进行封装和讲解，旨在提供一种清晰的日志追踪方案。
二、目标与方案
目标：实现能够快速查询同一请求下的所有日志信息的能力，简化问题排查。
方案：在 Web 中间件中为每个请求生成一个唯一的链路标识，在记录日志时带上该标识，从而形成贯穿请求全过程的日志链路。
三、具体实现
请求链路追踪中间件
首先设计请求链路的中间件生成唯一的链路标识，这里通过 uuid 来标识。
class TraceReqMiddleware(BaseHTTPMiddleware):
async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) -> Response:
# 设置请求id
request_id = uuid.uuid4().hex
request.state.request_id = request_id # 记录请求id
response = await call_next(request) # 执行请求获取响应
response.headers["X-Request-ID"] = f"{request_id}" # 响应头中记录请求id
return response
路由函数处理
router.add_api_route(
"/ping",
endpoint=HeartBeatController.heart,
methods=["get"],
response_model=SuccessRespModel,
summary="心跳",
)
class HeartBeatController:
@classmethod
async def heart_handler(cls, request: Request):
"""模拟业务处理函数"""
logger.info(f"{request.state.request_id} | heart_handler")
return SuccessRespModel()
@classmethod
async def heart(cls, request: Request):
"""心跳接口"""
logger.info(f"{request.state.request_id} | ping request_id test")
resp = await cls.heart_handler(request)
return resp
日志记录效果如下
这样就简单实现了，但还是不方便记录。问题如下
-
首先把生成的
request_id放入request对象的state中，要在路由函数中放置Request对象参数进行访问请求对象，进行业务函数处理时又要一直传递request对象，函数设计的时候会有点不灵活。 -
日志记录信息每次都要自己拼接 request_id
contextvars 配置
为了解决上面的 request 对象一直传递问题，可以采用 python 内置的 contextvars 模块进行请求上下文配置。
#!/usr/bin/python3
# -*- coding: utf-8 -*-
# @Author: Hui
# @Desc: { 上下文模块描述 }
# @File: context_util.py
# @Date: 2023/10/30 15:11
import contextvars
from typing import Union
from fastapi import Request
# 请求对象上下文
REQUEST_CTX: contextvars.ContextVar[Union[Request, None]] = contextvars.ContextVar("request", default=None)
# 请求唯一id
REQUEST_ID: contextvars.ContextVar[str] = contextvars.ContextVar("request_id", default="")
# 任务追踪唯一id
TRACE_ID: contextvars.ContextVar[str] = contextvars.ContextVar("trace_id", default="")
contextvars.ContextVar 是 Python 3.7 引入的一个类，用于处理上下文变量，可以在线程或异步任务之间保持隔离的状态。它特别适合在异步代码中存储和共享变量的状态，而不影响其他上下文。这在需要管理多个并发任务时非常有用，比如在 Web 应用程序中为每个请求设置唯一的 request_id 和 trace_id。
上下文变量的核心特点在于它们在每个任务、线程、或异步上下文中都是隔离的，因此同一个上下文变量在不同的任务之间不会互相干扰。
具体细节请看 Python 官方文档contextvars
使用 contextvars 简单封装 TraceUtil
#!/usr/bin/python3
# -*- coding: utf-8 -*-
# @Author: Hui
# @Desc: { 日志链路追踪工具模块 }
# @File: trace_util.py
# @Date: 2023/10/30 15:51
import uuid
from src.utils import context_util
class TraceUtil(object):
@staticmethod
def set_req_id(req_id: str = None, title="req-id") -> str:
"""
设置请求唯一ID
Args:
req_id: 请求ID 默认None取uuid
title: 标题 默认req-id
Returns:
title:req_id
"""
req_id = req_id or uuid.uuid4().hex
req_id = f"{title}:{req_id}"
context_util.REQUEST_ID.set(req_id)
return req_id
@staticmethod
def set_trace_id(trace_id: str = None, title="trace-id") -> str:
"""
设置追踪ID, 可用于一些脚本等场景进行链路追踪
Args:
trace_id: 追踪唯一ID 默认None取uuid
title: 标题 默认 trace-id, 可以用于标识业务
Returns:
title:trace_id
"""
trace_id = trace_id or uuid.uuid4().hex
trace_id = f"{title}:{trace_id}"
context_util.TRACE_ID.set(trace_id)
return trace_id
@staticmethod
def get_req_id() -> str:
return context_util.REQUEST_ID.get()
@staticmethod
def get_trace_id() -> str:
return context_util.TRACE_ID.get()
这里主要就是把生成的链路标识存储到 contextvars 中，以及从中获取设置的数据。
改造中间件路由处理函数
class TraceReqMiddleware(BaseHTTPMiddleware):
async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) -> Response:
# 设置请求id
request_id = TraceUtil.set_req_id()
response = await call_next(request)
response.headers["X-Request-ID"] = f"{request_id}" # 记录同一个请求的唯一id
return response
这次可以不用传递 request 参数了，通过上下文环境变量获取，效果是一样的。
接下来就是解决日志记录的问题了。
日志器配置追踪参数
解决记录日志信息每次手动拼接链路标识，这里采用的 loguru 的日志器的 filter 参数来实现
loguru 具体使用细节可以查看：精简日志管理：Loguru 配置与封装详解
#!/usr/bin/python3
# -*- coding: utf-8 -*-
# @Author: Hui
# @Desc: { 日志配置模块 }
# @Date: 2023/09/07 16:46
# @File: log_setting.py
import logging
import os
import sys
# 项目基准路径
base_dir = os.path.dirname(os.path.dirname(os.path.dirname(os.path.abspath(__file__))))
# 项目日志目录
logging_dir = os.path.join(base_dir, "logs/")
# 项目运行时所有的日志文件
server_log_file = os.path.join(logging_dir, "server.log")
# 项目日志配置
console_log_level = logging.DEBUG
log_format = "{time:YYYY-MM-DD HH:mm:ss.SSS} | {level:<8} | {trace_msg} | {name}:{function}:{line} - {message}"
这里主要的就是 log_format 设置了 trace_msg 参数，这个后面要动态填充链路标识。
设置日志信息过滤器 filter
#!/usr/bin/python3
# -*- coding: utf-8 -*-
# @Author: Hui
# @Desc: { 日志工具模块 }
# @Date: 2023/09/07 17:01
# @File: log_util.py
from py_tools.logging import setup_logging
from src.settings import log_setting
from src.utils import context_util
def _logger_filter(record):
"""日志过滤器补充request_id或trace_id"""
req_id = TraceUtil.get_req_id()
trace_id = TraceUtil.get_trace_id()
trace_msg = f"{req_id} | {trace_id}"
record["trace_msg"] = trace_msg
return record
def setup_logger():
"""配置项目日志信息"""
setup_logging(
log_dir=log_setting.logging_dir,
log_filter=_logger_filter,
log_format=log_setting.log_format,
console_log_level=log_setting.console_log_level,
)
_logger_filter 作用就是把每一条日志信息都动态填充 req_id 或 trace_id （链路标识），有了 req_id 为什么还要有 trace_id 呢？其实就是不是通过请求访问时，例如程序启动、脚本等都可以单独设置 trace_id 来进行标识。
具体使用如下 fastapi 应用服务启动
from contextlib import asynccontextmanager
from fastapi import FastAPI
from py_tools.logging import logger
from src.controllers.common.error_handler import register_exception_handler
from src.middlewares import register_middlewares
from src.routers import api_router
from src.utils import TraceUtil, log_util
@asynccontextmanager
async def lifespan(app: FastAPI):
await startup()
yield
await shutdown()
app = FastAPI(
description="任务管理系统",
lifespan=lifespan,
middleware=register_middlewares(), # 注册web中间件
exception_handlers=register_exception_handler(), # 注册web错误处理
)
async def init_setup():
"""初始化项目配置"""
# 配置日志
log_util.setup_logger()
# await dao.init_orm()
# await dao.init_redis()
async def startup():
"""项目启动时准备环境"""
TraceUtil.set_trace_id(title="app-server")
await init_setup()
# 加载路由
app.include_router(api_router)
logger.info("fastapi startup success")
async def shutdown():
logger.error("app shutdown")
这里 TraceUtil.set_trace_id(title="app-server") 在项目启动的时候设置了一个 trace_id 用来记录服务的启动与结束信息。
测试效果
当处理高并发请求时就会出现日志信息打印不是一条链路的，我们排查业务日志可以
-
先通过日志信息定位请求链路标识
-
然后通过链路标识（req_id、trace_id）查询整个个链路上下文信息
-
最后通过日志链路信息排查问题
例如查询 "user 1 ping" 的相关日志
tail -n 100 -f logs/server.log | grep "user 1 ping"
然后根据链路标识查看完整的日志上下文
tail -n 100 -f logs/server.log | grep "ae2a8f229c99459d834629aa7b47193b"
这样链路就清晰多了，这里就是举了一个简单例子，实际项目中使用需要灵活变通，例如分布式服务、微服务中，需要再网关层面生成链路标识然后放到请求头中然后将请求头透传到各个服务，各个服务调用也是这样，d但服务的中间件要改成首先从请求头中获取链路标识没有再生成。
四、Github 源代码
详细代码可以查看 TaskFlow 项目
