日誌列印之自定義logger handler
By:授客 QQ:1033553122
#實踐環境
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配置專案的值。具體程式碼如下:
class DictConfigurator(BaseConfigurator): # ... 略 def resolve(self, s): """ Resolve strings to objects using standard import and attribute syntax. """ name = s.split('.') # 本例中,s為study.MyLogHandler used = name.pop(0) # used 為study try: found = self.importer(used) # 這裡importer = staticmethod(__import__) # 所以此處程式碼等同於__import__(used) # 這裡匯入自定義日誌處理器所在模組會導致模組中的logging.config.dictConfig(config)程式碼再次被執行 for frag in name: used += '.' + frag try: found = getattr(found, frag) except AttributeError: self.importer(used) found = getattr(found, frag) return found except ImportError: e, tb = sys.exc_info()[1:] v = ValueError('Cannot resolve %r: %s' % (s, e)) v.__cause__, v.__traceback__ = e, tb raise v def configure_formatter(self, config): """Configure a formatter from a dictionary.""" if '()' in config: factory = config['()'] # for use in exception handler try: 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['()'] = factory result = 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.Formatter else: 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 error formatter = 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 = c else: cname = config.pop('class') klass = self.resolve(cname) #Special case for handler which refers to another handler if 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 cfg raise TypeError('target not configured yet') config['target'] = th except 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 = klass props = 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 + '.' + n try: found = getattr(found, n) except AttributeError: __import__(used) found = getattr(found, n) return found
如果自定義Formatter,把logging.config.dictConfig(config)放自定義日誌格式化類模組中,也可能導致重複執行