简易Python日志配置中出现重复输出问题

Question

我正在按照以下方式设置Python日志记录：

def setup_logging():
    loggers = (logging.getLogger("amcat"), logging.getLogger("scrapers"),logging.getLogger(__name__))
    filename = "somefile.txt"
    sys.stderr = open(filename, 'a')
    handlers = (logging.StreamHandler(sys.stdout),logging.FileHandler(filename))
    formatter = AmcatFormatter(date = True)

    for handler in handlers:
        handler.setLevel(logging.INFO)
        handler.setFormatter(formatter)

    for logger in loggers:
        logger.propagate = False
        logger.setLevel(logging.INFO)
        for handler in handlers:        
            logger.addHandler(handler)
    logging.getLogger().handlers = []

有2个主要模块记录器已启用，它们都应该记录到控制台和文件中。错误将被重定向到文件中（理想情况下，错误也会在控制台中显示，但我尚未实现此功能）。

紧接着，我检查一下事情是否正确：

should_work = [
    "amcat.scraping.scraper",
    "amcat.scraping.htmltools",
    "amcat.scraping.controller",
    "__main__"]

loggerdict = logging.Logger.manager.loggerDict #all loggers
for name, logger in loggerdict.items():
    if name in should_work:
        print("\nlogger: "+name)
        #iterate through parents see if effective handlers are set correctly
        print(effectivehandlers(logger))
        #test logger
        logger.info("test for {name}".format(**locals()))

def effectivehandlers(logger):
    handlers = logger.handlers
    while True:
        logger = logger.parent
        handlers.extend(logger.handlers)
        if not (logger.parent and logger.propagate):
            break
    return handlers

控制台输出：

logger: __main__
[<logging.StreamHandler object at 0x3425d50>, <logging.FileHandler object at 0x3425dd0>]
[2013-10-24 10:27:30 daily.py:133 INFO] test for __main__

logger: amcat.scraping.controller
[<logging.StreamHandler object at 0x3425d50>, <logging.FileHandler object at 0x3425dd0>]
[2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.controller
[2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.controller

logger: amcat.scraping.htmltools
[<logging.StreamHandler object at 0x3425d50>, <logging.FileHandler object at 0x3425dd0>]
[2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.htmltools
[2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.htmltools

logger: amcat.scraping.scraper
[<logging.StreamHandler object at 0x3425d50>, <logging.FileHandler object at 0x3425dd0>]
[2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.scraper
[2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.scraper

这里是文件输出：

[2013-10-24 10:27:30 daily.py:133 INFO] test for __main__
[2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.controller
[2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.controller
[2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.htmltools
[2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.htmltools
[2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.scraper
[2013-10-24 10:27:30 daily.py:133 INFO] test for amcat.scraping.scraper

正如您所看到的，尽管禁用了传播并确保没有重复的处理程序存在，但输出结果仍为双倍。这里出了什么问题？

- ToonAlfrink

---

我不确定您要实现什么，您需要澄清您的需求，并给出一小段代码示例并给出预期的日志输出。 （例如：执行一个简单的log.info（'message'），然后说一下您想要输出到控制台的内容，您想要输出到文件的内容。）您想如何使用这些多个记录器？ 这看起来有些冗余，您只需要1个记录器，然后可以有2个处理程序... - Inbar Rose

显然，我正在尝试避免重复的输出。就我所提供的代码样例而言，我认为它很清晰地表达了我想要如何配置记录日志。 - ToonAlfrink

如果这么明显，这么清楚，我就不会问了。你只是在这里倾倒你的代码，几乎没有解释任何东西，基本上只是说“这里的代码正常工作，但我不想让它这样...我该怎么办？”好吧...如果你不告诉我你到底想做什么，或者你是如何做的...那么帮助你就很难了。 - Inbar Rose

2 major module loggers are enabled, they're both supposed to log to the console aswell as a file. - ToonAlfrink

Answer 1

基本上，当你的一个子记录器显示一条消息时，它会沿着层次结构向上传递，父记录器也会记录相同的内容。

要取消这种行为，您可以添加以下内容：

logger.propagate = False

注意：您的日志记录器必须使用非空字符串的名称，例如getLogger（'my name'）

当它到达子级时，它不会再命中父级。
这里有一些关于这种行为的文档。

- Paco

---

事实上，子记录器没有处理程序，并将它们的消息传递给父级来处理。 - ToonAlfrink

即使它们有处理程序，行为仍然是相同的。 - Paco

重要提示：至少在Python 3.6版本中，为了让.propagate=False生效，你的日志记录器必须使用非空字符串作为名称，因此.getLogger()将不起作用，也不能使用.getLogger('')。必须使用.getLogger('my name')。 - kakyo

谢谢，这是我情况下的正确答案。 - HCLivess

如果您正在从配置文件中配置日志记录，则也可以在文件中设置propagate的值，而不是在代码中设置。它是特定记录器（例如“logger_abc”）的属性，因此，在该记录器的部分下 - 例如[logger_abc] - 您需要添加一行：propagate=0。这些值为0和1，而不是False和True，这只是配置解析的方式。 - Cornel Masson

可以工作，但如果你在pytest中使用caplog会导致测试失败。 - natielle

Answer 2

我搞清楚了，感谢Paco指导我走向正确的方向。

原来，在调用getLogger时，会向其添加处理程序：

>>> print(effectivehandlers(logger))
[<logging.StreamHandler object at 0x305ad90>, <logging.FileHandler object at 0x305ae10>]
>>> logging.getLogger(name) #the same logger
<logging.Logger object at 0x7fa08fb9b2d0>
>>> print(effectivehandlers(logger))
[<logging.StreamHandler object at 0x305ad90>, <logging.FileHandler object at 0x305ae10>, <logging.StreamHandler object at 0x305ad90>, <logging.FileHandler object at 0x305ae10>]

现在，子元素和父元素都有相同的处理程序，因此会出现重复输出。

- ToonAlfrink

---

当调用logging.info或其兄弟之一时，似乎也会发生这种情况。 - ToonAlfrink

根据记录，logging.info()等函数会调用basicConfig()函数，如果没有句柄存在，则会添加一个控制台句柄。这些模块级别的函数不应与其他配置机制混合使用 - 它们适用于最简单的用法。 - Vinay Sajip

是的。@ToonAlfrink，这个解决方案对我帮助很大。添加一个流处理程序（然后将格式化程序添加到该处理程序中）是我所需要的解决方案。在我的情况下，我还需要设置Logger.propogate = False。谢谢！ - Will Charlton

我理解为什么你会出现双重日志记录，但是你是如何解决这个问题的？你停止在代码中到处调用 logging.getLogger 了吗？ - Jay

Answer 3

对于Python 2.7

logging.handlers.pop()

参考用户“radtek”： Python日志记录 - 消息出现两次

- Felipe Illanes