В этом посте мы расскажем о том, как structlog может помочь вам писать логи, которые не только помогают в повседневной работе, но и реализуют лучшие практики для согласованного логирования во всём проекте.

Также мы рассмотрим распространённые сложности логирования и узнаем, как их позволяет решать structlog.

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

Structlog помогает упростить парсинг логов для опубликованного приложения и улучшает мониторинг в инструментах наподобие Datadog и Grafana.

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

import logging

... 

logging.debug("Start uploading file with name %s. Number of retries: %s", file_name, 0)

...

logging.error("Failed uploading file with name %s. Current retry: %s.", file_name, retries)

...

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

Нативный логгер Python

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

Классические трудности логирования

Прежде чем мы перейдём к практике, давайте сначала разберём основные сложности логирования на показанном выше примере.

1. Отсутствие контекстной информации

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

Однако при использовании такого лога в продакшен-системе обычно могут возникнуть следующие вопросы:

• Кто отправил этот запрос?

• К какой организации относится пользователь?

• К какому хранилищу файлов мы подключились? Есть ли идентификатор сессии или что-то ещё, позволяющее трассировать ошибку?

• Связана ли эта строка лога с идентификатором запроса?

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

2. Переход от логов разработки к машиночитаемым логам

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

3. Несогласованные формулировки

В одном и том же модуле Python строки логов часто выглядят совершенно по-разному. Иногда важная информация даже теряется. В зависимости от автора строки лога могут быть очень разнообразными. На сущности могут ссылаться по разным именам, значения переменных могут добавляться в лог в кавычках и без них, а формулировки в разных местах модуля могут варьироваться.

Это превращает поиск событий в сложную и долгую задачу.

Structlog

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

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

Первый шаг: заменяем нативный логгер Python на structlog

Давайте используем structlog для представленного выше фрагмента кода. Нам нужно получить логгер и добавить в сообщения лога переменные. Фрагмент кода может выглядеть так:

import structlog 

logger = structlog.get_logger()

... 

logger.debug("Start uploading file.", file_name=file_name,retries=0)

...

logger.error("Failed uploading file.", file_name=file_name,retries=retries)

...

Первым делом можно заметить, что переменные больше не загружаются в строку, а вместо этого являются kwargs методов debug и error. Это не только добавляет значения этих переменных в логгер, но и привязывает имена ключей к сообщению лога. Получившиеся строки лога будут выглядеть так:

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

Второй этап: привязка контекстных данных к логгерам

В общем случае есть два способа добавления контекстных данных в логгеры при помощи structlog.

1. Явная привязка переменных при помощи вызова .debug(…). Мы дополним предыдущий фрагмент кода, сначала привязав к логгеру file_name, а затем использовав экземпляр логгера для вывода сообщений лога.

import structlog 

logger = structlog.get_logger()

... 

log = logger.bind(file_name=file_name)

log.debug("Start uploading file.", retries=0)

...

log.error("Failed uploading file.", retries=retries)

...

Этот код позволяет нам удалить имя файла из всех строк логов и переместить его наверх, где он вызывается только один раз. Structlog сама займётся добавлением его в каждую строку лога.

2. Косвенная привязка контекстных переменных, при помощи вызова structlog.contextvars.bind_contextvars(…). Эта функция использует контекстные переменные, используемые, когда логгер в том же потоке выводит сообщения лога. Фрагмент кода, выводящий те же сообщения лога при помощи контекстных переменных, может выглядеть так:

# /controller/file.py

import structlog 

logger = structlog.get_logger()

... 

structlog.contextvars.bind_contextvars(file_name=file_name)

logger.debug("Start uploading file.", retries=0)

...

logger.error("Failed uploading file.", retries=retries)

Однако наша ситуация не является предпочтительным сценарием использования для применения контекстных переменных с целью добавления значений в логгер. Как мы узнали из раздела про сложности логирования, при классическом подходе контекстные данные часто теряются. Прежде чем обработать файл, мы предполагаем, что существует механизм аутентификации и авторизации, валидирующий доступ пользователя к конечной точке. Во фреймворке наподобие FastAPI эта нагрузка обрабатывается middleware. Так как здесь мы уже получили ID для аутентификации запроса, давайте добавим в логгер эту пару ключ-значение:

# /auth/middleware.py 

def verify_user(request: Request) -> bool:
    if not validate(request.token):
        return False

    user_id = get_user_id(request.token)
    structlog.contextvars.bind_contextvars(user_id=user_id)
    return True

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

Третий шаг: конфигурирование для машиночитаемых логов

Узнав, как добавлять информацию в строки лога при помощи structlog, мы хотим сконфигурировать её так, чтобы в среду разработки она отправляла украшенные строки лога, а в сервис логирования — распарсенные JSON. Мы выберем первое и самое простое решение из документации structlog. Прежде чем двигаться дальше, нам нужно понять две концепции structlog: препроцессоры и рендереры.

Препроцессоры (preprocessor) используются для расширения содержимого сообщений логов. Это можно сделать, добавляя метки времени, изменяя поля для обфускации имён пользователей или отбрасывая строки лога в зависимости от определённых условий.

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

Возможность писать собственные реализации этих узлов обеспечивает высокий уровень расширяемости.

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

Архитектура логирования из документации structlog

Мы начнём с настройки набора препроцессоров, добавляющих метки времени, задающих уровень лога и объединяющих контекстные переменные, используемые на втором шаге.

import structlog

from structlog.dev import ConsoleRenderer
from structlog.processors import JSONRenderer

# Препроцессор timestamper, добавляющий к каждому логу унифицированные  метки времени
timestamper = structlog.processors.TimeStamper(fmt="iso", utc=True)

# Препроцессоры Structlog
structlog_processors = [
    structlog.stdlib.add_log_level
    structlog.processors.add_log_level,
    structlog.contextvars.merge_contextvars,
    structlog.processors.StackInfoRenderer(),
    structlog.dev.set_exc_info,
    timestamper,
]

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

# __init__.py

from structlog.dev import ConsoleRenderer
from structlog.processors import JSONRenderer


def get_renderer() -> Union[JSONRenderer, ConsoleRenderer]:
    """
    Получаем рендерер на основании параметров среды
    :возвращаем рендерер structlog
    """

    if os.get("DEV_LOGS", True):
        return ConsoleRenderer()

    return JSONRenderer()

## Structlog
structlog.configure(
    processors=structlog_processors + [get_renderer()],
    wrapper_class=structlog.stdlib.BoundLogger,
    context_class=dict,
    logger_factory=structlog.PrintLoggerFactory(),
    cache_logger_on_first_use=False,
)

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

После присвоения переменной среды DEV_LOGS значения False строки лога будут выводиться как сырые JSON.

Логи парсятся как словари

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

А в локальной среде мы по-прежнему можем использовать старые раскрашенные строки лога:

Ограничения

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

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

1. <entity>_id <- (обязательно) — каждая обрабатываемая сущность (например, файл) должна добавляться в логгер

2. <entity>_name <- (необязательно) — каждая сущность (например, файл) может быть добавлена с суффиксом _name для удобства читаемости

3. <entity>_<additional_key> <- (необязательно) — допускается добавление дополнительных свойств сущностей с именем ключа в качестве суффикса

4. <custom_usecase_specific_field> ← (необязательно) — иногда может понадобиться добавить специфическую для ситуации информацию. В таких случаях можно использовать дополнительные произвольные ключи. Однако по возможности рекомендуется использовать стандарты наименований из пунктов 1-3.

Разумеется, это не единственный способ именования, но нам он подходит лучше всего.

Подведём итог

Мы узнали следующее:

1. Использование формата «ключ-значение» для переменных помогает создавать единообразные сообщения логов и мотивирует создавать согласованные наименования.

2. Контекстные данные можно добавлять явным образом, привязывая переменные к логгерам, или косвенным образом при помощи контекстных переменных, дополняющих строки лога полезными метаданными.

3. Выбор рендерера structlog позволяет в зависимости от среды удобно парсить строки логов в машиночитаемый или раскрашенный человекочитаемый формат.