Python: Логируем как профессионалы

Часто вижу, что помимо обработки исключений, люди мучаются кое с чем еще, а именно с логированием.

Большинство людей не знают, что писать в логи, поэтому решают логировать все, что угодно, думая, что все подряд – это в любом случае лучше, чем ничего, и, в конечном итоге, просто создают шум. А шум – это информация, которая никак не помогает вашей команде понять, в чем дело и как решить проблему.

Более того, я не думаю, что эти люди могут уверенно пользоваться уровнями логирования, поэтому используют по умолчанию logger.info везде (если не пишут print).

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

Цель этой статьи – разъяснить, что такое логирование и как вы должны его реализовывать. Я постараюсь привести содержательные примеры и обеспечить вас гибкими эмпирическими приемами, которые следует использовать при логировании в любом приложении, которое вы когда-либо будете создавать.

Введение

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

• Пользователи могут подключать несколько интеграций к ресурсам (например, GitHub, Slack, AWS и т.д.)

• Ресурсы уникальны в зависимости от интеграции (например, репозитории списков с GitHub, диалоги из Slack, экземпляры списков EC2 из AWS и т.д.)

• Каждая интеграция уникальна, имеет свой набор сложностей, конечных точек, шагов и т.д.

• Каждая интеграция может привести к различным ошибкам, которые могут возникнуть в любое время (например, неверная аутентификация, ресурс не существует и т.д.)

Я не буду сосредотачиваться на проблемах поддержки таких интеграций, просто пронаблюдаем за тем, как это работает. 

Природа логирования: хорошее логирование имеет значение

Для начала давайте проанализируем характеристики логов.

Логи должны быть:

• Наглядными;

• Контекстными;

• Реактивными.

«Наглядными» мы их называем потому, что они предоставляют вам какую-то информацию, «контекстными», потому что они дают вам общее представление о том, как обстоят дела на данный момент времени. И наконец, «реактивными» они являются потому, что они позволяют вам предпринимать действия только после того, как что-то произошло (даже если ваши логи отправляются/получаются в режиме реального времени, на самом деле вы не можете изменить то, что произошло только что).

Если вы не будете учитывать природу логов, то будете производить только шум, что снизит вашу производительность.

Дальше я приведу несколько примеров, основанных на системе, которую мы определили выше:

Если вы зададите описание, к примеру «operation connect failed», но не добавите контекст, трудно будет понять, какая из интеграций не отработала, кто пострадал, на каком этапе подключения произошел сбой, поэтому и среагировать вы не можете. В конечном итоге вы будете копаться в тонне логов без малейшего представления о том, где может быть проблема.

О, а еще не стоит недооценивать способность разработчика испортить описание. Сделать это легко, просто отправив поверхностные сообщения без какого-либо контекста, например «An error happened» или «An unexpected exception was raised». Если я прочту такое, то даже не пойму, на что повлияла ошибка, потому что не буду знать, ЧТО конкретно произошло. Так что да, можно сломать даже основной смысл логов. 

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

Когда нужно логировать?

Чтобы логи оставались реактивными, вам нужно логировать «события». Сделайте их такими же понятными и удобными для чтения, как эта статья. Возможно, вы не прочитали каждую строку, которую я написал выше, но вы все равно можете продолжить дальше, пропустить ненужные разделы и сосредоточиться на том, что привлекло ваше внимание. Логи должны быть такими же.

Есть эмпирическое правило построение логов:

• В начале соответствующих операций или потоков (например, при подключении к сторонним сервисам и т.д.);

• При любом достигнутом прогрессе (например, успешная аутентификация, получен валидный код ответа и т.д.);

• При завершении операции (успешном или неудачном).

Логи должны рассказывать вам историю, у каждой истории есть начало, середина и конец.

Будьте осторожны с релевантностью, добавлять логи проще, чем удалять их, ведь все, что нерелевантно – шум.

Что логировать?

Чтобы логи были наглядными и контекстными, нужно предоставлять правильный набор информации, и я не могу сказать, какая информация будет являться таковой, не зная вашего случая. Давайте вместо этого воспользуемся нашим примером.

Рассмотрим интеграцию с AWS в качестве примера. Было бы круто иметь следующие сообщения:

Хороший пример логов  

Сообщение	Понимание картины	Контекст
Connecting to AWS	Началась операция с AWS	Атрибуты лога должны позволить мне выяснить, кто его вызвал
Retrieved instances from all regions	Был достигнут существенный прогресс	-
Connection to AWS has been successful	Операция с AWS завершилась	Атрибуты лога должны позволить мне найти сущности, на которые операция произвела положительный эффект

Пример логов об ошибках

Допустим, что извлечь экземпляры из региона af-south-1 не удалось из-за какой-то внезапной ошибки в этом регионе.

Сообщение	Понимание картины	Контекст
Connecting to AWS	Началась операция с AWS	Атрибуты лога должны позволить мне выяснить, кто его вызвал
Failed to retrieve instances from regions af-south-1 when connecting to AWS for user X	Операция AWS не завершена, произошел сбой в регионе af-south-1, пострадал пользователь X	Я должен иметь возможность увидеть трассировку стека ошибки, чтобы понять, почему извлечение не удалось

В обоих случаях, я могу отследить, когда произошло какое-то событие (в логах есть отметки о времени), что именно произошло и кто от этого пострадал.

Я решил не указывать пользователя при начале и успешном завершении операции, потому что это не имеет значения (ведь это шум), поскольку:

• Если я знаю, что что-то запустилось, но не знаю результата выполнения, то что я могу сделать?

• Если все хорошо, то зачем беспокоиться?

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

С другой стороны, логи об ошибках кажутся более подробными, и так и должно быть! Чтение таких логов дает достаточно уверенности, чтобы немедленно перейти к действиям:

• Попросите разработчика проверить статус AWS в регионе af-south-1, и по возможности сделайте sanity check.

• Свяжитесь с пользователем Х и сообщите ему, что вам известно о проблеме в этом регионе.

Ключевой момент следующий: вы можете отреагировать сразу и для этого вам не требуется более глубокого изучения ситуации. Вы знаете все, что вам нужно, и можете немедленно принять меры для уменьшения ущерба. Разработчикам, возможно, потребуется углубиться в трассировку стека, чтобы собрать больше контекста (в случае с ошибкой), но общая картина уже становится ясна.

Любое сообщение об ошибке, в котором отсутствует эта минимальная информация, становится шумом, поскольку у вас появляется беспокойство, но вы все еще не можете действовать. Сначала нужно углубиться в ситуацию, чтобы понять, насколько проблема серьезна.

Если вы все еще не поняли, как писать полезные сообщения, я поделюсь с вами очень простым лайфхаком:

Всегда спрашивайте себя: Что я хочу уяснить для себя, после получения такого лога?

Предоставление контекста с помощью Python

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

# Do that
logger.info("Connecting to AWS", extra={"user": "X"})
...
logger.info("Connection to AWS has been successful", extra={"user": "X"})

Контекст не отменяет необходимости в содержательных сообщениях! Поэтому я бы так не делал:

# Don't do that
logger.info("Connecting to third-party", extra={"user": "X", "third-party": "AWS"})

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

Нечто большее, чем logger.info и logger.error

Не так-то просто понять, что происходит, когда тысячи клиентов выдают логи «Connecting to Slack». Поскольку вы выдаете логи, а вашим приложением пользуются несколько клиентов, нужно иметь возможность фильтровать информацию по релевантности.

В логах бывает много уровней (т.е. уровней релевантности). В Python у вас есть DEBUG, INFO, WARNING, ERROR, CRITICAL. Я рекомендую использовать их все. 

Чтобы упростить ситуацию, вот вам новое эмпирическое правило (будьте гибкими):

Уровень	Когда используется
DEBUG	Для какой-то действительно повторяющейся информации. Возможно, было бы полезно выдавать весь контекст информации, но порой этого не нужно.
INFO	Когда происходит что-то важное, достойное того, чтобы о нем было известно большую часть времени.
WARNING	Случилось что-то странное (но не прервало поток/операцию). Если проблема возникнет на более поздних этапах, такой лог может дать вам подсказку.
ERROR	Произошла ошибка, ее следует устранить как можно быстрее.
CRITICAL	Произошла очень серьезная ошибка, она требует немедленного вмешательства. Если не уверены в критичности ошибки, применяйте ERROR.

Для описанной системы/потоков, я бы использовал уровни логов, как определено:

Что делать с logger.critical и logger.warning?

Для примера хочу осветить случаи, когда я бы рассмотрел возможность использования WARNING и CRITICAL.

• WARNING – недостаточно веская причина для остановки потока, однако это предупреждение на будущее, если возникнет какая-то проблема.

• CRITICAL – самый тревожный предупреждающий лог, который вы когда-либо получите. По сути, он должен быть той самой причиной встать в три часа ночи и пойти что-то чинить.

Для этих случаев мы рассмотрим:

• Для AWS: если какой-то регион AWS недоступен, мы можем предположить, что у пользователя там нет никаких ресурсов, поэтому можно двигаться дальше.

• Для Slack: если OAuth завершится неудачно из-за невалидного id клиента, значит остальные пользователи столкнутся с той же проблемой, интеграция не отработает, пока мы вручную не сгенерируем новый id. Это дело кажется достаточно критичным.

Непопулярное мнение: использование DEBUG-уровня на продакшене

Да, я считаю, что логи DEBUG нужно использовать на продакшене.

Другой вариант – включить дебаг после того, как странная ошибка потребует более детального разбирательства.

Простите, но для меня такой вариант недопустим.

В реальном мире клиентам нужна быстрая реакция, командам нужно выполнять свою работу и постоянно поддерживать системы в рабочем состоянии. У меня нет времени и пропускной способности для нового деплоя или включения флага и ожидания повторения проблемы. Я должен реагировать на неожиданные проблемы в считанные секунды, а не минуты.

Правильно настройте логгер

Еще я замечаю, что люди испытывают трудности при настройке логгера (или вообще его не настраивают). Конечно, документация в Python не очень дружелюбная, но это не оправдание, чтобы вообще ее не трогать.

Есть несколько способов настроить логгер. Вы можете использовать logging.config.dictConfig, logging.config.fileConfig или вообще сделать все вручную, вызывая такие команды как setLevel, AddHandler, addFilter.

По моему опыту:

• Использование ручных команд непросто поддерживать и понимать;

• fileConfig – негибкая история, у вас не бывает динамических значений (без дополнительных фокусов);

• dictConfig – простая история в запуске и настройке.

Поэтому в качестве примера мы будем придерживаться dictConfig. Еще можно запустить basicConfig, но не думаю, что он вам понадобится, если вы все настроили правильно.

Я поделюсь несколькими советами и определениями, которые вам надо знать, а затем мы создадим окончательную конфигурацию на реальных примерах из проектов, над которыми я работаю.

Вот кусочек того, о чем мы будем говорить дальше:

Что такое логгеры?

Логгеры – это объекты, которые вы создаете с помощью logging.getLogger, они позволяют выдавать сообщения. Каждый отдельный логгер может быть привязан к конфигурации со своим собственным набором форматтеров, фильтров, обработчиков и т.д.

Самое интересное, что логгеры образуют иерархию и все наследуются от root-логгера. Дальнейшее наследование определяется «.» (точками), например mymodule.this.that будет наследником mymodule.this.

Посмотрите:

Из-за этого в документации Python есть рекомендация по использованию logger.getLogger(name), поскольку name, вернет лишь пространство имен текущего пакета.

В любом случае, придерживайтесь:

import logging

logger = logging.getLogger(__name__)

def myfunc():
    ...
    logger.info("Something relevant happened")
    ...

Внимание: Вы можете обратиться к корневому логгеру по имени root, пустой строке “” или вообще ни по чему. Да, это сбивает с толку, поэтому используйте root для многословности и ясности.

Форматируйте логи

Форматтеры вызываются для вывода конечного сообщения и отвечают за него преобразование в конечную строку.

Когда я работал в Zak (бывшем Mimic), и даже сегодня в Lumos мы форматировали логи как JSON. Он является хорошим стандартом для систем, работающих на продакшене, поскольку содержит множество атрибутов. Проще визуализировать JSON, чем обычную длинную строку, и для этого вам не нужно создавать свой собственный форматтер (ознакомьтесь с python-json-logger).

Для локальной разработки я рекомендую использовать форматирование по умолчанию для простоты.

Ваше решение будет зависеть от вида проекта. Для Tryceratops я решил использовать обычный форматтер, поскольку он проще и работает локально, там нет нужды в JSON.

Фильтруйте логи

Фильтры можно использовать либо для фильтрации логов (внезапно), либо для добавления дополнительного контекста в запись лога. Рассматривайте фильтры, как хуки, вызываемые до обработки итогового лога.

Их можно определить следующим образом:

class ContextFilter(logging.Filter):
    USERS = ['jim', 'fred', 'sheila']
    IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']

    def filter(self, record):  # Add random values to the log record
        record.ip = choice(ContextFilter.IPS)
        record.user = choice(ContextFilter.USERS)
        return True

Адаптировано из https://docs.python.org/3/howto/logging-cookbook.html#using-filters-to-impart-contextual-information

Или их можно добавить прямо в логгер или обработчик для упрощения фильтрации по уровням (скоро будут примеры).

Обрабатывайте логи и то, как все связано

Обработчики представляют из себя комбинации форматтеров, выходных данных (потоков) и фильтров.

С ними вы можете создавать следующие комбинации:

• Выводить все логи из info (фильтр), а потом выводить JSON в консоль.

• Выводить все логи, начиная с error (фильтр) в файл, содержащий только сообщение и трассировку стека (форматтер).

Наконец логгеры указывают обработчикам.

Пример logging.dictConfig

Теперь, когда вы понимаете, что делают все эти объекты, давайте писать собственные! Как всегда, я постараюсь показать вам примеры из реальной жизни. Я буду использовать конфигурацию Tryceratops. Вы можете открыть ссылку и посмотреть самостоятельно окончательную конфигурацию.

Шаблон конфигурации логирования

Начнем с такого каркаса, создадим константу LOGGING_CONFIG:

import logging.config

LOGGING_CONFIG = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": { },
    "handlers": { },
    "loggers": { },
    "root": { },
}

logging.config.dictConfig(LOGGING_CONFIG)

Несколько заметок:

• Version всегда будет 1. Это плейсхолдер для возможных следующих релизов. На данный момент версия всего одна.

• Я рекомендую оставить значение disable_existing_loggers в False, чтобы ваша система не поглощала другие неожиданные проблемы, которые могут возникнуть. Если вы хотите изменить другие логгеры, я бы порекомендовал их явно переписать (хоть это и скучно).

• Внешний ключ root, как вы могли догадаться, определяет логгер верхнего уровня, от которого может наследоваться текущий.

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

LOGGING_CONFIG = {
    "version": 1,
    ...
    "loggers": {
        "root": ... # Defines root logger
        "": ... # Defines root logger
    },
    "root": { }, # Define root logger
}

Выбирайте любой! Мне нравится оставлять его снаружи, поскольку так он выглядит очевиднее и подробнее говорит о том, чего я хочу, ведь корневой логгер влияет на все другие определенные логгеры.

Конфигурация логирования: форматтеры

Я дополню пример из Tryceratops примером с JSON из Lumos.

Обратите внимание, что любая конструкция %([name])[type], как %(message) или %(created), говорит форматтеру, что и как отображать. 

LOGGING_CONFIG = {
    ...,
    "formatters": {
        "default": {  # The formatter name, it can be anything that I wish
            "format": "%(asctime)s:%(name)s:%(process)d:%(lineno)d " "%(levelname)s %(message)s",  #  What to add in the message
            "datefmt": "%Y-%m-%d %H:%M:%S",  # How to display dates
        },
        "simple": {  # The formatter name
            "format": "%(message)s",  # As simple as possible!
        },
        "json": {  # The formatter name
            "()": "pythonjsonlogger.jsonlogger.JsonFormatter",  # The class to instantiate!
            # Json is more complex, but easier to read, display all attributes!
            "format": """
                    asctime: %(asctime)s
                    created: %(created)f
                    filename: %(filename)s
                    funcName: %(funcName)s
                    levelname: %(levelname)s
                    levelno: %(levelno)s
                    lineno: %(lineno)d
                    message: %(message)s
                    module: %(module)s
                    msec: %(msecs)d
                    name: %(name)s
                    pathname: %(pathname)s
                    process: %(process)d
                    processName: %(processName)s
                    relativeCreated: %(relativeCreated)d
                    thread: %(thread)d
                    threadName: %(threadName)s
                    exc_info: %(exc_info)s
                """,
            "datefmt": "%Y-%m-%d %H:%M:%S",  # How to display dates
        },
    },
    ...
}

Обратите внимание, что имена, которые мы задаем (default, simple и JSON), - произвольные, но актуальные. Вскоре мы к ним обратимся.

Конфигурация логирования: обработчики

ERROR_LOG_FILENAME = ".tryceratops-errors.log"

LOGGING_CONFIG = {
    ...,
    "formatters": {
        "default": { ... },
        "simple": { ... },
        "json": { ... },
    },
    "handlers": {
        "logfile": {  # The handler name
            "formatter": "default",  # Refer to the formatter defined above
            "level": "ERROR",  # FILTER: Only ERROR and CRITICAL logs
            "class": "logging.handlers.RotatingFileHandler",  # OUTPUT: Which class to use
            "filename": ERROR_LOG_FILENAME,  # Param for class above. Defines filename to use, load it from constant
            "backupCount": 2,  # Param for class above. Defines how many log files to keep as it grows
        },
        "verbose_output": {  # The handler name
            "formatter": "simple",  # Refer to the formatter defined above
            "level": "DEBUG",  # FILTER: All logs
            "class": "logging.StreamHandler",  # OUTPUT: Which class to use
            "stream": "ext://sys.stdout",  # Param for class above. It means stream to console
        },
        "json": {  # The handler name
            "formatter": "json",  # Refer to the formatter defined above
            "class": "logging.StreamHandler",  # OUTPUT: Same as above, stream to console
            "stream": "ext://sys.stdout",
        },
    },
    ...
}

Обратите внимание, что если вы используете logging.fileConfig, иметь хорошую константу, такую как ERROR_LOG_FILENAME, невозможно. Эту же информацию можно прочитать из переменных среды, если хотите.

Также обратите внимание, что классы/параметры, которые я использую для обработчиков, создавал не я. Они из библиотеки logging, и там есть не только они!

Конфигурация логирования: логгеры и root

LOGGING_CONFIG = {
    ...,
    "formatters": {
        "default": { ... },
        "simple": { ... },
        "json": { ... },
    },
    "handlers": {
        "logfile": { ... },
        "verbose_output": { ... },
        "json": { ... },
    },
    "loggers": {
        "tryceratops": {  # The name of the logger, this SHOULD match your module!
            "level": "INFO",  # FILTER: only INFO logs onwards from "tryceratops" logger
            "handlers": [
                "verbose_output",  # Refer the handler defined above
            ],
        },
    },
    "root": {  # All loggers (including tryceratops)
        "level": "INFO",  # FILTER: only INFO logs onwards
        "handlers": [
            "logfile",  # Refer the handler defined above
            "json"  # Refer the handler defined above
        ]
    }

Давайте разберемся, что происходит:

• В root мы определяем все логи, кроме DEBUG, которые будут обрабатываться logfile и обработчиками JSON.

• Обработчик logfile отфильтровывает только логи ERROR и CRITICAL, и выводит их в файл с форматтером по умолчанию.

• JSON принимает все входящие логи (без фильтра) и выводит их в консоль с JSON-форматтером.

• Tryceratops переопределяет некоторые конфигурации, унаследованные от root, такие как level (несмотря на то, что это то же самое), и handlers для использования только verbose_output.

• verbose_output принимает все входящие логи (фильтр по DEBUG) и выводит их в консоль, используя форматтер simple.

Имя логгера tryceratops – это очень важная часть, и оно должно соответствовать логгерам, которые я создам позже. Для нашего примера, когда я пишу: logger.getLogger(name) внутри модуля, я получаю такие имена как tryceratops.main, tryceratops.runners или tryceratops.files.discovery, и все они соответствуют созданному нами правилу.

Я определил новый набор обработчиков для tryceratops, но все другие логгеры (в том числе из сторонних библиотек) будут использовать те, которые находятся в корне.

Кроме того, обратите внимание, что я могу переписать правила по умолчанию. Через настройки или позже динамически. Например, каждый раз, когда triceratops получает подобный флаг от CLI, он обновляет конфигурацию logging чтобы включить дебаг.

Логирование – это важно, но наличие хорошо структурированных исключений и блоков try/except также важно, поэтому вы можете также прочитать, как профессионально обрабатывать и структурировать исключения в Python.

---

Материал подготовлен в рамках курса «Python Developer. Basic».

Всех желающих приглашаем на demo-занятие «Основы ООП». Цели занятия: научиться работать с классами и познакомиться с наследованием.
Краткое содержание:
- мутабельность экземпляров класса
- передача аргументов в инициализатор
- наследование
- переопределение методов
- обращение к методам суперкласса
>> РЕГИСТРАЦИЯ