测试平台系列(111) 利用loguru改造日志模块

这是我参与2022初次更文挑战的第26天，活动详情检查：2022初次更文挑战。

我们好~我是米洛！
我正在从0到1打造一个开源的接口测试渠道, 也在编写一套与之对应的教程，期望我们多多支撑。
欢迎重视我的大众号米洛的测开日记，获取最新文章教程!

回忆

上一节咱们聊了grpc相关的完成思路，但也只是提供了思路和对应的库，但读者们需求时刻消化，所以咱们来转换一下思想，来聊聊日志这块内容。

现有日志

虽然现有的日志现已足够咱们使用了，但随着时刻的推移，日志的切开，这些都得考虑进来，否则你将具有一个好几百MB的日志文件。考虑到企业内部许多都是基于es、cat等日志体系，logbook用起来就有点底气不足了。

其实也不算吧，首要是觉得loguru这玩意挺不错的，五颜六色的东西是我的最爱，我觉得比单调的操控台好不少。

虽然logbook差不多能满足我的需求，但我还是想研究下loguru。

loguru

github地址: github.com/Delgan/logu…

loguru是一款十分快捷的日志管理工具，里边自带了切开日志，五颜六色输出等一系列操作，但人家api相对比较友爱，不需求像logging那样装备许多许多内容，并且本身是线程安全/进程安全的（当然这是它自己说的）。下面咱们就来看一看它的基本用法，用一张官网的gif:

这个gif演示的demo十分丰富，有打印到操控台的，有输出到log文件的，还有日志分片和格式以及异常等内容，但是的确只写了极少量的代码。

老实说这也是我被他吸引到的地方，我也亲身体验了一下，感觉还不错。那咱们该如何进行改造呢？从哪里下手呢？

我会把本文分为2个内容，第一是替换fastapi自带的日志句柄，第二则是用到咱们自身的日志板块中。

替换fastapi默许的输出

在windows下，假如咱们不选用loguru，能够看到日志的输出大概是这样的:

十分朴实无华，和颜悦色。

再来看看改造后的效果:

多的不说，就一个时刻就现已很有作用了，有时分你不知道服务啥时分发动的，咱们就能够经过日志的时刻来判别。更何况这个日志输出如此美腻呢~

话不多说，甘蔗！

在app/__init__.py新增以下内容

class InterceptHandler(logging.Handler):
    """
    Default handler from examples in loguru documentaion.
    See https://loguru.readthedocs.io/en/stable/overview.html#entirely-compatible-with-standard-logging
    """
    def emit(self, record: logging.LogRecord):
        # Get corresponding Loguru level if it exists
        try:
            level = logger.level(record.levelname).name
        except ValueError:
            level = record.levelno
        # Find caller from where originated the logged message
        frame, depth = logging.currentframe(), 2
        while frame.f_code.co_filename == logging.__file__:
            frame = frame.f_back
            depth += 1
        logger.opt(depth=depth, exception=record.exc_info).log(
            level, record.getMessage()
        )
def format_record(record: dict) -> str:
    """
    这儿的代码是copy的，记载日志格式的
    Custom format for loguru loggers.
    Uses pformat for log any data like request/response body during debug.
    Works with logging if loguru handler it.
    Example:
    # >>> payload = [{"users":[{"name": "Nick", "age": 87, "is_active": True}, {"name": "Alex", "age": 27, "is_active": True}], "count": 2}]
    # >>> logger.bind(payload=).debug("users payload")
    # >>> [   {   'count': 2,
    # >>>         'users': [   {'age': 87, 'is_active': True, 'name': 'Nick'},
    # >>>                      {'age': 27, 'is_active': True, 'name': 'Alex'}]}]
    """
    format_string = LOGURU_FORMAT
    if record["extra"].get("payload") is not None:
        record["extra"]["payload"] = pformat(
            record["extra"]["payload"], indent=4, compact=True, width=88
        )
        format_string += "\n<level>{extra[payload]}</level>"
    format_string += "{exception}\n"
    return format_string
def make_filter(name):
    # 过滤操作，当日志要挑选对应的日志文件的时分，经过filter进行筛选
    def filter_(record):
        return record["extra"].get("name") == name
    return filter_
def init_logging():
    loggers = (
        logging.getLogger(name)
        for name in logging.root.manager.loggerDict
        if name.startswith("uvicorn.")
    )
    for uvicorn_logger in loggers:
        uvicorn_logger.handlers = []
    # 这儿的操作是为了改动uvicorn默许的logger，使之选用loguru的logger
    # change handler for default uvicorn logger
    intercept_handler = InterceptHandler()
    logging.getLogger("uvicorn").handlers = [intercept_handler]
    # set logs output, level and format
    # logger.add(sys.stdout, level=logging.DEBUG, format=format_record, filter=make_filter('stdout'))
    # 为pity增加一个info log文件，首要记载debug和info级别的日志
    pity_info = os.path.join(Config.LOG_DIR, "pity_info.log")
    # 为pity增加一个error log文件，首要记载warning和error级别的日志
    pity_error = os.path.join(Config.LOG_DIR, "pity_error.log")
    logger.add(pity_info, enqueue=True, rotation="20 MB", level="DEBUG", filter=make_filter("pity_info"))
    logger.add(pity_error, enqueue=True, rotation="10 MB", level="WARNING", filter=make_filter("pity_error"))
    # 装备loguru的日志句柄，sink代表输出的目标
    logger.configure(
        handlers=[
            {"sink": sys.stdout, "level": logging.DEBUG, "format": format_record},
            {"sink": pity_info, "level": logging.INFO, "format": format_record, "filter": make_filter("pity_info")},
            {"sink": pity_error, "level": logging.WARNING, "format": format_record, "filter": make_filter("pity_error")}
        ]
    )
    return logger

这儿的代码看似很复杂，实际上InterceptHandler这个类是用于界说uvicorn输出的类，能够不必细看，由于代码我也是copy的（其实里边大部分都是注释）。

format_record则是操控日志输出格式的，包含时刻，文件名，以及传入字典的时分对字典做了一个额外处理。

咱们重点看init_logging办法，这个里边前半部分是过滤出uvicorn的默许日志句柄，接着替换。后边是新增了pity的2种业务日志（info和error），一共3个handler。

最终装备logger的输出，别离输出到sys.stdout（操控台）和pity_info.log以及pity_error.log。

（pity_error和info里边都有个filter自带，这个是为了合作make_filter用的，由于日志句柄许多，而logger又是一个全局目标，所以日志究竟要输出到哪个日志文件，就要经过filter来过滤了。）

改写main.py

在main.py里边引进init_logging即可。接着重启服务，操控台就变成了上面的样子。

新增参数获取

有时分咱们想获取到恳求的json参数或许form参数，以便于报错的时分便利找到历史的恳求数据，所以咱们能够写一个中间件:

async def request_info(request: Request):
    logger.bind(name=None).info(f"{request.method} {request.url}")
    try:
        body = await request.json()
        logger.bind(payload=body, name=None).debug("request_json: ")
    except:
        body = await request.body()
        if len(body) != 0:
            # 有恳求体，记载日志
            logger.bind(payload=body, name=None).debug(body)
pity.include_router(user.router)
pity.include_router(project.router, dependencies=[Depends(request_info)])
pity.include_router(http.router, dependencies=[Depends(request_info)])
pity.include_router(testcase_router, dependencies=[Depends(request_info)])
pity.include_router(config_router, dependencies=[Depends(request_info)])
pity.include_router(online_router, dependencies=[Depends(request_info)])
pity.include_router(oss_router, dependencies=[Depends(request_info)])
pity.include_router(operation_router, dependencies=[Depends(request_info)])
pity.include_router(msg_router, dependencies=[Depends(request_info)])

这儿我过滤出了name=None（即stdout）的句柄，并打印出恳求办法和url。接着判别是不是json数据，假如不是则判别有没有body，假如有json或许有body，则打印出来。

接着咱们在每个router都参加这个依靠的中间件（request_info），用户路由没有加是由于用户登录的时分会传入明文的账号密码（js加密这儿还没做 暂时也不想做），所以假如被有心之人发现的话就难受了，所以我直接去掉了。

测试一下恳求参数

由于await request.json()会回来一个Python里边的目标（大概率是dict），所以打印会按照字典的办法打印出来，我们这儿需求了解一下。

这个功能就很nice了！！！但缺陷就是现在是打印的字典，假如能打印json就更好了，这个读者有爱好能够自己去完成。

改造原本的Log类

import inspect
import os
from loguru import logger
from config import Config
# 注意这儿
# @SingletonDecorator
class Log(object):
    business = None
    def __init__(self, name='pity'):  # Logger标识默许为app
        """
        :param name: 业务名称
        """
        # 假如目录不存在则创建
        if not os.path.exists(Config.LOG_DIR):
            os.mkdir(Config.LOG_DIR)
        self.business = name
        self.pity_info = logger.bind(name="pity_info")
        self.pity_error = logger.bind(name='pity_error')
    def info(self, message: str):
        file_name, line, func, _, _ = inspect.getframeinfo(inspect.currentframe().f_back)
        self.pity_info.info(f"func: {func} line: {line} module: {self.business} message: {message}")
    def error(self, message: str):
        file_name, line, func, _, _ = inspect.getframeinfo(inspect.currentframe().f_back)
        self.pity_error.error(f"func: {func} line: {line} module: {self.business} message: {message}")
    def warning(self, message: str):
        file_name, line, func, _, _ = inspect.getframeinfo(inspect.currentframe().f_back)
        self.pity_error.warning(f"func: {func} line: {line} module: {self.business} message: {message}")
    def debug(self, message: str):
        file_name, line, func, _, _ = inspect.getframeinfo(inspect.currentframe().f_back)
        self.pity_info.debug(f"func: {func} line: {line} module: {self.business} message: {message}")

为了不影响之前的日志模块，所以咱们没有大改，由于体系日志都是app/utils/logger.py文件的办法，所以导致自界说的日志都会出现: 显现不出来真正调用log.info的文件这个问题。

所以我这用了inspect自带的模块，获取到info/error等办法的调用方，一起来看看:

比如websocket这儿，xxx连接上了，咱们看看日志怎样展现的:

由于日志的调用一直是logger文件下的info办法，所以每次都会打印app.utils.logger.info，而咱们用了inspect之后就不一样了，能获取到实在的办法:

图中能够看到是connect办法，44行，由于文件名巨长，所以我没放进去，其实也是能够获取到的。感爱好的朋友能够自己改装下。

这块内容就当作业留给我们了，咱们下期再见！