Почему дублируются логи при использовании библиотеки logging?

Question

[Руслан]

Необходимо организовать логирование для простейшего агента парсинга почты, написал такой скрипт:

#!/usr/bin/python3 -u

import logging

from logging import config
from time import sleep

LOGGING_CONFIG = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'standard': {
            'format': '[%(asctime)s] %(levelname)s | %(name)s: %(message)s',
            'datefmt': '%Y-%m-%d %H:%M:%S',
        },
    },
    'handlers': {
        'init': {
            'level': 'INFO',
            'formatter': 'standard',
            'class': 'logging.StreamHandler',
            'stream': 'ext://sys.stdout',
        },
        'getmail': {
            'level': 'INFO',
            'formatter': 'standard',
            'class': 'logging.StreamHandler',
            'stream': 'ext://sys.stdout',
        },
        'parse': {
            'level': 'INFO',
            'formatter': 'standard',
            'class': 'logging.StreamHandler',
            'stream': 'ext://sys.stdout',
        },
    },
    'loggers': {
        '': {
            'level': 'NOTSET',
            'handlers': ['init', 'getmail', 'parse'],
            'propagate': 1,
        }
    },
}

def agent_getmail():
    sleep(1)
    logger = logging.getLogger('getmail')
    logger.debug('getmail - debug')
    logger.info('getmail - info')
    logger.error('getmail - error')
    return True


def agent_parse():
    sleep(1)
    logger = logging.getLogger('parse')
    logger.debug('parse - debug')
    logger.info('parse - info')
    logger.error('parse - error')
    return True

def main():
    logging.config.dictConfig(LOGGING_CONFIG)

    logger = logging.getLogger('init')
    logger.debug('init - debug')
    logger.info('init - info')
    logger.error('init - error')
    agent_getmail()
    agent_parse()

if __name__ == "__main__":
    main()

При запуске получаю дублирование сообщений на столько же сколько хэндлеров:

[2020-12-22 12:05:33] INFO | init: init - info
[2020-12-22 12:05:33] INFO | init: init - info
[2020-12-22 12:05:33] INFO | init: init - info
[2020-12-22 12:05:33] ERROR | init: init - error
[2020-12-22 12:05:33] ERROR | init: init - error
[2020-12-22 12:05:33] ERROR | init: init - error
[2020-12-22 12:05:34] INFO | getmail: getmail - info
[2020-12-22 12:05:34] INFO | getmail: getmail - info
[2020-12-22 12:05:34] INFO | getmail: getmail - info
[2020-12-22 12:05:34] ERROR | getmail: getmail - error
[2020-12-22 12:05:34] ERROR | getmail: getmail - error
[2020-12-22 12:05:34] ERROR | getmail: getmail - error
[2020-12-22 12:05:35] INFO | parse: parse - info
[2020-12-22 12:05:35] INFO | parse: parse - info
[2020-12-22 12:05:35] INFO | parse: parse - info
[2020-12-22 12:05:35] ERROR | parse: parse - error
[2020-12-22 12:05:35] ERROR | parse: parse - error
[2020-12-22 12:05:35] ERROR | parse: parse - error

Что я неправильно указал в конфиге? Делал вроде все по ману.

Answer 1

[Сергей П]

Так вы, судя по конфигу, именно этого и хотите. У вас по факту один логгер, который жрёт всё подряд и передает без разбора трем хендлерам.
Вы запутались в именах. Имя хендлера не фильтрует логи. Вы создаете именованные логгеры в коде, но по этим именам нигде не фильтруете.
Для сности и прозрачности рекомендую именовать хендлеры в конфиге с префиксом "handler_" или как-то так. Чтобы не было соблазно ошибиться в именах. Явное лучше неявного
Вам в конфиге нужно сделать три логера, каждый из которых будет фильтровать свои логи и отдавать своему хендлеру.

Да, похоже вы не правильно поняли суть хендлеров.
Фильтруют сообщения логгеры, хендлеры их обрабатывают.
В вашем случае достаточно было одного хендлера. Несколько нужны на случай, если бы вам помимо stdout некоторые логи нужно было бы отправлять по почте, некоторые особенным образом форматировать и пихать в отдельный файл (например важные ошибки), некоторые гасить и никуда не выводить, некоторые отправлять через телеграм-бота в чат.

LOGGING_CONFIG = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'standard': {
            'format': '[%(asctime)s] %(levelname)s | %(name)s: %(message)s',
            'datefmt': '%Y-%m-%d %H:%M:%S',
        },
    },
    'handlers': {
        'std': {
            # 'level': 'INFO',
            'formatter': 'standard',
            'class': 'logging.StreamHandler',
            'stream': 'ext://sys.stdout',
        },
    },
    'loggers': {
        'init': {
            'level': 'DEBUG',
            'handlers': ['std'],
            'propagate': 1,
        },
        'parse': {
            'level': 'DEBUG',
            'handlers': ['std'],
            'propagate': 1,
        },
        'getmail': {
            'level': 'DEBUG',
            'handlers': ['std'],
            'propagate': 1,
        },
    },
}

Comments

[Руслан]

Огромное Вам спасибо. Наконец я понял что к чему. И теперь понятно что для одного и того же именованного логера можно сделать разные хэндлеры (например stdout и файл) с разным уровнем регистрации.

Вот этот конфиг теперь правильный? Или я не до конца уловил мысль?

LOGGING_CONFIG = {
    'version': 1,
    'disable_existing_loggers': True,
    'formatters': {
        'standard': {
            'format': '[%(asctime)s] %(levelname)s | %(name)s: %(message)s',
            'datefmt': '%Y-%m-%d %H:%M:%S',
        },
    },
    'handlers': {
        'handler_init': {
            'level': 'INFO',
            'formatter': 'standard',
            'class': 'logging.StreamHandler',
            'stream': 'ext://sys.stdout',
        },
        'handler_getmail': {
            'level': 'DEBUG',
            'formatter': 'standard',
            'class': 'logging.StreamHandler',
            'stream': 'ext://sys.stdout',
        },
        'handler_parse': {
            'level': 'INFO',
            'formatter': 'standard',
            'class': 'logging.StreamHandler',
            'stream': 'ext://sys.stdout',
        },
    },
    'loggers': {
        '': {
            'level': 'NOTSET',
            'propagate': 1,
        },
        'init': {
            'level': 'NOTSET',
            'handlers': ['handler_init'],
            'propagate': 1,
        },
        'getmail': {
            'level': 'NOTSET',
            'handlers': ['handler_getmail'],
            'propagate': 1,
        },
        'parse': {
            'level': 'NOTSET',
            'handlers': ['handler_parse'],
            'propagate': 1,
        },     
    },
}

[Сергей П]

Руслан, да, так лучше. Не знаю чего вы там хотели добиться, но теперь можно придумать смысл такому конфигу=)

[Руслан]

Сергей Паньков, Да все просто, мне нужно что бы при работе моего агента в докере, в stdout уходили только WARNING и выше (для локального просмотра в docker logs), а в отдельный хэндлер (еще не изучил как это делается (может Вы наставите на путь истинный? :D) писались с уровнем DEBUG и уходили через Интернет в ELK, который будет на удаленном хосте от агентов. Агенты будут разбросаны по разным местам и каждый раз бегать я к ним не смогу, а мне нужно мониторить на первых парах что там с ними творится). А именованные логи делаю для того что бы более гибко управлять уровнем на разных этапах обработки и сразу из журнала видеть в какой части агента проблемы.
Но предложенный Вами конфиг понятнее и не избыточен как мой, взял на заметку, спасибо!