[TOC]
# 浅析python日志重复输出问题
## 问题起源：
在学习了python的函数式编程后，又接触到了logging这样一个强大的日志模块。为了减少重复代码，应该不少同学和我一样便迫不及待的写了一个自己的日志函数，比如下面这样：
```
# 这里为了便于理解，简单的展示了一个输出到屏幕的日志函数
def my_log():
logger = logging.getLogger('mysql.log')
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
fmt = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(fmt)
logger.addHandler(ch)
return logger
my_log().error('run one')
my_log().error('run two')
my_log().error('run three')
```
函数写好了，看起来似乎也没有问题，我们来运行一下！
结果如下：
```
> 2018-06-21 13:06:37,569 - mysql.log - ERROR - run one
> 2018-06-21 13:06:37,569 - mysql.log - ERROR - run two
> 2018-06-21 13:06:37,569 - mysql.log - ERROR - run two
> 2018-06-21 13:06:37,569 - mysql.log - ERROR - run three
> 2018-06-21 13:06:37,569 - mysql.log - ERROR - run three
> 2018-06-21 13:06:37,569 - mysql.log - ERROR - run three
```
日志居然重复输出了，且数量递增。
* * *
## 问题解析
* 实际上`logger = logging.getLogger('mysql.log')`在执行时，没有每次生成一个新的logger，而是先检查内存中是否存在一个叫做‘mysql.log’的logger对象，存在则取出，不存在则新建。
* 实例化的logger对象具有‘handlers’这样一个属性来存储 Handler，代码演示如下：
```
def my_log():
logger = logging.getLogger('mysql.log')
# 每次被调用后打印出logger的handlers列表
print(logger.handlers)
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
fmt = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(fmt)
logger.addHandler(ch)
return logger
my_log().error('run one')
my_log().error('run two')
my_log().error('run three')
```
运行结果：
```
> \[\]
> 2018-06-21 13:26:14,059 - mysql.log - ERROR - run one
> \[ (ERROR)>\]
> 2018-06-21 13:26:14,060 - mysql.log - ERROR - run two
> 2018-06-21 13:26:14,060 - mysql.log - ERROR - run two
> \[ (ERROR)>, (ERROR)>\]
> 2018-06-21 13:26:14,060 - mysql.log - ERROR - run three
> 2018-06-21 13:26:14,060 - mysql.log - ERROR - run three
> 2018-06-21 13:26:14,060 - mysql.log - ERROR - run three
```
1. `logger.handlers`最初是一个空列表，执行‘logger.addHandler(ch)’添加一个‘StreamHandler’，输出一条日志
2. 在第二次被调用时，`logger.handlers`已经存在一个‘StreamHandler’，再次执行‘logger.addHandler(ch)’就会再次添加一个‘StreamHandler’，此时的logger有两个个‘StreamHandler’，输出两条重复的日志
3. 在第三次被调用时，`logger.handlers`已经存在两个‘StreamHandler’，再次执行‘logger.addHandler(ch)’就会再次添加一个，此时的logger有三个‘StreamHandler’，输出三条重复的日志
## 解决办法
### 1.改名换姓
```
# 为日志函数添加一个name，每次调用时传入不同的日志名
def my_log(name):
logger = logging.getLogger(name)
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
fmt = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(fmt)
logger.addHandler(ch)
return logger
my_log('log1').error('run one')
my_log('log2').error('run two')
my_log('log3').error('run three')
```
运行结果：
```
> 2018-06-21 13:40:51,685 - log1 - ERROR - run one
> 2018-06-21 13:40:51,685 - log2 - ERROR - run two
> 2018-06-21 13:40:51,685 - log3 - ERROR - run three
```
### 2.及时清理(logger.handlers.clear)
```
def my_log():
logger = logging.getLogger()
# 每次被调用后，清空已经存在handler
logger.handlers.clear()
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
fmt = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(fmt)
logger.addHandler(ch)
return logger
my_log().error('run one')
my_log().error('run two')
my_log().error('run three')
```
### 3.用前判断
```
import logging
def my_log():
logger = logging.getLogger('mysql.log')
# 判断logger是否已经添加过handler，是则直接返回，否则才执行
if not logger.handlers:
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
fmt = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(fmt)
logger.addHandler(ch)
return logger
my_log().error('run one')
my_log().error('run two')
my_log().error('run three')
```
* * *