使用 JSON 配置登录 python - 事情被记录不止一次？

Question

我正在使用 Python 3，并且正在学习如何使用日志记录。我正在查看来自https://docs.python.org/3/howto/logging-cookbook.html和https://fangpenlin.com/posts/2012/08/26/good-logging-practice-in的代码-蟒蛇/。

我尝试修改第一个链接中的前两个代码块的一部分，主模块和辅助模块，以使用 JSON 文件。但是当我运行主文件时，我得到某些日志输出重复了 3 次，但我不知道为什么，或者要更改什么以使行不重复但仍输出到同一个 .log 文件。

.log 文件： .log 文件输出

我的 JSON 文件：

{
"version": 1,
"disable_existing_loggers": false,
"formatters": {
    "simple": {
        "format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
    }
},

"handlers": {
    "debug_file_handler": {
        "class": "logging.FileHandler",
        "level": "DEBUG",
        "formatter": "simple",
        "filename": "debug.log",
        "encoding": "utf8"
    }
},

"loggers": {
    "spam_application.auxiliary.Auxiliary": {
        "level": "DEBUG",
        "handlers": ["debug_file_handler"]
    },
    "spam_application.auxiliary": {
        "level": "DEBUG",
        "handlers": ["debug_file_handler"]
    }

},

"root": {
    "level": "DEBUG",
    "handlers": ["debug_file_handler"]
}}

对于主文件：

import auxiliary_module
import os
import json
import logging.config

with open('python_logging_configuration.json', 'r') as logging_configuration_file:
config_dict = json.load(logging_configuration_file)

logging.config.dictConfig(config_dict)

logger = logging.getLogger(__name__)

logger.info('creating an instance of auxiliary_module.Auxiliary')
a = auxiliary_module.Auxiliary()
logger.info('created an instance of auxiliary_module.Auxiliary')
logger.info('calling auxiliary_module.Auxiliary.do_something')
a.do_something()
logger.info('finished auxiliary_module.Auxiliary.do_something')
logger.info('calling auxiliary_module.some_function()')
auxiliary_module.some_function()
logger.info('done with auxiliary_module.some_function()')

而对于辅助模块文件

module_logger = logging.getLogger('spam_application.auxiliary')

class Auxiliary:
def __init__(self):
    self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
    self.logger.info('creating an instance of Auxiliary')
    self.logger.debug('debug in Auxiliary')

def do_something(self):
    self.logger.info('doing something')
    a = 1 + 1
    self.logger.info('done doing something')

def some_function():
    module_logger.info('received a call to "some_function"')

提前致谢

Answer 1

简答

这是因为一个名为propagate的特殊属性。它是一个标志，用于确定记录器是否应将日志记录传递给其父记录器 ( propagate=True) 或不 ( propagate=False)。您需要从中间记录器中删除通用配置，只留下唯一的东西，或者传递"propagate": false给所有记录器。

长答案

记录器层次结构和日志记录传播

Python 中的所有记录器都是按层次结构组织的：总有一个根记录器，当您getLogger不带名称调用时返回：

root_logger = logging.getLogger()

您使用名称创建的所有记录器都是根记录器的子项，因此

my_logger = logging.getLogger('my-special-logger')

有root_logger作为父母。现在，当你打电话my_logger.info('Hello world')时，会发生以下情况：my_logger将

• 处理记录本身
• 检查它是否已propagate设置为True，如果是，则它将记录传递给其父记录器（在本例中为根记录器），它也将处理该记录。

这也在日志流图中可视化，您可以根据需要查看。

现在，您可能已经猜到如果我这样配置两个记录器会发生什么：

root_logger = logging.getLogger()

在每个传入的日志记录上，my-special-logger将记录写入debug.log，然后将记录进一步传递到root，这也将记录写入debug.log。所以记录最后会出现两次。

模块命名空间层次结构

但是，问题是：为什么调试日志中有一些记录的三个副本？答案可在高级日志记录教程中找到：

每个 [logger] 实例都有一个名称，它们在概念上排列在命名空间层次结构中，使用点（句点）作为分隔符。例如，一个名为记录scan是记录器的父scan.text，scan.html和scan.pdf。

所以现在您可以在代码中评估记录器层次结构：

my_logger = logging.getLogger('my-special-logger')

解决方案

在日志层次结构中传播记录的优点是您不需要为每个记录器重复配置。因此，当您的应用程序应该登录到 时debug.log，将debug_file_handler根记录器添加一次，它已经为所有其他记录器提供服务，无论您是否将它们添加到配置中。

这样，您的初始配置可以简化为：

"loggers": {
    "my-special-logger": {
        "handlers": ["debug_file_handler"]
    },
},

"root": {
    "handlers": ["debug_file_handler"]
}

另一种方法是传递"propagate": false给每个显式配置的记录器，这样消息就不会被 多次处理debug_file_handler：

root                                                -> writes to debug.log
??? spam_application
     ??? spam_application.auxiliary                -> writes to debug.log
          ??? spam_application.auxiliary.Auxiliary -> writes to debug.log