解决logging模块日志信息重复问题
问题描述
相信大家都知道python的logging模块记录日志信息的步骤:
# coding:utf-8
import logging
### 创建logger对象
logger = logging.getLogger()
###设置下最低级别
logger.setLevel(logging.DEBUG)
### 创建文件操作符
fh = logging.FileHandler('test',encoding='utf-8')
### 创建屏幕操作符
sh = logging.StreamHandler()
### 创建一个格式对象
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
### logger绑定文件操作符
logger.addHandler(fh)
### logger绑定屏幕操作符
logger.addHandler(sh)
### 文件操作符绑定格式
fh.setFormatter(formatter)
### 屏幕操作符绑定格式
sh.setFormatter(formatter)
### 用logger对象输出信息
logger.warning('logger1')
logger.info('logger2')
logger.error('logger3')
然后,如果我们用上面的思路来写一个函数实现日志功能(我们写日志的py文件为logger.py,在同目录下创建一个文件log.log来记录日志信息,而且这里只将日志信息输出到文件来显示):
# logger.py
# coding:utf-8
import logging
def logger(msg):
#生成logger对象
whw_logger = logging.getLogger('log.log')
whw_logger.setLevel(logging.INFO)
#生成handler对象
whw_fh = logging.FileHandler('log.log')
whw_fh.setLevel(logging.INFO)
#生成Formatter对象
file_formatter = logging.Formatter(' %(asctime)s - %(name)s - %(levelname)s - %(message)s ')
#把formatter对象绑定到handler对象中
whw_fh.setFormatter(file_formatter)
# 把handler对象绑定到logger对象中
whw_logger.addHandler(whw_fh)
whw_logger.info(msg)
if __name__ == '__main__':
logger('hello world1')
logger('hello world2')
logger('hello world3')
但是,当程序运行后,你会发现,你的log.log
文件中的记录竟然是酱紫的(程序运行2次):
2019-04-07 14:47:12,318 - log.log - INFO - hello world1
2019-04-07 14:47:12,319 - log.log - INFO - hello world2
2019-04-07 14:47:12,319 - log.log - INFO - hello world2
2019-04-07 14:47:12,319 - log.log - INFO - hello world3
2019-04-07 14:47:12,319 - log.log - INFO - hello world3
2019-04-07 14:47:12,319 - log.log - INFO - hello world3
2019-04-07 14:47:15,388 - log.log - INFO - hello world1
2019-04-07 14:47:15,388 - log.log - INFO - hello world2
2019-04-07 14:47:15,388 - log.log - INFO - hello world2
2019-04-07 14:47:15,388 - log.log - INFO - hello world3
2019-04-07 14:47:15,388 - log.log - INFO - hello world3
2019-04-07 14:47:15,388 - log.log - INFO - hello world3
也就是说,我们每一次进行日志信息打印的次数是成倍增长的!!!
问题分析
其实,我们每次在创建一个logger对象的时候,里面会有一个handlers属性,初始值为一个空列表:
class Logger(Filterer):
"""
logger 对象的介绍 详情大家可以看源码
"""
def __init__(self, name, level=NOTSET):
"""
Initialize the logger with a name and an optional level.
"""
Filterer.__init__(self)
self.name = name
self.level = _checkLevel(level)
self.parent = None
self.propagate = True
# 初始化为空列表的handlers属性
self.handlers = []
self.disabled = False
那么问题来了:这个handlers属性
是做什么用的呢?让我们再来看一下源码:
def addHandler(self, hdlr):
"""
Add the specified handler to this logger.
"""
_acquireLock()
try:
if not (hdlr in self.handlers):
self.handlers.append(hdlr)
finally:
_releaseLock()
当我们为一个logger对象绑定一个文件或者屏幕操作符的时候,其实就是讲它们加在了这个handlers列表
里面。然后我们再接着往下看(这里只截取代码片段,帮助大家分析问题,具体的还是建议大家自己看源码):
for h in handlers:
if h.formatter is None:
h.setFormatter(fmt)
root.addHandler(h)
这段代码下面其实就是从我们这个handlers列表
中获取操作符,然后进行文件或屏幕的格式化操作。
问题就出现在了这里:由于我们上面的代码每次都打印三个信息————在第一次执行打印 hello world1 的时候会创建一个logger对象,而此时handlers列表是空的,因此程序会为这个空列表加上一个文件操作符;在第二次打印 hello world2 时,程序会根据getLogger函数的name属性获取之前的同一个logger对象,并没有创建新的logger对象,而接着程序又会‘像之前一样’误将文件操作符又一次append到了handlers列表里,此时这个列表中有两个相同的文件操作符,因此第二次会打印两次相同的信息;第三次原理一样...文件中输出三次相同的信息
我们可以在logger函数的结尾加上下面这段代码,每次都打印一下handlers列表,验证一下我们的猜想::
print(whw_logger.handlers)
print(len(whw_logger.handlers))
输出结果如下:
[<FileHandler E:\practice\old_boy_all_day\all_days\day26+1\log.log (INFO)>]
1
[<FileHandler E:\practice\old_boy_all_day\all_days\day26+1\log.log (INFO)>, <FileHandler E:\practice\old_boy_all_day\all_days\day26+1\log.log (INFO)>]
2
[<FileHandler E:\practice\old_boy_all_day\all_days\day26+1\log.log (INFO)>, <FileHandler E:\practice\old_boy_all_day\all_days\day26+1\log.log (INFO)>, <FileHandler E:\practice\old_boy_all_day\all_days\day26+1\log.log (INFO)>]
3
结果果真如我们所想的那样:列表中每一次都添加了新的文件操作符。
问题解决
关于一次性重复打印的问题的原因我们找到了,那么如何解决呢?下面给出两种推荐的解决方案:
每一次输出完后及时移除操作符
就是说,在每一次输出结束后,我们将handlers这个列表中的logger对象及时移除。
移除的方法有两种,一种是利用logger对象中自带的removeHandler方法
,另外也可以直接利用列表的pop方法直接将handlers对象中的文件操作符删除(不过这种方法得考虑每一次添加了多少个文件操作符),针对本例给出的解决方案的代码如下:
# coding:utf-8
import logging
def logger(msg):
#生成logger对象
whw_logger = logging.getLogger('log.log')
whw_logger.setLevel(logging.INFO)
#生成handler对象
whw_fh = logging.FileHandler('log.log')
whw_fh.setLevel(logging.INFO)
#生成Formatter对象
file_formatter = logging.Formatter(' %(asctime)s - %(name)s - %(levelname)s - %(message)s ')
#把formatter对象绑定到handler对象中
whw_fh.setFormatter(file_formatter)
# 把handler对象绑定到logger对象中
whw_logger.addHandler(whw_fh)
whw_logger.info(msg)
whw_logger.removeHandler(whw_fh)
if __name__ == '__main__':
logger('hello world1')
logger('hello world2')
logger('hello world3')
在logger函数中判断handlers属性是否为空
使用前判断logger对象的handlers列表是否为空,空则添加一个handler,不空则直接调用:
# coding:utf-8
import logging
def logger(msg):
#生成logger对象
whw_logger = logging.getLogger('log.log')
whw_logger.setLevel(logging.INFO)
# 如果handlers属性为空则添加文件操作符,不为空直接写日志
if not whw_logger.handlers:
#生成handler对象
whw_fh = logging.FileHandler('log.log')
whw_fh.setLevel(logging.INFO)
#生成Formatter对象
file_formatter = logging.Formatter(' %(asctime)s - %(name)s - %(levelname)s - %(message)s ')
#把formatter对象绑定到handler对象中
whw_fh.setFormatter(file_formatter)
# 把handler对象绑定到logger对象中
whw_logger.addHandler(whw_fh)
whw_logger.info(msg)
if __name__ == '__main__':
logger('hello world1')
logger('hello world2')
logger('hello world3')
利用单例模式解决
如果利用面向对象的方法写一个Log类去实现的话,基本思路是:首先利用重写__new__的方法创建每个logger对象的单例,然后在每次实例化的时候判断是否已经存在这个logger对象,如果不存在的话就创建,若之前已经创建了一个相同的logger对象,就直接用之前的,酱紫大大提高了程序的效率
话不多说,直接上代码:
# -*- coding:utf-8 -*-
import logging
class Log(object):
__instance = None
# 重写new方法实现单例模式
def __new__(cls, *args, **kwargs):
if not cls.__instance:
obj = object.__new__(cls)
cls.__instance = obj
return cls.__instance
def __init__(self,level=logging.DEBUG):
# 如果之前没创建过 就新建一个logger对象,后面相同的实例共用一个logger对象
if 'logger' not in self.__dict__:
logger = logging.getLogger()
logger.setLevel(level)
fh = logging.FileHandler('log.log', encoding='utf-8')
ch = logging.StreamHandler()
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)
logger.addHandler(fh)
logger.addHandler(ch)
self.logger = logger
if __name__ == '__main__':
log1 = Log()
log2 = Log()
log3 = Log()
log1.logger.info('123')
log2.logger.info('456')
log3.logger.info('789')
输出结果:
2019-04-09 20:39:08,081 - root - INFO - 123
2019-04-09 20:39:08,081 - root - INFO - 456
2019-04-09 20:39:08,081 - root - INFO - 789
当然,如果考虑到效率的问题,在logger函数中判断handlers属性是否为空
与利用单例模式解决
的方法要比每次从handlers属性列表中删除掉之前的操作符
的方法高效,因为这样可以避免Python解释器做重复繁琐的工作。