Отделяйте сбор логов от обработки

Если ваша программа состоит из одного файла, то у вас нет проблем с логированием. Можете использовать модуль logging как хотите, в любом случае у вас всё получится. С большими программами дела обстоят сложнее и именно здесь проявляется настоящая сила модуля logging. В этой статье вы узнаете как ей воспользоваться. Перед чтением ознакомьтесь с вводной статьей о логировании в Python.

Рассмотрим пример. Есть два бота, один для ВКонтакте и другой для Telegram. Они оба общаются с базой данных. В репозитории лежат четыре файла:

• vk_bot.py — бот для VK;
• tg_bot.py — бот для Telegram;
• load_data_to_db.py — служебный скрипт для загрузки данных в БД;
• db.py — вспомогательный код, упрощающий работу с базой данных

Первых три файла — это самостоятельные программы для запуска из консоли. Для работы с базой данных каждая из программ импортируют и используют четвертый файл db.py.

Если с базой данных возникают проблемы, то полезно иметь под рукой логи. Добавим их в файл db.py:

import logging

def save(data):
    try:
        ...
        logging.debug('Send data to db')
    except ConnectionError:
        ...
        logging.error('Lost connection to DB')

Всё выглядит просто и незатейливо. Но вот вы запускаете ботов VK и Telegram на сервере и теперь вместо вывода в консоль хотите отправлять логи в чат Telegram. Вы добавляете в код новый класс TelegramLogsHandler — обработчик логов на базе logging.Handler. Теперь код выглядит так:

import logging

class TelegramLogsHandler(logging.Handler):

    def __init__(self, tg_bot, chat_id):
        super().__init__()
        self.chat_id = chat_id
        self.tg_bot = tg_bot

    def emit(self, record):
        log_entry = self.format(record)
        self.tg_bot.send_message(chat_id=self.chat_id, text=log_entry)

logger = logging.getLogger('Logger')
logger.setLevel(logging.WARNING)
logger.addHandler(TelegramLogsHandler(tg_bot))

def save(data):
    try:
        ...
        logger.debug('Send data to db')
    except ConnectionError:
        ...
        logger.error('Lost connection to DB')

Теперь логи сыпятся в чатик, и вы моментально узнаете о проблемах. Это победа!

А как теперь поведёт себя скрипт для загрузки данных load_data_to_db.py? Это консольная программа, её запускает сам программист вручную из терминала, но, раз она тоже импортирует db.py, её логи также сыпятся в чат. Очень cтранное поведение…

Теперь поставьте себя на место разработчика популярной библиотеки, например Requests. Вам очень пригодилось бы логирование, ведь с ним так просто отлаживать код. Проходит время, в консоли собирается море отладочной информации, и пользователи библиотеки начинают бунтовать. Может, кому-то логи и нужны, но в обычной консольной программе пять экранов непонятных логов убьют любой пользовательский интерфейс. На их фоне будет невозможно заметить полезные сообщения. Что же делать?

Архитектура библиотеки logging

Ключевая идея в том, чтобы разделить обязанности. Пускай обычные библиотеки пишут в логи что хотят, но ни в коем случае не трогают настройки. А основная программа — тот скрипт, что вы непосредственно запускаете из консоли — настроит работу всех объектов Logger сразу для всех подключенных библиотек.

В примере с ботом таких исполняемых программ сразу три: vk_bot.py, tg_bot.py и load_data_to_db.py — каждый из них будет содержать свои настройки. Вот иллюстрация принципа работы одного скрипта tg_bot.py:

Пример кода, файл db.py:

import logging

logger = logging.getLogger('database')

def save(data):
    try:
        ...
        logger.debug('Send data to db')
    except ConnectionError:
        ...
        logger.error('Lost connection to DB')

Запускаемый файл tg_bot.py:

import logging
import db

...
class TelegramLogsHandler(logging.Handler):

    def __init__(self, tg_bot, chat_id):
        super().__init__()
        self.chat_id = chat_id
        self.tg_bot = tg_bot

    def emit(self, record):
        log_entry = self.format(record)
        self.tg_bot.send_message(chat_id=self.chat_id, text=log_entry)

if __name__ == '__main__':
    logger = logging.getLogger('database')
    logger.setLevel(logging.WARNING)
    logger.addHandler(TelegramLogsHandler(tg_bot))
    ...

Обратите внимание, что в обоих файлах происходит вызов функции logging.getLogger('database'). В одном случае функция создает новый объект Logger, а в другом возвращает ранее созданный, и получаются что оба файла работают с одним и тем же объектом. Здесь дело в названии 'database'. Функция getLogger ведёт учёт всех ранее созданных объектов Logger и запрещает создание двух разных Logger с одинаковыми названиями. Поэтому в каждом файле может быть свой отдельный вызов getLogger('database'), но все они возвращают один и тот же объект.

Функция getLogger возвращает один и тот же объект

Всю настройку логов: фильтрацию, форматирование и что куда выводить — собираем в основной программе внутри ifmain или def main. Следуем нескольким правилам:

• Подключенные библиотеки и модули отправляют сообщения в именованные логеры
• Библиотеки и модули не вмешиваются в настройку логирования
• У каждого запускаемого скрипта свой набор настроек логирования, даже если это копипаста

В трех исполняемых скриптах vk_bot.py, tg_bot.py и load_data_to_db.py будет похожий код по настройке логирования. Чтобы избежать большого количества повторяющегося кода, можно воспользоваться методом dictConfig.

Стандартный шаблон кода

Библиотека logging очень гибкая и использовать её можно по-разному, но в большинстве случаев достаточно взять стандартный шаблон кода:

import logging

logger = logging.getLogger(__file__)


def alarm():  # пример функции, использующей logger
    logger.warning('Alarm was called')
    # ...


if __name__ == '__main__':
    logging.basicConfig(level=logging.ERROR)
    logger.setLevel(logging.DEBUG)
    # ...
    # остальные настройки логирования
    
    alarm()

Функция alarm() в коде приведена ради примера и не особо важна. А вот на глобальную переменную logger стоит обратить внимание. Она определена в шапке файла, там же где находится вызов функции getLogger. В шапке файла опасно вызывать функции, ведь в случае поломки они намертво заблокируют импорт модуля. Но к функции getLogger это не относится. Она не имеет побочных эффектов и не мешает импорту файла. Она безопасна.

Вызовы basicConfigи setLevel в отличие от getLogger меняют настройки программы и её поведение, а потому должны быть спрятаны внутри ifmain. Еще лучше — завести функцию def main и перенести настройки туда.

Что читать дальше?

Прочитайте статьи с других сайтов:

• Логирование в Python. Пример с dictConfig
• Advanced Logging Tutorial