logging 重复打日志

正确使用姿势

import logging

import config

LOG_LEVEL = "INFO"
LOG_FORMAT = "%(asctime)s %(name)s %(levelname)s %(message)s"

def get_logger(name, level=LOG_LEVEL, log_format=LOG_FORMAT):
    """
    :param name: looger 实例的名字
    :param level: logger 日志级别
    :param log_format: logger 的输出`格式
    :return:
    """
    # 强制要求传入 name
    logger = logging.getLogger(name)
    # 如果已经实例过一个相同名字的 logger，则不用再追加 handler
    if not logger.handlers:
        logger.setLevel(level=level)
        formatter = logging.Formatter(log_format)
        sh = logging.StreamHandler()
        sh.setFormatter(formatter)
        logger.addHandler(sh)
    return logger

官方文档有关介绍

Note that Loggers should NEVER be instantiated directly, but always through the module-level function logging.getLogger(name). Multiple calls to getLogger() with the same name will always return a reference to the same Logger object.

Logger对象一般不会直接实例化得到，而是通过模块级别的函数logging.getLogger(name)得到。以相同的名称多次调用getLogger()将永远返回相同Logger对象的引用。

If you attach a handler to a logger and one or more of its ancestors, it may emit the same record multiple times. In general, you should not need to attach a handler to more than one logger - if you just attach it to the appropriate logger which is highest in the logger hierarchy, then it will see all events logged by all descendant loggers, provided that their propagate setting is left set to True. A common scenario is to attach handlers only to the root logger, and to let propagation take care of the rest.

注如果你添加一个handler到logger和 它的一个或多个祖先中，它可能多次打印相同的记录。一般来说，你不应该需要将一个handler添加给多个logger - 如果你只将它添加到合适的logger而它是logger层次中最高的，那么它将看到所有子logger记录的事件，只要它们的propagate设置保留为True。一个常见的场景是将handlers附加给根logger，然后让propagation负责剩下的事情。

先看下面这段代码会发生什么？

先看源码里有关日志输出的地方

def callHandlers(self, record):
    """
    Pass a record to all relevant handlers.

    Loop through all handlers for this logger and its parents in the
    logger hierarchy. If no handler was found, output a one-off error
    message to sys.stderr. Stop searching up the hierarchy whenever a
    logger with the "propagate" attribute set to zero is found - that
    will be the last logger whose handlers are called.
    """
    c = self
    found = 0
    while c:
        for hdlr in c.handlers:
            found = found + 1
            if record.levelno >= hdlr.level:
                hdlr.handle(record)
        if not c.propagate:
            c = None    #break out
        else:
           # 将 parent 属性重新赋值给自己
            c = c.parent

如果，c 是一个 self 实例，先查找里面的 c.handlers，当前 logger 实例有多少个 handlers 会 flush多少次日志；而 c.propagate 默认为 TRUE，所以当遍历当前 实例的 handles，还会寻找其parent的handles，依次遍历。

因此，出现多次打印日志的可能

• 当前 logger 实例有多个 handlers。出现这种情况，是因为在创建 logger 实例，即 logging.getLogger(name) 时，相同的名称多次调用getLogger()，这时候会返回相同Logger对象的引用，然而每次调用getLogger()后都添加一个 handlers，此时同一个 logger 实例就有多个 handlers。

• 父类有 handlers。出现这种情况，一般是因为引用了 root logger ，并且给 root logger 添加了 StreamHandlers。

1. logger 实例有多个 handles - 相同的名称多次调用getLogger()

错误示范：

def log(name=None):
    ch = logging.StreamHandler()
    ch.setLevel(logging.INFO)

    formatter = logging.Formatter("%(asctime)s,%(name)s,%(levelname)s,%(message)s")

    logger = logging.getLogger(name)
    logger.setLevel(logging.INFO)

    ch.setFormatter(formatter)
    logger.addHandler(ch)
    return logger

log('test').info('log')
log('test').info('test')

输出

2020-01-10 14:21:50,222,test,INFO,log
2020-01-10 14:21:50,222,test,INFO,test
2020-01-10 14:21:50,222,test,INFO,test

原因是 log(‘test’).info(‘log’) 会创建一个 logger 的实例，并且添加一个 handlers，此时只有一个handlers，因此只打印一次。log(‘test’).info(‘test’) 则不会再创建一个新的 logger 实例，而是引用了之前创建的对象，并且又添加了一个 handlers，此时这个实例就有2个 handlers，因此会输出两次同一条日志

正确做法：

LOG_LEVEL = "INFO"
LOG_FORMAT = "%(asctime)s %(name)s %(levelname)s %(message)s"
def get_logger(name, level=LOG_LEVEL, log_format=LOG_FORMAT):
    """
    :param name: looger 实例的名字
    :param level: logger 日志级别
    :param log_format: logger 的输出`格式
    :return:
    """
    # 强制要求传入 name
    logger = logging.getLogger(name)
    # 如果已经实例过一个相同名字的 logger，则不用再追加 handler
    if not logger.handlers:
        logger.setLevel(level=level)
        formatter = logging.Formatter(log_format)
        sh = logging.StreamHandler()
        sh.setFormatter(formatter)
        logger.addHandler(sh)
    return logger

2. 调用 getLogger() 时 没有赋值 name

错误实例

def log(name=None):
    ch = logging.StreamHandler()
    ch.setLevel(logging.INFO)

    formatter = logging.Formatter("%(asctime)s,%(name)s,%(levelname)s,%(message)s")

    logger = logging.getLogger(name)
    logger.setLevel(logging.INFO)

    ch.setFormatter(formatter)
    logger.addHandler(ch)
    return logger

log().info('log')
log('test').info('test')

输出

2020-01-10 14:29:50,920,root,INFO,log
2020-01-10 14:29:50,920,test,INFO,test
2020-01-10 14:29:50,920,test,INFO,test

相应源码

root = RootLogger(WARNING)
Logger.root = root
Logger.manager = Manager(Logger.root)
...
...

def getLogger(name=None):
    """
    Return a logger with the specified name, creating it if necessary.

    If no name is specified, return the root logger.
    """
    if name:
        return Logger.manager.getLogger(name)
    # 如果在 getLogger 时没有赋值 name，会返回 root对象
    else:
        return root

如果在 getLogger 时没有赋值 name，会返回 root对象，而 root 是 RootLogger的实例。在getLogger后又添加了一个 handler，此时，root 这个 logger实例，就会有一个handler了（默认是没有的），因此当logger实例找到父级时，其父级也有有一个 handler，因此会再输出多一次相同的日志。

3. import logging 或者使用了 logging.basicConfig(kwargs)

先看下面这个测试案例

import logging
logging.error('hello')

输出

ERROR:root:hello

从源码分析

def error(msg, *args, **kwargs):
    """
    Log a message with severity 'ERROR' on the root logger. If the logger has
    no handlers, call basicConfig() to add a console handler with a pre-defined
    format.
    """
    if len(root.handlers) == 0:
        basicConfig()
    root.error(msg, *args, **kwargs)

调式可以发现，root 是一个 RootLogger的对象，且 root.handlers 是一个空的列表，那么根据上面的源码，接下来就会调用 basicConfig()方法。

那么可以理解为

import logging == import logging; logging.basicConfig()

测试

import logging

log_format = "[%(asctime)s] %(filename)s %(funcName)s line:%(lineno)d [%(levelname)s]%(message)s"
logging.basicConfig(level=logging.INFO, format=log_format)


def log(name=None):
    ch = logging.StreamHandler()
    ch.setLevel(logging.INFO)

    formatter = logging.Formatter("%(asctime)s,%(name)s,%(levelname)s,%(message)s")

    logger = logging.getLogger(name)
    logger.setLevel(logging.INFO)

    ch.setFormatter(formatter)
    logger.addHandler(ch)
    return logger

log('test').info('test')

输出

2020-01-10 14:32:36,817,test,INFO,test
[2020-01-10 14:32:36,817] __init__.py <module> line:26 [INFO]test

先看源码

def basicConfig(**kwargs):
    _acquireLock()
    try:
        if len(root.handlers) == 0:
            handlers = kwargs.pop("handlers", None)
            if handlers is None:
                if "stream" in kwargs and "filename" in kwargs:
                    raise ValueError("'stream' and 'filename' should not be "
                                     "specified together")
            else:
                if "stream" in kwargs or "filename" in kwargs:
                    raise ValueError("'stream' or 'filename' should not be "
                                     "specified together with 'handlers'")
            if handlers is None:
                filename = kwargs.pop("filename", None)
                mode = kwargs.pop("filemode", 'a')
                # 如果赋值了 filename，则创建 FileHandler
                if filename:
                    h = FileHandler(filename, mode)
                # 否则默认创建 StreamHandler
                else:
                    stream = kwargs.pop("stream", None)
                    h = StreamHandler(stream)
                handlers = [h]
            dfs = kwargs.pop("datefmt", None)
            style = kwargs.pop("style", '%')
            if style not in _STYLES:
                raise ValueError('Style must be one of: %s' % ','.join(
                                 _STYLES.keys()))
            fs = kwargs.pop("format", _STYLES[style][1])
            fmt = Formatter(fs, dfs, style)
            for h in handlers:
                if h.formatter is None:
                    h.setFormatter(fmt)
                # 加入到 root 
                root.addHandler(h)
            level = kwargs.pop("level", None)
            if level is not None:
                root.setLevel(level)
            if kwargs:
                keys = ', '.join(kwargs.keys())
                raise ValueError('Unrecognised argument(s): %s' % keys)
    finally:
        _releaseLock()

如上，如果 basicConfig 有赋值参数 filename，则会创建一个 filehandler，将日志输入到文件上，否则默认创建一个StreamHandler,并且会添加一个 name=None的 handler 到 rootLogger 上，此时情况又变成了类似第二种，root 这个 logger实例带有一个handler。

总结

1. basicConfig是 logging的所有顶级配置，如果在这里配置了，其后面声明的 logging.getLogger(name) 都可能会受到影响。最好不要随便使用 basicConfig 来输入 streamhandler，即使用 basicConfig 一般是用于输出到文件上。

2. 使用 logging.getLogger(name) 时，一定要赋值 name，且 name 不应该相同，如果不知道怎么命名，可以 logging.getLogger(_name_) 或者 logginggetLogger(_file_)

3. 如果怕万一使用了相同的name，可以在创建下，先判断有没有相同 name的 logger实例存在，如果有，则不添加 Handler，如第一点的正确做法

4. 其实 如果设置 Logger.propagate = False（默认为TRUE），日志消息就不会传递给祖先 loggers 的 handlers。如果它为真，记录到该 logger 的事件除了传递给该 logger 的 handler 之外，也被传递给上游（祖先）logger的 handler。信息将直接传递给祖先 logger 的 handler - 不会考虑祖先 logger 的级别和 filter。但感觉最好不要这样处理

本作品采用《CC 协议》，转载必须注明作者和本文链接