flask 解决日志重复打印问题 or Python日志重复打印

背景：业务代码上线后，莫名会重复输出很多相同的日志，已知以为是多线程问题，后仔细了解期logging原理后发现并非如此。

以下为解决方案

from flask import Flask as _Flask
from flask.helpers import locked_cached_property
from flask.logging import has_level_handler, default_handler



def create_MyLogger(app: "Flask") -> logging.Logger:
    """Get the Flask app's logger and configure it if needed.

    The logger name will be the same as
    :attr:`app.import_name <flask.Flask.name>`.

    When :attr:`~flask.Flask.debug` is enabled, set the logger level to
    :data:`logging.DEBUG` if it is not set.

    If there is no handler for the logger's effective level, add a
    :class:`~logging.StreamHandler` for
    :func:`~flask.logging.wsgi_errors_stream` with a basic format.
    """
    # logger = logging.getLogger(app.name)
    # 防止重复打印
    logger = logging.getLogger(uuid.uuid1().hex)

    if app.debug and not logger.level:
        logger.setLevel(logging.DEBUG)

    if not has_level_handler(logger) :
        logger.addHandler(default_handler)

    return logger



class Flask(_Flask):
    """
    将重新的方法进行注册
    """
  

    @locked_cached_property
    def logger(self) -> logging.Logger:
        """A standard Python :class:`~logging.Logger` for the app, with
        the same name as :attr:`name`.

        In debug mode, the logger's :attr:`~logging.Logger.level` will
        be set to :data:`~logging.DEBUG`.

        If there are no handlers configured, a default handler will be
        added. See :doc:`/logging` for more information.

        .. versionchanged:: 1.1.0
            The logger takes the same name as :attr:`name` rather than
            hard-coding ``"flask.app"``.

        .. versionchanged:: 1.0.0
            Behavior was simplified. The logger is always named
            ``"flask.app"``. The level is only set during configuration,
            it doesn't check ``app.debug`` each time. Only one format is
            used, not different ones depending on ``app.debug``. No
            handlers are removed, and a handler is only added if no
            handlers are already configured.

        .. versionadded:: 0.3
        """
        return create_MyLogger(self)

　　重复打印的原因 参考 http://static.kancloud.cn/noahs/python/932418

问题起源：

​ 在学习了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')

综上，解决方法可以参照上诉三种在 create_MyLogger 函数中实现即可。