时间戳

首页 > 技术文章 > Python-logging模块定制格式描述符实现定长日志等级

Python-logging模块定制格式描述符实现定长日志等级

SnowPhoenix 2021-08-28 21:32 原文

Python-logging模块定制格式描述符实现定长日志等级

前言

在写我自己的练手项目的时候，需要写一系列Python脚本来帮助我进行运维/环境配置，我希望这些脚本能够有比较好的日志记录。

上一篇博客中，我实现了日志同时向控制台和日志中进行输出，并且二者的日志等级、日志格式不相同。

但是，仍旧存在一个让我极其难受的问题：日志的等级是不定长的。大概看起来长这样：

2021-08-28 20:37:48,430 [DEBUG] code.31 __main__:	debug
2021-08-28 20:37:48,430 [INFO] code.32 __main__:	info
2021-08-28 20:37:48,430 [WARNING] code.33 __main__:	warning
2021-08-28 20:37:48,431 [CRITICAL] code.34 __main__:	critical

可给我恶心坏了，所以我希望能够将其长度改为定长的。

本博客中，我通过自定义日志的格式描述符，实现了定长的日志等级。

参考

解决思路

我现在使用的格式化字符串为：

'%(asctime)s [%(levelname)s] %(module)s.%(lineno)d %(name)s:\t%(message)s'
'[%(asctime)s %(levelname)s] %(message)s'

第一个是向文件写入的格式，第二个是向控制台输出的格式。可见，格式化字符串通过asctime、levelname等名称来指定当前占位的应该是什么内容。那我们可不可以自定义一个shortlevelname，将原先不等长的DEBUG、INFO、WARNING、CRITICAL映射为等长的DBG、INF、WAR、ERR呢？

Filter

关于为日志格式添加新的格式描述符，官方提供了专门的接口Filter。

其使用方法参见Python 官方文档 | 利用 Filter 传递上下文信息。

Filter已经很好用了，官方文档也给出了很好的示例，这已经足以应对大多数情况了。

但是使用Filter有一个问题，它没法像handler一样，可以通过logging.basicConfig设置全局的默认配置，使用Filter需要先通过logging.getLogger()来获取一个logger实例，然后通过logger.setFilter()方法来设置Filter，每一次我们创建新的logger都需要进行这样的步骤，这未免有些麻烦。

LogRecord

通过Python官方文档|LogRecord，我们可以发现，我们在格式字符串中使用的格式描述符，其实对应的是LogRecord的属性的名字。所以，只要我们有办法在LogRecord被转换为字符串之前，为其添加我们需要的shortlevelname属性，也许就可以成功了。

关于修改LogRecord，有两个思路：

  1. 通过setLogRecordFactory()方法，使得LogRecord创建的时候就具有我们自定义的格式描述符；
  2. 继承Formatter，重写其format(record)方法，为record添加我们自定义的属性，然后调用super().format(record)，在创建全局的handler后，调用handler.setFormatter()来将我们定义的子类传入；

第一种方法是整体的修改，而第二种方法可以进行更细粒度的控制。

这两种方法都利用了Python动态类型的特点——我们可以随时为一个对象添加新的属性。

实现

这里在原有代码的基础上进行修改（原有代码参见上一篇博客），通过在程序入口调用我们自定义的方法config_logging()来配置全局日志。

先把结果贴出来：

  1. 文件里长这样：
2021-08-28 22:43:37,953 [DBG] code.46 __main__:	debug
2021-08-28 22:43:37,954 [INF] code.47 __main__:	info
2021-08-28 22:43:37,954 [WAR] code.48 __main__:	warning
2021-08-28 22:43:37,954 [ERR] code.49 __main__:	critical
  1. 控制台长这样：
[2021/08/28 22:43:37 WAR] warning
[2021/08/28 22:43:37 ERR] critical
[2021/08/28 22:43:37 WAR] warning
[2021/08/28 22:43:37 ERR] critical

思路一、setLogRecordFactory

import logging
import sys

class ShortLevelNameLogFactory:
    def __init__(self, old_factory) -> None:
        self.old_factory = old_factory
        tmp = {
            "DEBUG": "DBG",
            "INFO": "INF",
            "WARNING": "WAR",
            "CRITICAL": "ERR"
        }
        self.levelname_trans = tmp # dict({v:v for v in tmp.values()}, **tmp)

    def __call__(self, name, level, fn, lno, msg, args, exc_info, func=None, sinfo=None, **kwargs)->logging.LogRecord:
        record = self.old_factory(name, level, fn, lno, msg, args, exc_info, func, sinfo, **kwargs)
        record.shortlevelname = self.levelname_trans[record.levelname]
        return record

def config_logging(file_name: str, console_level: int=logging.INFO, file_level: int=logging.DEBUG):
    old_factory = logging.getLogRecordFactory()
    new_factory = ShortLevelNameLogFactory(old_factory)
    logging.setLogRecordFactory(new_factory)
    
    file_handler = logging.FileHandler(file_name, mode='a', encoding="utf8")
    file_handler.setFormatter(logging.Formatter(
        '%(asctime)s [%(shortlevelname)s] %(module)s.%(lineno)d %(name)s:\t%(message)s'
        ))
    file_handler.setLevel(file_level)

    console_handler = logging.StreamHandler(sys.stdout)
    console_handler.setFormatter(logging.Formatter(
        '[%(asctime)s %(shortlevelname)s] %(message)s',
        datefmt="%Y/%m/%d %H:%M:%S"
        ))
    console_handler.setLevel(console_level)

    logging.basicConfig(
        level=min(console_level, file_level),
        handlers=[file_handler, console_handler],
        )

if __name__ == '__main__':
    config_logging("test.log", logging.WARNING, logging.DEBUG)
    logging.debug("debug")
    logging.info("info")
    logging.warning("warning")
    logging.critical("critical")

    logger = logging.getLogger(__name__)
    logger.debug("debug")
    logger.info("info")
    logger.warning("warning")
    logger.critical("critical")

思路二、继承Formatter

import logging
import sys

class ShortLevelNameFormatter(logging.Formatter):
    def __init__(self, *args, **kargs):
        super().__init__(*args, **kargs)
        tmp = {
            "DEBUG": "DBG",
            "INFO": "INF",
            "WARNING": "WAR",
            "CRITICAL": "ERR"
        }
        self.levelname_trans = tmp # dict({v:v for v in tmp.values()}, **tmp)

    def format(self, record: logging.LogRecord) -> str:
        record.shortlevelname = self.levelname_trans[record.levelname]
        return super().format(record)

def config_logging(file_name: str, console_level: int=logging.INFO, file_level: int=logging.DEBUG):
    file_handler = logging.FileHandler(file_name, mode='a', encoding="utf8")
    file_handler.setFormatter(ShortLevelNameFormatter(
        '%(asctime)s [%(shortlevelname)s] %(module)s.%(lineno)d %(name)s:\t%(message)s'
        ))
    file_handler.setLevel(file_level)

    console_handler = logging.StreamHandler(sys.stdout)
    console_handler.setFormatter(ShortLevelNameFormatter(
        '[%(asctime)s %(shortlevelname)s] %(message)s',
        datefmt="%Y/%m/%d %H:%M:%S"
        ))
    console_handler.setLevel(console_level)

    logging.basicConfig(
        level=min(console_level, file_level),
        handlers=[file_handler, console_handler],
        )

if __name__ == '__main__':
    config_logging("test.log", logging.WARNING, logging.DEBUG)
    logging.debug("debug")
    logging.info("info")
    logging.warning("warning")
    logging.critical("critical")

    logger = logging.getLogger(__name__)
    logger.debug("debug")
    logger.info("info")
    logger.warning("warning")
    logger.critical("critical")

推荐阅读