日志打印之自定義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)放自定義日志格式化類模塊中，也可能導致重復執行