爱站程序员基地日志打印之自定义logger handler
By:授客 QQ：1033553122
#实践环境
WIN 10
Python 3.6.5
#实践代码
handler.py
#!/usr/bin/env python# -*- coding:utf-8 -*-\'\'\'@Author : shouke\'\'\'import loggingimport logging.configclass 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，shoukeprocess ： 27932processName ： MainProcessthread ： 45464threadName ： MainThreadINFO:logger:hello，shouke
#通过字典配置添加自定义handler
mytest.py(与handler.py位于同一层级目录)
#!/usr/bin/env python# -*- coding:utf-8 -*-### \'\'\'# @CreateTime: 2020/12/29 14:08# @Author : shouke# \'\'\'#import loggingimport logging.configLOGGING_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，shoukeprocess ： 36280processName ： MainProcessthread ： 37316threadName ： MainThreadINFO:logger:hello，shouke2021-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，shoukeprocess ： 17276processName ： MainProcessthread ： 14516threadName ： MainThread初始化自定义日志处理器： LoggerHandler其它属性值： something others获取到的消息为： 2021-01-09 10:48:24,090 study.py 66 INFO ： hello，shoukeprocess ： 17276processName ： MainProcessthread ： 14516threadName ： MainThread
如上，可以看到，自定义类构造函数被重复执行，日志消息被重复处理
##原因分析
logging.config.dictConfig(config)函数内部调用了DictConfigurator(config).configure()，而configure函数内DictConfigurator部，根据incremental，handlers等当前日志配置，被执行的分支代码中，会调用
DictConfigurator类实例的configure_handler()方法，该方法中，根据当前配置，又会再次调用DictConfigurator类实例的resolve(self, s)方法，参数s接收handler中class配置项目的值。具体代码如下：
class DictConfigurator(BaseConfigurator):# ... 略def resolve(self, s):\"\"\"Resolve strings to objects using standard import and attributesyntax.\"\"\"name = s.split(\'.\') # 本例中，s为study.MyLogHandlerused = name.pop(0) # used 为studytry:found = self.importer(used) # 这里importer = staticmethod(__import__) # 所以此处代码等同于__import__(used) # 这里导入自定义日志处理器所在模块会导致模块中的logging.config.dictConfig(config)代码再次被执行for frag in name:used += \'.\' + fragtry:found = getattr(found, frag)except AttributeError:self.importer(used)found = getattr(found, frag)return foundexcept ImportError:e, tb = sys.exc_info()[1:]v = ValueError(\'Cannot resolve %r: %s\' % (s, e))v.__cause__, v.__traceback__ = e, tbraise vdef configure_formatter(self, config):\"\"\"Configure a formatter from a dictionary.\"\"\"if \'()\' in config:factory = config[\'()\'] # for use in exception handlertry:result = self.configure_custom(config)except TypeError as te:if \"\'format\'\" not in str(te):raise#Name of parameter changed from fmt to format.#Retry with old name.#This is so that code can be used with older Python versions#(e.g. by Django)config[\'fmt\'] = config.pop(\'format\')config[\'()\'] = factoryresult = self.configure_custom(config)else:fmt = config.get(\'format\', None)dfmt = config.get(\'datefmt\', None)style = config.get(\'style\', \'%\')cname = config.get(\'class\', None)if not cname:c = logging.Formatterelse:c = _resolve(cname)result = c(fmt, dfmt, style)return result# ... 略def configure_handler(self, config):\"\"\"Configure a handler from a dictionary.\"\"\"config_copy = dict(config) # for restoring in case of errorformatter = config.pop(\'formatter\', None)if formatter:try:formatter = self.config[\'formatters\'][formatter]except Exception as e:raise ValueError(\'Unable to set formatter \'\'%r: %s\' % (formatter, e))level = config.pop(\'level\', None)filters = config.pop(\'filters\', None)if \'()\' in config:c = config.pop(\'()\')if not callable(c):c = self.resolve(c)factory = celse:cname = config.pop(\'class\')klass = self.resolve(cname)#Special case for handler which refers to another handlerif issubclass(klass, logging.handlers.MemoryHandler) and\\\'target\' in config:try:th = self.config[\'handlers\'][config[\'target\']]if not isinstance(th, logging.Handler):config.update(config_copy) # restore for deferred cfgraise TypeError(\'target not configured yet\')config[\'target\'] = thexcept Exception as e:raise ValueError(\'Unable to set target handler \'\'%r: %s\' % (config[\'target\'], e))elif issubclass(klass, logging.handlers.SMTPHandler) and\\\'mailhost\' in config:config[\'mailhost\'] = self.as_tuple(config[\'mailhost\'])elif issubclass(klass, logging.handlers.SysLogHandler) and\\\'address\' in config:config[\'address\'] = self.as_tuple(config[\'address\'])factory = klassprops = config.pop(\'.\', None)kwargs = dict([(k, config[k]) for k in config if valid_ident(k)])try:result = factory(**kwargs)except TypeError as te:if \"\'stream\'\" not in str(te):raise#The argument name changed from strm to stream#Retry with old name.#This is so that code can be used with older Python versions#(e.g. by Django)kwargs[\'strm\'] = kwargs.pop(\'stream\')result = factory(**kwargs)if formatter:result.setFormatter(formatter)if level is not None:result.setLevel(logging._checkLevel(level))if filters:self.add_filters(result, filters)if props:for name, value in props.items():setattr(result, name, value)return result
至此，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 + \'.\' + ntry:found = getattr(found, n)except AttributeError:__import__(used)found = getattr(found, n)return found
如果自定义Formatter，把logging.config.dictConfig(config)放自定义日志格式化类模块中，也可能导致重复执行
