Структурные логи в Python: типичные ошибки

Вы перешли с текстовых логов на JSON, подключили python-json-logger или structlog, и ждёте, что в Grafana Loki можно будет фильтровать по полю user_id. А в итоге половина записей приходит строкой без единого поля, часть событий пишется дважды, а в одном из логов лежит заголовок Authorization с боевым токеном. Разберём четыре ошибки, которые встречаются почти в каждом проекте, перешедшем на структурные логи, и покажем, как их править. Речь про CPython 3.11+ и стандартный модуль logging; примеры со structlog — для версии 24.x.

Ошибка 1. Данные внутри строки, а не в полях

Самая частая ошибка при переходе — оставить старый стиль вызова. Человек подключил JSON-форматтер, но продолжает собирать строку сам:

# так делать не надо: user_id и order_id склеены в message
import logging

logger = logging.getLogger(__name__)
logger.info(f"user {user_id} paid order {order_id}")

На выходе будет валидный JSON, но с единственным осмысленным полем message: {"message": "user 42 paid order 100"}. По user_id в Loki отфильтровать нельзя — значение утонуло в тексте. Структурный лог теряет весь смысл: вы платите за JSON-сериализацию, но получаете тот же неразбираемый текст.

Правильно — вынести переменные в отдельные поля через extra:

import logging

logger = logging.getLogger(__name__)

logger.info(
 "order paid",
 extra={"user_id": user_id, "order_id": order_id, "amount": amount},
)

Тогда JSON-форматтер разложит их в отдельные ключи. Но у extra стандартного logging есть ловушка: имена полей не должны совпадать с зарезервированными атрибутами LogRecord — message, args, levelname, name и другими. Попытка передать extra={"name": ...} вызовет KeyError при создании записи. Со structlog проблема исчезает — там аргументы и есть поля:

import structlog

log = structlog.get_logger()
log.info("order paid", user_id=user_id, order_id=order_id, amount=amount)

Если после перехода на JSON вы всё ещё пишете f-строки в logger.info, вы поменяли формат вывода, но не способ мышления. Событие — это имя плюс поля, а не готовое предложение.

Ошибка 2. Контекст живёт в одном месте, а нужен везде

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

Для сквозного контекста в structlog есть contextvars. Значение привязывается к текущей асинхронной задаче или потоку и подхватывается всеми логами до очистки:

import structlog

structlog.configure(
 processors=[
 structlog.contextvars.merge_contextvars, # подмешивает контекст в каждую запись
 structlog.processors.add_log_level,
 structlog.processors.TimeStamper(fmt="iso"),
 structlog.processors.JSONRenderer(),
 ],
)

log = structlog.get_logger()

# в middleware в начале обработки запроса
structlog.contextvars.bind_contextvars(request_id=request_id)

# где угодно глубже по стеку — request_id уже в записи
log.info("cache miss", key=cache_key)

# в конце обработки обязательно очистить
structlog.contextvars.clear_contextvars()

Ключевой момент — clear_contextvars() в конце запроса. Забыв его в синхронном воркере с переиспользуемыми потоками, вы получите request_id от предыдущего запроса в логах следующего. В FastAPI и других async-фреймворках чистить нужно в finally middleware, а не после первого await.

Стандартный logging сквозного контекста из коробки не даёт. Обычно к нему прикручивают свой logging.Filter, который читает значение из contextvars.ContextVar и дописывает в record. Это рабочий путь, но именно поэтому на новых проектах чаще берут structlog.

Ошибка 3. Каждая запись пишется дважды

Вы видите в консоли два одинаковых JSON-объекта на одно событие. Причина почти всегда одна — распространение записи по иерархии логгеров. У любого именованного логгера propagate=True: запись обрабатывается его хендлерами, а потом поднимается к родителю вплоть до root. Если хендлер висит и на вашем логгере, и на root, сообщение форматируется двумя разными хендлерами.

Типичный сценарий: вы вызвали logging.basicConfig() (повесил StreamHandler на root), а потом добавили свой хендлер конкретному логгеру, не тронув propagate. Проверить, что происходит:

import logging

root = logging.getLogger()
print(root.handlers) # какие хендлеры на root

mine = logging.getLogger("myapp.payments")
print(mine.handlers, mine.propagate) # свои хендлеры и флаг распространения

Два способа починить, выбирайте один и держитесь его:

• Хендлеры только на root. Настраиваете форматтер и хендлер один раз на корневом логгере, а в модулях пишете через logging.getLogger(__name__). Записи поднимаются к root и там форматируются единожды. Простой и предсказуемый вариант для большинства сервисов.
• Хендлер на конкретном логгере + propagate=False. Нужен, когда часть логов должна идти в отдельный файл или формат. Тогда обязательно отключите распространение, иначе запись всё равно уйдёт наверх.

Отдельная тонкость: повторный вызов logging.basicConfig() ничего не делает, если на root уже есть хендлеры. Поэтому если библиотека успела вызвать basicConfig до вас, ваш повторный вызов молча проигнорируется, а логи пойдут в чужом текстовом формате. Настраивайте логирование через logging.config.dictConfig — там есть флаг disable_existing_loggers и явный контроль над каждым логгером.

Ошибка 4. Секреты и лишние данные в логах

Структурный лог соблазняет писать целые объекты: log.info("request", headers=dict(request.headers)). Одной строкой в лог уезжает заголовок Authorization с токеном, cookie сессии, а иногда и тело с номером карты. Логи потом лежат в Loki или CloudWatch, куда доступ шире, чем к базе — и утечка секрета через лог считается инцидентом безопасности.

В structlog проблема решается процессором, который вырезает опасные поля до рендеринга:

import structlog

SENSITIVE_KEYS = {"authorization", "password", "token", "cookie", "set-cookie"}

def redact_secrets(logger, method_name, event_dict):
 """Заменяет значения чувствительных ключей на заглушку."""
 for key in list(event_dict.keys()):
 if key.lower() in SENSITIVE_KEYS:
 event_dict[key] = "[REDACTED]"
 return event_dict

structlog.configure(
 processors=[
 redact_secrets, # редактируем до JSON-рендеринга
 structlog.processors.add_log_level,
 structlog.processors.JSONRenderer(),
 ],
)

Процессор смотрит только на верхний уровень словаря — вложенные структуры вроде headers он не разбирает. Если логируете вложенные объекты, редактируйте их рекурсивно или, что надёжнее, вообще не кладите заголовки и тела целиком: выбирайте конкретные безопасные поля руками.

Что ещё уводит объём логов в потолок

Помимо секретов, в логи часто уезжает лишнее из-за жадного логирования на уровне DEBUG в проде. Две частые причины:

• Тяжёлый аргумент вычисляется до проверки уровня: logger.debug("state %s", build_full_dump()) вызовет build_full_dump() даже при уровне INFO. Оборачивайте в if logger.isEnabledFor(logging.DEBUG): или передавайте функцию, а не результат.
• Логирование в цикле по всем элементам большой коллекции. Одна запись на итерацию по списку из десятков тысяч элементов — и лог за минуты забивает диск и упирается в лимиты хранилища.

Сводка ошибок и решений

Что сделать дальше

Соберите конфигурацию логирования в одном месте — через logging.config.dictConfig или один structlog.configure при старте приложения, а не разбросанными basicConfig по модулям. Проверьте боевой вывод грепом по authorization, token, password: если что-то нашлось незамаскированным — правьте до выката. Убедитесь, что request_id реально проходит сквозь весь путь запроса, а не только в middleware. Инвалидация и ротация файлов логов — отдельная тема, здесь мы её не трогали; на проде за это обычно отвечает logrotate или сборщик логов вроде Vector, а не само приложение.