使用 Python 日志记录出现两次的日志消息答案

【问题标题】：log messages appearing twice with Python Logging使用 Python 日志记录出现两次的日志消息
【发布时间】：2011-10-07 10:34:35
【问题描述】：

我正在使用 Python 日志记录，由于某种原因，我的所有消息都出现了两次。

我有一个模块来配置日志记录：

# BUG: It's outputting logging messages twice - not sure why - it's not the propagate setting.
def configure_logging(self, logging_file):
    self.logger = logging.getLogger("my_logger")
    self.logger.setLevel(logging.DEBUG)
    self.logger.propagate = 0
    # Format for our loglines
    formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s")
    # Setup console logging
    ch = logging.StreamHandler()
    ch.setLevel(logging.DEBUG)
    ch.setFormatter(formatter)
    self.logger.addHandler(ch)
    # Setup file logging as well
    fh = logging.FileHandler(LOG_FILENAME)
    fh.setLevel(logging.DEBUG)
    fh.setFormatter(formatter)
    self.logger.addHandler(fh)

后来，我调用这个方法来配置日志：

if __name__ == '__main__':
    tom = Boy()
    tom.configure_logging(LOG_FILENAME)
    tom.buy_ham()

然后在里面说，buy_ham 模块，我会调用：

self.logger.info('Successfully able to write to %s' % path)

由于某种原因，所有消息都出现了两次。我注释掉了一个流处理程序，还是一样的。有点奇怪，不知道为什么会这样……哈哈。假设我错过了一些明显的东西。

干杯，维克多

【问题讨论】：

你确定configure_logging() 没有被调用两次（例如也从构造函数调用）？是否只创建了一个 Boy() 实例？
改用self.logger.handlers = [ch] 可以解决这个问题，但最好只是确保您不会两次运行此代码，例如在开始时使用if not self.logger。跨度>

标签： python logging

【解决方案1】：

您正在调用configure_logging 两次（可能在Boy 的__init__ 方法中）：getLogger 将返回相同的对象，但addHandler 不会检查是否已将类似的处理程序添加到记录器。

尝试跟踪对该方法的调用并消除其中一个。或者在Boy的__init__方法中设置一个标志logging_initialized初始化为False，如果logging_initialized是True，则将configure_logging更改为不做任何事情，然后将其设置为True '已经初始化了记录器。

如果您的程序创建了多个 Boy 实例，您将不得不通过添加处理程序的全局 configure_logging 函数和仅初始化 self.logger 属性的 Boy.configure_logging 方法来更改执行方式。

解决此问题的另一种方法是检查记录器的 handlers 属性：

logger = logging.getLogger('my_logger')
if not logger.handlers:
    # create the handlers and call logger.addHandler(logging_handler)

【讨论】：

是的，你是对的——我真傻。我在 init 中以及在其他地方明确地调用了它。哈哈。谢谢 =)。
谢谢。今天你的解决方案救了我。
就我而言，它们出现了 6 次。我怀疑是因为我在 6 个 oop 类中声明了相同类型的记录器
我想在这里分享我的经验：对于我开发的 Flask 应用程序，日志消息出现了两次以上。我会说它们在日志文件上递增，因为在加载应用程序和模块时，使用的 logger 变量不是从我的一个类中实例化的变量，而是 @987654340 @ 变量存在于 Python3 缓存中，并且处理程序由我配置的 AppScheduler 每 60 秒添加一次。因此，if not logger.handlers 是避免此类现象的一种非常聪明的方法。感谢您的解决方案，同志:)！
我在我的 Flask 应用程序中看到了这个问题。此解决方案解决了主烧瓶应用程序中生成的日志消息的问题，但我的应用程序在库模块中调用函数，并且来自该库的那些消息仍然被多次记录。我不知道如何解决这个问题。

【解决方案2】：

如果您遇到此问题并且没有两次添加处理程序，请查看 abarnert 的回答 here

来自docs：

注意：如果您将处理程序附加到记录器，并且它的一个或多个祖先，它可能会多次发出相同的记录。一般来说，你不需要将处理程序附加到多个记录器 - 如果您只需将其附加到适当的记录器上记录器层次结构，然后它将看到所有后代记录的所有事件记录器，前提是它们的传播设置保留为 True。一种常见的情况是仅将处理程序附加到根记录器，并让传播处理剩下的事情。

因此，如果您希望在“测试”上使用自定义处理程序，并且不希望它的消息也发送到根处理程序，答案很简单：关闭它的 propagate 标志：

logger.propagate = False

【讨论】：

这是最好的答案。它不符合海报的目的（编码中的逻辑错误），但大多数时候，情况应该如此。
太棒了。这是重复的实际原因（对于最一般的情况）。
这也是我的代码的问题。非常感谢。
有史以来最好的答案。谢谢！
这确实有帮助。谢谢。

【解决方案3】：

我是 python 新手，但这似乎对我有用（Python 2.7）

while logger.handlers:
     logger.handlers.pop()

【讨论】：

这对我有用，但更喜欢使用 logger.handlers.clear()

【解决方案4】：

每次从外部调用时都会添加处理程序。完成工作后尝试删除处理程序：

self.logger.removeHandler(ch)

【讨论】：

我在 python 2.7 中使用了logger.handlers.pop() ，成功了

【解决方案5】：

在我的情况下，我会设置 logger.propagate = False 以防止重复打印。

在下面的代码中，如果你删除logger.propagate = False，你会看到双重打印。

import logging
from typing import Optional

_logger: Optional[logging.Logger] = None

def get_logger() -> logging.Logger:
    global _logger
    if _logger is None:
        raise RuntimeError('get_logger call made before logger was setup!')
    return _logger

def set_logger(name:str, level=logging.DEBUG) -> None:
    global _logger
    if _logger is not None:
        raise RuntimeError('_logger is already setup!')
    _logger = logging.getLogger(name)
    _logger.handlers.clear()
    _logger.setLevel(level)
    ch = logging.StreamHandler()
    ch.setLevel(level)
    # warnings.filterwarnings("ignore", "(Possibly )?corrupt EXIF data", UserWarning)
    ch.setFormatter(_get_formatter())
    _logger.addHandler(ch)
    _logger.propagate = False # otherwise root logger prints things again


def _get_formatter() -> logging.Formatter:
    return logging.Formatter(
        '[%(asctime)s] [%(name)s] [%(levelname)s] %(message)s')

【讨论】：

这是我遇到的问题。谢谢
很好的答案；在登录到 Flask 的 app.logger 实例时，添加 logger.propagate = False 是防止在 Waitress 托管的 Flask 应用程序中重复登录的解决方案。

【解决方案6】：

如果没有安装根处理程序，对logging.debug() 的调用会调用logging.basicConfig()。这发生在我无法控制测试用例触发顺序的测试框架中。我的初始化代码正在安装第二个。默认使用我不想要的 logging.BASIC_FORMAT。

【讨论】：

我认为这就是我正在发生的事情。如何防止自动创建控制台记录器？
@Robert 这是关于确保在第一次记录调用之前使用所需的记录器进行初始化。测试框架可以掩盖这一点，但应该有办法做到这一点。此外，如果您要进行多进程处理，则必须对每个进程执行相同的操作。

【解决方案7】：

看来如果你（不小心）向记录器输出了一些东西然后配置它，那就太晚了。例如，在我的代码中，我有

logging.warning("look out)"

...
ch = logging.StreamHandler(sys.stdout)
root = logging.getLogger()
root.addHandler(ch)

root.info("hello")

我会得到类似的东西（忽略格式选项）

look out
hello
hello

所有内容都被写入标准输出两次。我相信这是因为第一次调用logging.warning 会自动创建一个新的处理程序，然后我明确添加了另一个处理程序。当我删除意外的第一个 logging.warning 调用时，问题就消失了。

【讨论】：

【解决方案8】：

我在多个进程的上下文中遇到了同样的问题。（代码参见docs，我几乎一字不差地关注它。）也就是说，来自任何子进程的所有日志消息都被复制了。

我的错误是打电话给worker_configurer()，

def worker_configurer(logging_queue):
    queue_handler = logging.handlers.QueueHandler(logging_queue)
    root = logging.getLogger()
    root.addHandler(queue_handler)
    root.setLevel(level)

在子进程中和在主进程中（因为我也希望主进程记录东西）。这导致麻烦（在我的 Linux 机器上）的原因是在 Linux 上，子进程是通过分叉启动的，因此从主进程继承了现有的日志处理程序。也就是说，在 Linux 上，QueueHandler 注册了两次。

现在，防止QueueHandler 在worker_configurer() 函数中注册两次并不像看起来那么简单：

像根记录器root 这样的记录器对象有一个handlers 属性，但它没有记录。
根据我的经验，即使root.handlers 看似包含相同的QueueHandler，在分叉后测试any([handler is queue_handler for handler in root.handlers])（身份）或any([handler == queue_handler for handler in root.handlers])（平等）是否会失败。（显然，前两个表达式可以缩写为queue_handler in root.handlers，因为in 运算符checks for both identity and equality in the case of lists。）
root logger 被 pytest 等软件包修改，所以 root.handlers 和 root.hasHandlers() 一开始就不太可靠。（毕竟它们是全局状态。）

因此，干净的解决方案是将分叉替换为生成，以从一开始就防止此类多处理错误（当然，前提是您可以忍受额外的内存占用）。或者使用不依赖全局状态的logging 包的替代方案，而是需要您进行适当的依赖注入，但我离题了...... :)

话虽如此，我最终还是做了一个相当琐碎的检查：

def worker_configurer(logging_queue):
    queue_handler = logging.handlers.QueueHandler(logging_queue)
    root = logging.getLogger()

    for handler in root.handlers:
        if isinstance(handler, logging.handlers.QueueHandler):
            return

    root.addHandler(queue_handler)
    root.setLevel(level)

显然，当我决定在其他地方注册第二个队列处理程序时，这将产生令人讨厌的副作用。

【讨论】：

【解决方案9】：

如果您尝试从父文件创建日志记录对象，也会发生这种情况。例如这是主应用文件test.py

import logging

# create logger
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)

# create console handler and set level to debug
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

# create formatter
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

# add formatter to ch
ch.setFormatter(formatter)

# add ch to logger
logger.addHandler(ch)

def my_code():
# 'application' code
    logger.debug('debug message')
    logger.info('info message')
    logger.warning('warn message')
    logger.error('error message')
    logger.critical('critical message')

下面是父文件main.py

import test

test.my_code()

这个输出只会打印一次

2021-09-26 11:10:20,514 - simple_example - DEBUG - debug message
2021-09-26 11:10:20,514 - simple_example - INFO - info message
2021-09-26 11:10:20,514 - simple_example - WARNING - warn message
2021-09-26 11:10:20,514 - simple_example - ERROR - error message
2021-09-26 11:10:20,514 - simple_example - CRITICAL - critical message

但是如果我们有一个父日志对象，那么它将被打印两次。例如如果这是父文件

import test
import logging
logging.basicConfig(level=logging.DEBUG,format='%(asctime)s - %(name)s - %(levelname)s - %(message)s')


test.my_code()

输出将是

2021-09-26 11:16:28,679 - simple_example - DEBUG - debug message
2021-09-26 11:16:28,679 - simple_example - DEBUG - debug message
2021-09-26 11:16:28,679 - simple_example - INFO - info message
2021-09-26 11:16:28,679 - simple_example - INFO - info message
2021-09-26 11:16:28,679 - simple_example - WARNING - warn message
2021-09-26 11:16:28,679 - simple_example - WARNING - warn message
2021-09-26 11:16:28,679 - simple_example - ERROR - error message
2021-09-26 11:16:28,679 - simple_example - ERROR - error message
2021-09-26 11:16:28,679 - simple_example - CRITICAL - critical message
2021-09-26 11:16:28,679 - simple_example - CRITICAL - critical message

【讨论】：

【解决方案10】：

来自文档：

"Loggers 具有以下属性和方法。请注意，Loggers 永远不应直接实例化，而应始终通过模块级函数 logging.getLogger(name)。 多次调用同名的 getLogger() 将始终返回对同一个 Logger 对象的引用。

确保不要使用相同的名称初始化记录器我建议您使用 name 作为名称参数初始化记录器即初始化记录器对象的类：

class log():
    def __init__(self,name,debbug=False) -> None:
        
        #create logger with name as a param
        self.logger = logging.getLogger(name)
        self.logger.setLevel(logging.DEBUG) 
        formatter = logging.Formatter("%(asctime)s;%(levelname)s;%(message)s",
                              "%Y-%m-%d %H:%M:%S")
        fh = logging.FileHandler("LOG.txt",'a')
        fh.setFormatter(formatter)
        fh.setLevel(logging.DEBUG)
        self.logger.addHandler(fh)
        if debbug:
            # create console handler and set level to debug
            ch = logging.StreamHandler()
            ch.setLevel(logging.DEBUG)
            # add formatter to ch
            ch.setFormatter(formatter)
            # add ch to logger
            self.logger.addHandler(ch)
            self.logger.removeHandler(fh)
    
    def get_logger(self)->logging.Logger:
        return self.logger

注意： 即使你从同名的其他模块初始化一个记录器，但从主线程，你仍然会得到相同的记录器，因此调用 .log 将记录你启动记录器类的次数。

【讨论】：

【解决方案11】：

我遇到了一个奇怪的情况，控制台日志翻了一番，但我的文件日志却没有。经过大量的挖掘，我想通了。

请注意，第三方包可以注册记录器。这是需要注意的（在某些情况下是无法避免的）。在许多情况下，第三方代码会检查是否存在任何现有的 root 记录器处理程序；如果没有 - 他们注册一个新的控制台处理程序。

我的解决方案是在根级别注册我的控制台记录器：

rootLogger = logging.getLogger()  # note no text passed in--that's how we grab the root logger
if not rootLogger.handlers:
        ch = logging.StreamHandler()
        ch.setLevel(logging.INFO)
        ch.setFormatter(logging.Formatter('%(process)s|%(levelname)s] %(message)s'))
        rootLogger.addHandler(ch)

【讨论】：

【解决方案12】：

如果您使用任何配置进行日志记录，例如 log.conf

在 .conf 文件中，您可以通过在 [logger_myLogger] 部分添加此行来实现：propagate=0

[logger_myLogger]
level=DEBUG
handlers=validate,consoleHandler
qualname=VALIDATOR
propagate=0

【讨论】：