【Python】如何在FastAPI中使用UUID标记日志，以跟踪一个请求的完整生命周期

为什么要使用uuid标记日志？

在分布式系统中，一个请求可能会经过多个服务，每个服务都会生成自己的日志。如果我们只使用普通的日志记录，那么很难将这些日志串联在一起，以至难以跟踪一个请求的完整生命周期。

如果能够使用uuid标记日志，为每个请求生成一个唯一的uuid，且这个日志可以在不同的系统间传递，就可以解决这个问题。

FastAPI和Loguru是两个非常流行的Python库。FastAPI是一个现代的Web框架，具有高性能和易于使用的特点。Loguru是一个灵活的日志记录库，具有简单、易用和强大的特点。在这篇文章中，我们将介绍如何使用FastAPI和Loguru进行日志记录，并使用同一个uuid标记来标记每个请求的日志链路。

安装FastAPI和Loguru

首先，我们需要安装FastAPI和Loguru。可以使用pip命令来安装它们：

pip install fastapi
pip install loguru

创建FastAPI应用程序

接下来，我们需要创建一个FastAPI应用程序。在这个例子中，我们将创建一个简单的应用程序，它对外提供一个根路径访问，我们在根路径被访问时会记录日志，并且会调用hello函数，hello函数自身也添加了日志记录。

import uvicorn
from fastapi import FastAPI
from loguru import logger

app = FastAPI()

logger.add("log.log")


@app.get("/{name}")
async def root(name):
    logger.info("Hello from the root path")
    hello()
    return {"message": f"Hello {name}"}


def hello():
    logger.info("hello() called!")


if __name__ == '__main__':
    uvicorn.run("main:app", port=10001, reload=True)

tips uvicorn.run("main:app", port=10001, reload=True) 中的 main 表示执行 main.py 文件中的 app

服务启动后，如果我们访问 http://localhost:10001/Bingo，会收到响应 {"message":"Hello Bingo"}, log.log文件中会记录

2023-06-01 21:24:13.471 | INFO     | main:root:19 - Root path is Visited!
2023-06-01 21:24:13.472 | INFO     | main:hello:26 - hello() called!
2023-06-01 21:24:13.472 | INFO     | main:root:21 - Bingo Visited!

添加uuid标记

上面的三条日志虽然都是因为 我们访问一个地址产生的，但是他们之间除了时间，没有其他的管理；如果同一时间有多个请求，我们就难以跟踪随调用了 hello()做了什么 ，那么如何才能将他们关联起来呢？

这需要用到 with 上下文管理函数 和** FastAPI中间件** 的概念。

with 上下文管理函数

with 是 Python 中的一个上下文管理器，它可以在代码块执行完毕后自动释放资源，避免资源泄漏等问题，提高代码的可读性和可维护性。
with 语句的语法如下：

with expression [as variable]:
    with-block

其中，expression 是一个上下文管理器对象，可以是一个函数或一个类，必须实现 __enter__ 和 __exit__ 方法。as variable 是可选的，用来指定一个变量名，将 expression.__enter__() 方法的返回值赋值给该变量。with-block 是一个代码块，用来执行需要被管理的代码。

with 语句的执行流程如下：

1. 执行 expression.__enter__() 方法，获取上下文管理器对象。
2. 如果指定了 as variable，将 __enter__() 方法的返回值赋值给该变量。
3. 执行 with-block 中的代码。
4. 如果 with-block 中的代码执行过程中抛出异常，则执行 expression.__exit__(exc_type, exc_value, traceback) 方法，释放资源。
5. 如果 with-block 中的代码执行完毕，则执行 expression.__exit__(None, None, None) 方法，释放资源。

with 语句可以用来管理文件、网络连接、锁等资源，例如：

with open('file.txt', 'r') as f:
    content = f.read()
    print(content)

上述代码使用 with 语句来管理文件资源，当代码块执行完毕后，会自动关闭文件句柄，释放资源。

FastAPI中间件

FastAPI中间件是一种机制，允许我们在请求到达应用程序之前或之后执行一些操作。它们可以用于添加请求头、验证身份、记录日志等。在FastAPI中，中间件是使用装饰器实现的。我们可以使用@app.middleware()装饰器来定义中间件。中间件函数接收一个Request对象和一个call_next函数作为参数。它可以在请求到达应用程序之前或之后执行一些操作，并调用call_next函数来继续处理请求。

代码实现

改造后的代码如下：

import uvicorn
import uuid
from fastapi import FastAPI
from loguru import logger
from starlette.responses import JSONResponse

app = FastAPI()

logger.add(
    "log.log",
    format="{time:YYYY-MM-DD HH:mm:ss.ms} [{extra[request_id]}] | {level} | {module}.{function}:{line} : {message}"
)


@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("/{name}")
async def root(name):
    logger.info("Root path is Visited!")
    hello()
    logger.info(f"{name} Visited!")
    return {"message": f"Hello {name}"}


def hello():
    logger.info("hello() called!")


if __name__ == '__main__':
    uvicorn.run("main:app", port=10001, reload=True)

当我们再次访问 http://localhost:10001/Bingo，收到的响应 {"message":"Hello Bingo"}不会有变化, 但是log.log文件中会记录：

2023-06-01 21:35:55.3555 [b61c693f-97c0-4c84-9f44-3b855bea2568] | INFO | main.request_middleware:29 : Request started
2023-06-01 21:35:55.3555 [b61c693f-97c0-4c84-9f44-3b855bea2568] | INFO | main.root:43 : Root path is Visited!
2023-06-01 21:35:55.3555 [b61c693f-97c0-4c84-9f44-3b855bea2568] | INFO | main.hello:50 : hello() called!
2023-06-01 21:35:55.3555 [b61c693f-97c0-4c84-9f44-3b855bea2568] | INFO | main.root:45 : Bingo Visited!
2023-06-01 21:35:55.3555 [b61c693f-97c0-4c84-9f44-3b855bea2568] | INFO | main.request_middleware:38 : Request ended

再次请求时，uuid 会发生变化:

2023-06-01 21:35:55.3555 [b0e02e34-51ee-4cbb-838b-8222ec8f0483] | INFO | main.request_middleware:29 : Request started
2023-06-01 21:35:55.3555 [b0e02e34-51ee-4cbb-838b-8222ec8f0483] | INFO | main.root:43 : Root path is Visited!
2023-06-01 21:35:55.3555 [b0e02e34-51ee-4cbb-838b-8222ec8f0483] | INFO | main.hello:50 : hello() called!
2023-06-01 21:35:55.3555 [b0e02e34-51ee-4cbb-838b-8222ec8f0483] | INFO | main.root:45 : Bingo Visited!
2023-06-01 21:35:55.3555 [b0e02e34-51ee-4cbb-838b-8222ec8f0483] | INFO | main.request_middleware:38 : Request ended

实现原理是我们在每个请求的状态中存储uuid，并在日志记录中使用它。

代码解释：

1. @app.middleware("http") 表示注册一个 HTTP 中间件，用于处理 HTTP 请求。
2. request 是一个请求对象，call_next 是一个回调函数，用于调用下一个中间件或路由处理函数。
3. uuid.uuid4() 生成一个唯一的请求 ID，用于在日志中标识该请求。
4. logger.contextualize(request_id=request_id) 用于在日志中添加请求 ID 上下文。
5. logger.info("Request started") 记录请求开始的日志信息。
6. await call_next(request) 调用下一个中间件或路由处理函数，并返回响应对象。
7. logger.error(f"Request failed: {ex}") 记录请求失败的日志信息，其中 ex 是捕获到的异常对象。
8. JSONResponse(content={"success": False}, status_code=500) 返回一个 HTTP 500 错误响应，表示请求处理失败。
9. logger.info("Request ended") 记录请求结束的日志信息。

这个中间件只用实现一次，对后续所有其他接口的开发没有任何的侵入，一劳永逸。

tips: 为什么使用uuid.uuid4()而不是uuid.uuid()？

uuid.uuid()生成的UUID是根据主机ID、序列号和当前时间生成的。这意味着在同一台计算机上生成的UUID可能会重复，尤其是在高负载情况下。为了避免这种情况，我们可以使用uuid.uuid4()生成随机UUID。uuid.uuid4()生成的UUID是完全随机的，几乎不可能重复。因此，它是生成唯一标识符的最佳选择。

总结

在这个例子中，我们使用FastAPI和Loguru进行了日志记录，并使用同一个uuid标记来标记每个请求的日志链路。这使得我们能够轻松地跟踪每个请求的日志，并识别它们的来源，如果上游也使用了这样方式记录日志， 那做到跟踪一个请求的完整生命周期就不难办到了。