为什么要使用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 语句的执行流程如下：
- 执行
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 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，并在日志记录中使用它。
代码解释：
-
@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标记来标记每个请求的日志链路。这使得我们能够轻松地跟踪每个请求的日志，并识别它们的来源，如果上游也使用了这样方式记录日志， 那做到跟踪一个请求的完整生命周期就不难办到了。
服务器托管，北京服务器托管，服务器租用 http://www.fwqtg.net
机房租用，北京机房租用，IDC机房托管， http://www.fwqtg.net
