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

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

(资料图片仅供参考)

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

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

安装FastAPI和Loguru

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

pip install fastapipip install loguru

创建FastAPI应用程序

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

import uvicornfrom fastapi import FastAPIfrom loguru import loggerapp = 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)

tipsuvicorn.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语句的执行流程如下：

执行 expression.__enter__()方法，获取上下文管理器对象。如果指定了 as variable，将 __enter__()方法的返回值赋值给该变量。执行 with-block中的代码。如果 with-block中的代码执行过程中抛出异常，则执行 expression.__exit__(exc_type, exc_value, traceback)方法，释放资源。如果 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 uvicornimport uuidfrom fastapi import FastAPIfrom loguru import loggerfrom starlette.responses import JSONResponseapp = 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 started2023-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 started2023-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，并在日志记录中使用它。

代码解释：

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

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

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

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

总结

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