Многоканальное логирование для python проекта

Логируй так, будто завтра сервер упадет, и только твои записи спасут мир.

Рассмотрим, как создать логгер для проекта, который предусматривает вывод сообщений и в консоль, и в файл журнала. Реализовывать его будем в форме класса Python, но сначала рассмотрим типичные особенности в интерактивном режиме.

Нашими строительными блоками будут составляющие модуля logging:

функция getLogger для получения логгера с заданным именем;
классы handler-ов: FileHandler для логирования в файл, StreamHandler для вывода в консоль, которые добавляются в полученный на предыдущем этапе логгер;
метод логгера setLevel для задания уровня вывода сообщений;
методы логгера info, debug, error, warning для вывода сообщений с заданным уровнем.

Про уровни вывода сообщений и методы я рассказывал ранее. Создадим тестовый logger:

import logging

file_handler = logging.FileHandler('journal.log')
console_handler = logging.StreamHandler()

logger = logging.getLogger('test_logger')
logger.setLevel(logging.INFO)

logger.addHandler(file_handler)
logger.addHandler(console_handler)

logger.info('test message 1')

!cat journal.log

propagate

Можно заметить 2 сообщения в консоли и одно - в журнале. Почему в консоль отправлен лишний вывод?

Поведение по умолчанию предполагает передачу сообщений вверх по иерархии к root-логгеру, который является предком всех logger-ов и обрабатывает сообщение путем вывода на консоль. Это регулируется атрибутом propagate (который по умолчанию равен True). Соответственно, чтобы остановить передачу "наверх" надо задать: logger.propagate = False:

logger.propagate = False
logger.info('test message 2')

разные хэндлеры

Для вывода списка обработчиков, которые отвечают за отправку сообщений в канал, можно обратиться к свойству logger.handlers:

logger.handlers

Если попытаться добавить одинаковые хэндлеры, то список не изменится:

logger.addHandler(file_handler)
logger.addHandler(console_handler)
logger.handlers

Однако при создании новых объектов (и с другими id, соответственно) система будет считать их другими и произойдет дублирование вывода, поэтому при двухкратном обращении к одному логгеру в нашем классе надо будет предусмотреть такое поведение:

file_handler = logging.FileHandler('journal.log')
console_handler = logging.StreamHandler()

logger.addHandler(file_handler)
logger.addHandler(console_handler)
logger.handlers

закрытие хэндлеров

По завершении работы с логгером надо удалить из него привязку к обработчикам, что можно сделать, очистив соответствующий список. Однако следует помнить о коварной ошибке при удалении handler-ов из того же списка, по которому происходит итерация:

for handler in logger.handlers:
    logger.removeHandler(handler)

logger.handlers

А так (logger.handlers[:]) создаем копию списка для итерации, поэтому результат будет пустым, и новые сообщения при обращении к логгеру не появляются:

for handler in logger.handlers[:]:
    logger.removeHandler(handler)
logger.handlers

Для корректного освобождения ресурсов (закрытия файла, сброса буферов) также рекомендуется вызывать метод close обработчиков:

file_handler.stream.closed

file_handler.close()
console_handler.close()

класс логгера

На основании описанного выше можно создать класс логгера, который одновременно выводит и в журнал, и на консоль. Также добавим удобный формат сообщений (подробнее было тут).

import logging

LOG_FN = 'journal.log'

class ActivityLogger():

    def __init__(self, level=logging.INFO, encoding='utf-8'):

        self.level = level
        self.file_handler = logging.FileHandler(LOG_FN, encoding=encoding)
        self.console_handler = logging.StreamHandler()

    def get_logger(self, name):

        file_formatter = logging.Formatter(f'%(asctime)s \nMODULE:{name}, LEVEL:%(levelname)s, LINE:%(lineno)s, MSG:%(message)s\n')
        cons_formatter = logging.Formatter(f'%(asctime)s \n%(lineno)s %(message)s\n\n')

        # Применяем форматтер к обоим Handler
        self.file_handler.setFormatter(file_formatter)
        self.console_handler.setFormatter(cons_formatter)

        # Создаем объект logger и применяем к нему оба Handler
        logger = logging.getLogger(name)
        logger.setLevel(self.level)

        if len(logger.handlers)==0:
            logger.addHandler(self.file_handler)
            logger.addHandler(self.console_handler)

        # Disable propagation of messages to the root logger
        logger.propagate = False

        return logger

    def close_logger(self, logger):

        # import pdb;pdb.set_trace()
        for handler in logger.handlers[:]:
            logger.removeHandler(handler)

        self.file_handler.close()
        self.console_handler.close()

Для демонстрационных целей имитируем наличие проекта и класс logger-а в отдельном модуле:

скрипты передают свои имена в журнал

Теперь создадим 2 одинаковых скрипта, использующих логгер:

t = r'''
from constants import ActivityLogger

try:

    logger = ActivityLogger().get_logger(__file__)
    logger.info(f'тестовое сообщение')

    ActivityLogger().close_logger(logger)

except Exception:
    logger.exception('ВОЗНИКЛО ИСКЛЮЧЕНИЕ!!!')
    ActivityLogger().close_logger(logger)

'''

with open('project/script1.py', 'wt') as f:
    f.write(t)

with open('project/script2.py', 'wt') as f:
    f.write(t)

Запустим оба скрипта и увидим, что сообщения корректно выводятся и в журнал и на консоль с указанием файла-источника, что удобно для отладки:

нет дублирования при многократном обращении к логгеру

Так как мы предусмотрели проверку наличия обработчиков (в блоке - if len...), при обращении к одному и тому же логгеру дважды сообщения не дублируются:

from project.constants import ActivityLogger
import logging

logger1 = ActivityLogger(level = logging.ERROR).get_logger('note1')
logger1.error("тестовое сообщение note 1")

print(logging.getLogger('note1').handlers)

logger2 = ActivityLogger().get_logger('note1')

logger2.error("тестовое сообщение note 2")
print(logger2.handlers)

Следует отметить, что вместо проверки наличия в логгере обработчиков, можно было бы задать их на уровне переменных класса (а не экземпляра), тогда они бы при повторном добавлении id не меняли и, соответственно, каналы бы не дублировались:

import logging

LOG_FN = 'journal.log'

class ActivityLogger():

    file_handler = logging.FileHandler(LOG_FN, encoding='utf-8')
    console_handler = logging.StreamHandler()

    def __init__(self, level=logging.INFO):
        self.level = level

    def get_logger(self, name):

        file_formatter = logging.Formatter(f'%(asctime)s \nMODULE:{name}, LEVEL:%(levelname)s, LINE:%(lineno)s, MSG:%(message)s\n')
        cons_formatter = logging.Formatter(f'%(asctime)s \n%(lineno)s %(message)s\n\n')

        # Применяем форматтер к обоим Handler
        self.file_handler.setFormatter(file_formatter)
        self.console_handler.setFormatter(cons_formatter)

        # Создаем объект logger и применяем к нему оба Handler
        logger = logging.getLogger(name)
        logger.setLevel(logging.INFO)

        logger.addHandler(self.file_handler)
        logger.addHandler(self.console_handler)

        # Disable propagation of messages to the root logger
        logger.propagate = False

        return logger

    def close_logger(self, logger):

        for handler in logger.handlers[:]:
            logger.removeHandler(handler)

        self.file_handler.close()
        self.console_handler.close()

параллельная работа с несколькими логгерами

Если мы работаем с двумя логгерами, то закрытие одного не влияет на работу другого:

from project.constants import ActivityLogger

logger1 = ActivityLogger().get_logger('note1')
logger1.info("тестовое сообщение note 1")

logger2 = ActivityLogger().get_logger('note2')
logger2.info("тестовое сообщение note 2")

#logger #logging #activitylogger