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: %(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，有两个思路：
- 通过setLogRecordFactory()方法，使得LogRecord创建的时候就具有我们自定义的格式描述符；
- 继承Formatter，重写其
format(record)方法，为record添加我们自定义的属性，然后调用super().format(record)，在创建全局的handler后，调用handler.setFormatter()来将我们定义的子类传入；
第一种方法是整体的修改，而第二种方法可以进行更细粒度的控制。
这两种方法都利用了Python动态类型的特点——我们可以随时为一个对象添加新的属性。
实现
这里在原有代码的基础上进行修改（原有代码参见上一篇博客），通过在程序入口调用我们自定义的方法config_logging()来配置全局日志。
先把结果贴出来：
- 文件里长这样：
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
- 控制台长这样：
[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: %(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: %(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")