基于python装饰器和logging模块实现清晰便于追踪的接口日志

爱吃肉的鱼
5,565 阅读14分钟

1． 序言

大家好，我爱吃肉的鱼🐠 *^_^*🍃，最近好像写博客比较频繁，其实主要是想对以前在工作中遇到的一些问题进行归纳总结，养成一个良好的习惯，希望自己能在归纳总结的过程中积累更丰富的经验，增强自己的技术实力，同时也希望能对后续遇到过类似问题的伙伴提供一些参考和帮助。

我目前在腾讯云主要从事的Web项目类的开发工作，Python Web、Java Web居多。B端服务主要基于python Flask框架开发，uwsgi进行部署，之所以选择python主要是python开发效率高、迭代快，并且考虑的B端的服务通常并发访问量不会特别大，对性能要求不会那么高（其实我个人不太喜欢用flask，平常我自己做些网站后端等开发时，我更喜欢FastApi(fastapi.tiangolo.com/)。相比起Flask和… Cloud微服务。

好了，简介到此为止，让我们言归正传！今天想要介绍的主题是如何为后端web接口生成清晰明了、便于查错追踪的日志。日志对应后端开发的重要性我想应该不用我说了吧，主要用于追踪记录当前程序的执行路径、记录一些重要的提示或错误信息，方便我们快速定位系统问题，一个良好的日志输出通常能在极大程度上帮助我们解决问题。下面主要分享下自己开发中对接口日志处理的一下相关总结，主要基于Python介绍，其他任何语言Web框架都是类似的。

2． 如何实现清晰可追踪的接口日志

2.1 统一日志格式，打印接口入参及响应

在每个接口开始时，打印接口开始标志及接口参数。其目的是为了方便我们知道哪个接口被调用了，以及调用该接口时的请求参数是什么，并且可以让我们根据请求参数去预估应有的响应，或者当响应不符合预期时，可以很方便到检查其请求参数是否正确。

如何做到上一点，当然不需要在每个接口开始和结尾处都加一段日志打印操作，通过装饰器很容易实现以上功能（如果是Java，使用切面、注解的方式一样很容易实现）。实现上述功能的python装饰器代码可如下（decorators.py）:

def log_filter(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        start = 1000 * time.time()
        logger.info(f"=============  Begin: {func.__name__}  =============")
        logger.info(f"Args: {kwargs}")
        try:
            rsp = func(*args, **kwargs)
            logger.info(f"Response: {rsp}")
            end = 1000 * time.time()
            logger.info(f"Time consuming: {end - start}ms")
            logger.info(f"=============   End: {func.__name__}   =============\n")
            return rsp
        except Exception as e:
            logger.error(repr(e))
            raise e
    return wrapper

在需要的接口上加上@log_filter装饰器就可以了。这里还顺便打印了接口的执行时间，可以方便我们找到响应比较慢的接口并针对其进行性能调优。

假如在common_hanlder.py里有如下一个接口, 当我们浏览器访问GET /test?name=Tom时，其日志输入格式应如图1所示:

@router.get("/test")
@log_filter
def test(name: str):
    logger.debug(f"Hello {name}, welcome!")
    time.sleep(2)
    logger.info("goodbye!")
    return {"ret_code": 0, "ret_msg": "success", "ret_data": {"name": name}}

注: 这里使用的logger为python自带的logging模块的logger，输出日志格式为：%(asctime)s %(filename)s[line:%(lineno)d] - %(levelname)s: %(message)s，即打印当前时间、logger被调用文件及对应代码行数、日志级别、日志内容

图1

2.2 为每个请求增加唯一请求id，便于追踪请求日志

通过上面我们已经可以清楚的看到每个接口的入口，接口参数、内部逻辑日志、接口响应、接口耗时，并且知道每一行日志数据的文件以及位置。但是这是在单个请求的情况下，请求的日志都输出在一起，看起来还比较清晰，如果是在并发请求的情况下，那么通常会出现不同请求日志纵横交错的情况（如图2），这样看日志便无法判断哪个日志是哪个请求产生的。

图2

为此，常用的做法便是为每个请求生成一个唯一的request id，然后在打印日志的时候把request id也打印出来，这样边可以根据request id追踪请求执行路径，同时也可以将request id在响应中返回个调用方，这样当调用方收到错误应答时可以根据响应中的request id快速定位错误日志。那么问题就在于如何为请求生成唯一request id以及如何在日志中打印request id？

如何生成唯一request id?

生成唯一id的方法有很多，这里不打算介绍，可以参考这篇文章，这里更重要的是要保证在同一个请求中多次获取request id时id值始终是一样的，而且不同请求获取到的id不一样，也就是说A请求的id不会被B请求获取到或者修改。这可以通过ThreadLocal来实现，将生成的request id存放到全局ThreadLocal对象中，由于每个线程都会存一个ThreadLocal对象的副本，可以保证id在线程间的隔离性，同时同一个请求处理线程内都可以通过全局ThreadLocal对象获取当前线程的request id。

当然，python之所以开发快是因为很多功能大多数情况下没必要自己去实现，python中有很多开源的实现方案可以使用，如asgi_request_id, 这个是针对异步服务器（如uvicorn、starlette）的request id实现方案，同步服务器（如uwsgi）可以使用request-id, 或者一些web框架自带的请求id实现方案，如Flask的flask-request-id, Django的django-request-id。这里我们使用的是asgi_request_id，使用示例如下:

# 引入request_id包
from asgi_request_id import RequestIDMiddleware, get_request_id

app = FastAPI(title="RequestId示例")

# 为每个请求分配一个request id
app.add_middleware(
    RequestIDMiddleware,
    incoming_request_id_header="request_id",
)

@router.get("/test")
@log_filter
def test(name: str):
    # 获取当前request id
    logger.info(f"current request_id: {get_request_id()}"")
    
    logger.debug(f"Hello {name}, welcome!")
    time.sleep(2)
    logger.info("goodbye!")
    return {"ret_code": 0, "ret_msg": "success", "ret_data": {"name": name}}
  • 首先引入相关依赖包，创建当前应用对象
  • 为当前应用对象app添加RequestIDMiddleware，这里Middleware相当于Java Web里面的Filter，用于对请求进行过滤，所有的请求都会先经过这里，再达到具体的请求handler。这里RequestIDMiddleware的作用就是为所有到达服务器的请求分配一个唯一的request id，并将它存放到一个全局的ThreadLocal对象中，然后在整个请求处理过程中，都可以通过get_request_id()方法从ThreadLocal对象中获取到当前的request id。最后点请求处理结束时，RequestIDMiddleware还会将当前的request id放到响应header中返回到客户端，方便错误定位。
  • 获取打印当前request id

如何将request id打印到日志？

获取到request id还不够，还需要将它打印到日志才行。最直接也是最笨的办法当然是每次打log时，手动将request id作为要打印日志消息的一部分输出（日志打印效果如图3），如下：

@router.get("/test")
@log_filter
def test(name: str):
    logger.debug(f"request_id={get_request_id()} log_msg=Hello {name}, welcome!")
    time.sleep(2)
    logger.info("request_id={get_request_id()} log_msg=goodbye!")
    return {"ret_code": 0, "ret_msg": "success", "ret_data": {"name": name}}

图3

虽然这样做可以达到目的，但显然不是一个可观的做法，太麻烦，至少我是不愿因每次打日志还重复的去手工加一段相同的内容。那么有没有什么办法可以像日志前面的日期、文件名、代码行数这样默认打印而不用每次手动打印的呢？我们知道这部分字段内容实际上就是通过logging.Formatter来指定的，如前面的Formatter字符串"%(asctime)s %(filename)s[line:%(lineno)d] - %(levelname)s: %(message)s"就是指定日志的打印时间、文件名、代码行数、日志级别以及要打印的日志消息，而且这里的字段名称asctime、filename、lineno、levelname、message这些变量名称并不是可以随便指定的，logging模块在打印每行日志时会把这些变量的值传进去一起打印。

基于这个思路，那是不是可以在Formatter字符串中指定request_id(如: "%(asctime)s %(request_id)s %(filename)s[line:%(lineno)d] - %(levelname)s: %(message)s")，然后在打印日志时自动把request_id的值填充进去就行呢？request-id和django-request-id本质上就是通过这种方式实现的，需要为logger配置一个filter，这个filter会在打印日志时把request_id插入到每条日志中，两者具体用法会有些，可以参考下相关文档介绍。

但是这里我们使用的asgi_request_id好像没有提供类似的配置，因此我就琢磨着自己实现一个通用的通用方案。于是就从logger.info开始将python logging模块打印日志的处理流程大致看了一遍，发现python logger生成日志记录的方法(logging/__init__.py文件的makeRecord方法)实际上是支持在日志记录中添加额外字段的。

logging/__init__.py:

    def makeRecord(self, name, level, fn, lno, msg, args, exc_info,
                   func=None, extra=None, sinfo=None):
        """
        A factory method which can be overridden in subclasses to create
        specialized LogRecords.
        """
        rv = _logRecordFactory(name, level, fn, lno, msg, args, exc_info, func,
                             sinfo)
        if extra is not None:
            for key in extra:
                if (key in ["message", "asctime"]) or (key in rv.__dict__):
                    raise KeyError("Attempt to overwrite %r in LogRecord" % key)
                rv.__dict__[key] = extra[key]
        return rv

从makeRecord的实现可以看出，在生成记录的时候会把extra这个参数中各个字段的内容添加到最终生成的日志记录rv中，但是extra中的字段名不能与默认的字段名(即Formatter字符串中的asctime、filename、lineno等)重复，否则会抛出KeyError错误。基于此，我们可以封装默认logger实现，在打印日志时将request_id存入extra中进行打印，实现如下:

import logging
from functools import wraps
from asgi_request_id import get_request_id

class MyLogger:
    def process(func):
        """
        自定义日志处理, 往日志中输出额外参数字段(这里为request id)
        """
        @wraps(func)
        def wrapper(self, msg, *args, **kwargs):
            kwargs["extra"] = {
                # 当前请求id
                "request_id": get_request_id(),
            }
            func(self, msg, *args, **kwargs)
        return wrapper

    def __init__(self, name):
        self.logger = logging.getLogger(name)

    def setLevel(self, log_level):
        self.logger.setLevel(log_level)

    def addHandler(self, handler):
        self.logger.addHandler(handler)

    @process
    def debug(self, msg, *args, **kwargs):
        self.logger.debug(msg, *args, **kwargs)

    @process
    def info(self, msg, *args, **kwargs):
        self.logger.info(msg, *args, **kwargs)

    @process
    def warn(self, msg, *args, **kwargs):
        self.logger.warn(msg, *args, **kwargs)

    @process
    def error(self, msg, *args, **kwargs):
        self.logger.error(msg, *args, **kwargs)

思路其实很简单，就是封装python logging的logger，本质还是通过logging模块去打印日志，只是在打印日志是通过process装饰器往extra添加了当前的request id(字段名为: request_id)，前面已经说了，这个extra中的字段是可以在Formatter字符串中指定打印的，因此可以配置如下:

"%(asctime)s %(request_id)s %(filename)s[line:%(lineno)d] - %(levelname)s: %(message)s"

这样，我们便可以像使用logging.logger一模一样的方式来使用MyLogger:

# 设置打印字段格式
formatter = logging.Formatter("%(asctime)s %(request_id)s %(filename)s[line:%(lineno)d] - %(levelname)s: %(message)s")

# 创建MyLogger对象
logger = MyLogger("My Logger")
logger.setLevel(logging.DEBUG)

# 创建logger handler
fh = TimedRotatingFileHandler(filename=app_log_path, when='midnight', backupCount=30)
fh.setLevel(logging.DEBUG)
fh.setFormatter(formatter)
logger.addHandler(fh)

对于刚才的test接口，日志打印格式如图4：

图4

可以看到request id已经按照我们想要的方式打印出来（如红框所示），但是却出了个问题（如蓝框所示），打印日志的文件名全都成了__init__.py(这个是MyLogger定义的模块文件名)，这是因为python logging.logger打印的文件名及代码行数是它自身被调用的文件名和代码行数，显然我们是希望打印MyLogger的debug、info、error等方法被调用的文件名和代码行数。这就涉及到如何获取调用方信息。

如何获取调用方信息?

在操作系统里面，程序方法（函数）的调用是通过栈这种数据结构来实现的，每调用一个方法实际就是往方法栈中新增一个栈帧，栈帧中会存放该方法的参数、返回地址、局部变量等基本信息。注意这里的"返回地址"实际上就是上一个方法（上一帧）调用当前方法（当前帧）的地址，也就是我们想要获取的调用方信息。python中可以通过以下方式获取方法调用栈信息:

import inspect

inspect.stack()

inspect.stack()获取的是整个调用栈的列表，列表元素是个tuple类型的FrameInfo，表示栈帧信息。如果在MyLogger.info中将其打印出来如下图5所示：

图5:

方法栈信息

栈顶（第一帧）为当前方法帧，第二帧即为其调用方法所在栈帧，因此调用方帧可以表示为inspect.stack()[1]。再观察FrameInfo结果，元组第2个元素即为该栈帧所在模块文件路径名，第3个元素即为该栈帧所处的代码行数。因此，我们要获取调用方的文件名和代码行数可以表示为: 
import inspect

# 获取调用方所在栈帧(第2帧，数组下标为1)
frame = inspect.stack()[1]

# 获取调用方所文件名，这里只取文件名，不带路径
file_name = os.path.basename(frame[1])

# 获取代码行数
file_no = frame[2]

OK, 现在已经成功获取到调用方信息了，剩下就是打印到日志即可，处理方式和上面打印request id的方式一致，在extra中添加字段值，然后在Formatter字符串指定要打印的字段名就行，修改实现如下:

class MyLogger:
    def process(func):
        """
        自定义日志处理, 往日志中输出额外参数字段(这里为request id)
        """
        @wraps(func)
        def wrapper(self, msg, *args, **kwargs):
            # 获取调用方所在栈帧(第2帧，数组下标为1)
            frame = inspect.stack()[1]

            # 获取调用方所文件名，这里只取文件名，不带路径
            file_name = os.path.basename(frame[1])

            # 获取代码行数
            file_no = frame[2]

            kwargs["extra"] = {
                # 当前请求id
                "request_id": get_request_id(),
                # 获取调用方模块文件名
                "file_name": file_name,  
                # 获取被调用方法被调用时所处代码行数
                "file_no": file_no
            }
            func(self, msg, *args, **kwargs)
        return wrapper

    def __init__(self, name):
        self.logger = logging.getLogger(name)

    def setLevel(self, log_level):
        self.logger.setLevel(log_level)

    def addHandler(self, handler):
        self.logger.addHandler(handler)

    @process
    def debug(self, msg, *args, **kwargs):
        self.logger.debug(msg, *args, **kwargs)

    @process
    def info(self, msg, *args, **kwargs):
        self.logger.info(msg, *args, **kwargs)

    @process
    def warn(self, msg, *args, **kwargs):
        self.logger.warn(msg, *args, **kwargs)

    @process
    def error(self, msg, *args, **kwargs):
        self.logger.error(msg, *args, **kwargs)

在Formatter字符串配置如下:

"%(asctime)s %(request_id)s %(file_name)s[line:%(file_no)d] - %(levelname)s: %(message)s"

注意这里文件名和代码行数对应的字段要换为extra参数中对应file_name、file_no字段名。最终打印效果如6所示:

图6

大功告成。yeah！

3． 总结

本文主要介绍了如何打印清晰、美观、以及便于追踪查询的接口日志，并基于python logging模块封装实现了自定义的Logger类，其使用方式和使用logging.Logger完全一致，并支持在日志格式化规则字符串中新增打印request id（当然，新增其它任何需要打印的字段信息都可以采用这种方式实现）。功能看似挺简单，真正动手去做发现还是有很对东西需要深入理解，比如需要看源码了解logging模块打印日志的实现，寻找新增默认打印字段信息的方式，其后又涉及如何获取方法调用方信息，需要对方法调用栈的理解等。任何一个小功能都不应被轻视，勤动脑、勤动手、深入挖掘才能实现自我提升！

avatar
文章
阅读
粉丝