Python 日誌列印之自定義logger handler

授客發表於2021-01-24

日誌列印之自定義logger handler

By:授客 QQ1033553122

#實踐環境

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)放自定義日誌格式化類模組中,也可能導致重複執行

 

相關文章