Вход в python с настройкой JSON - что-то регистрируется более одного раза?

Question

Я использую Python 3 и изучаю, как использовать ведение журнала. Я смотрю на код от https://docs.python.org/3/howto/logging-cookbook.html и https://fangpenlin.com/posts/2012/08/26/good-logging-practice-in-python/.

Я попытался изменить часть первых двух блоков кода в первой ссылке, основной модуль и вспомогательный модуль, чтобы использовать файл 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, если да, то он передаст запись своему родительскому регистратору (в данном случае корневому регистратору), который также будет обрабатывать запись.

Это также отображается на блок-схеме , вы можете проверить это, если хотите.

Теперь вы, вероятно, уже можете догадаться, что произойдет, если я настрою оба регистратора следующим образом:

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

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

В каждой входящей записи журнала my-special-logger записывает запись в debug.log, затем передает запись дальше до root, что также записывает запись в debug.log. Таким образом, запись появится дважды в конце.

иерархия пространства имен модуля

Однако возникает вопрос: почему в журнале отладки есть три копии некоторых записей? Ответ можно найти в Advanced Logging Tutorial :

Каждый экземпляр [logger] имеет имя, и они концептуально расположены в иерархии пространства имен, используя точки (точки) в качестве разделителей. Например, регистратор с именем scan является родителем регистраторов scan.text, scan.html и scan.pdf.

Теперь вы можете оценить иерархию логгера в вашем коде:

root                                                <b>-> writes to debug.log</b>
└── spam_application
     └── spam_application.auxiliary                <b>-> writes to debug.log</b>
          └── spam_application.auxiliary.Auxiliary <b>-> writes to debug.log</b>

решение

Преимущество распространения записей в иерархии журналов заключается в том, что вам не нужно повторять конфигурацию для каждого регистратора. Итак, когда ваше приложение должно войти в систему debug.log, добавьте debug_file_handler к корневому регистратору один раз, и он уже будет обслуживать все другие регистраторы, независимо от того, добавляете ли вы их в конфигурацию или нет.

Таким образом, ваша первоначальная конфигурация может быть уменьшена до:

{
    "version": 1,
    "disable_existing_loggers": false,
    "formatters": { ... },

    "handlers": {
        "debug_file_handler": { ... }
    },

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

Альтернативой этому будет передача "propagate": false каждому явно настроенному регистратору, чтобы сообщения не обрабатывались несколько раз debug_file_handler:

{
    "version": 1,

    ...

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

    ...