日志打印之自定义logger handler
#实践环境
WIN 10
Python 3.6.5
#实践代码
handler.py
#!/usr/bin/env python # -*- coding:utf-8 -*- ''' @Author : shouke ''' import logging import logging.config class MyLogHandler(logging.Handler, object): """ 自定义日志handler """ def __init__(self, name, other_attr=None, **kwargs): logging.Handler.__init__(self) print('初始化自定义日志处理器：', name) print('其它属性值：', other_attr) def emit(self, record): """ emit函数为自定义handler类时必重写的函数，这里可以根据需要对日志消息做一些处理，比如发送日志到服务器 发出记录(Emit a record) """ try: msg = self.format(record) print('获取到的消息为：', msg) for item in dir(record): if item in ['process', 'processName', 'thread', 'threadName']: print(item, '：', getattr(record, item)) except Exception: self.handleError(record) # 测试 logging.basicConfig() logger = logging.getLogger("logger") logger.setLevel(logging.INFO) my_log_handler = MyLogHandler('LoggerHandler') logger.addHandler(my_log_handler) logger.info('hello，shouke') 运行handler.py，结果输出如下 初始化自定义日志处理器： LoggerHandler 其它属性值： None 获取到的消息为： hello，shouke process ： 27932 processName ： MainProcess thread ： 45464 threadName ： MainThread INFO:logger:hello，shouke
#通过字典配置添加自定义handler
mytest.py(与handler.py位于同一层级目录)
#!/usr/bin/env python # -*- coding:utf-8 -*- # # # ''' # @CreateTime: 2020/12/29 14:08 # @Author : shouke # ''' # import logging import logging.config LOGGING_CONFIG = { "version": 1, "disable_existing_loggers": False, "formatters": { "default": { "format":"%(asctime)s %(filename)s %(lineno)s %(levelname)s ： %(message)s", }, "plain": { "format": "%(message)s", } }, "handlers": { "customer_handler":{ "class":"study.MyLogHandler", "formatter":"default", # 注意，class，formatter，level，filters之外的参数将默认传递给由class指定类的构造函数 "name":"LoggerHandler", "other_attr":"something others" }, "console": { "class": "logging.StreamHandler", "formatter": "default", }, }, "loggers": { "customer_logger":{ "handlers": ["customer_handler", "console"], "level": logging.INFO, "propagate": False, } } } logging.config.dictConfig(LOGGING_CONFIG) logger = logging.getLogger('customer_logger') logger.info('hello，shouke') 运行mytest.py，输出结果如下 初始化自定义日志处理器： LoggerHandler 其它属性值： something others 获取到的消息为： 2021-01-01 17:51:54,661 mytest.py 48 INFO ： hello，shouke process ： 36280 processName ： MainProcess thread ： 37316 threadName ： MainThread INFO:logger:hello，shouke 2021-01-01 17:51:54,661 mytest5.py 48 INFO ： hello，shouke。
##问题：为什么mytest.py中的代码，不能放在study.py中？
如下，在study.py模块，MyLogHandler类之后追加下述代码
LOGGING_CONFIG = { "version": 1, "disable_existing_loggers": False, "formatters": { "default": { "format":"%(asctime)s %(filename)s %(lineno)s %(levelname)s ： %(message)s", } }, "handlers": { "customer_handler":{ "class":"study.MyLogHandler", "formatter":"default", "name":"LoggerHandler", "other_attr":"something others" } }, "loggers": { "customer_logger":{ "handlers": ["customer_handler"], "level": logging.INFO, "propagate": False, } } } logging.config.dictConfig(LOGGING_CONFIG) logger = logging.getLogger('customer_logger') logger.info('hello，shouke') 运行mytest.py，输出结果如下 初始化自定义日志处理器： LoggerHandler 其它属性值： something others 获取到的消息为： 2021-01-09 10:48:24,090 study.py 66 INFO ： hello，shouke process ： 17276 processName ： MainProcess thread ： 14516 threadName ： MainThread 初始化自定义日志处理器： LoggerHandler 其它属性值： something others 获取到的消息为： 2021-01-09 10:48:24,090 study.py 66 INFO ： hello，shouke process ： 17276 processName ： MainProcess thread ： 14516 threadName ： MainThread
如上，可以看到，自定义类构造函数被重复执行，日志消息被重复处理
##原因分析
logging.config.dictConfig(config)函数内部调用了DictConfigurator(config).configure()，而configure函数内DictConfigurator部，根据incremental，handlers等当前日志配置，被执行的分支代码中，会调用
DictConfigurator类实例的configure_handler()方法，该方法中，根据当前配置，又会再次调用DictConfigurator类实例的resolve(self, s)方法，参数s接收handler中class配置项目的值。具体代码如下：
LOGGING_CONFIG = { "version": 1, "disable_existing_loggers": False, "formatters": { "default": { "format":"%(asctime)s %(filename)s %(lineno)s %(levelname)s ： %(message)s", } }, "handlers": { "customer_handler":{ "class":"study.MyLogHandler", "formatter":"default", "name":"LoggerHandler", "other_attr":"something others" } }, "loggers": { "customer_logger":{ "handlers": ["customer_handler"], "level": logging.INFO, "propagate": False, } } } logging.config.dictConfig(LOGGING_CONFIG) logger = logging.getLogger('customer_logger') logger.info('hello，shouke') 运行mytest.py，输出结果如下 初始化自定义日志处理器： LoggerHandler 其它属性值： something others 获取到的消息为： 2021-01-09 10:48:24,090 study.py 66 INFO ： hello，shouke process ： 17276 processName ： MainProcess thread ： 14516 threadName ： MainThread 初始化自定义日志处理器： LoggerHandler 其它属性值： something others 获取到的消息为： 2021-01-09 10:48:24,090 study.py 66 INFO ： hello，shouke process ： 17276 processName ： MainProcess thread ： 14516 threadName ： MainThread
至此，logging.config.dictConfig(config)放自定义日志处理类模块中，导致自定义日志处理类重复被执行的原因已经清楚了。
configure函数内部，根据incremental，handlers等当前日志配置，被执行的分支代码中，也可能执行DictConfigurator类实例的configure_formatter()方法，类似的，该方法中也会调用一个名为_resolve的方法，具体代码如下
def _resolve(name): """Resolve a dotted name to a global object.""" name = name.split('.') used = name.pop(0) found = __import__(used) for n in name: used = used + '.' + n try: found = getattr(found, n) except AttributeError: __import__(used) found = getattr(found, n) return found
如果自定义Formatter，把logging.config.dictConfig(config)放自定义日志格式化类模块中，也可能导致重复执行
