Логирование в продакшене на Python: что ломается первым

Сервис на gunicorn с четырьмя воркерами пишет логи в один файл app.log. В три часа ночи начинается всплеск ошибок, вы открываете файл — а там 200 тысяч строк вперемешку от четырёх процессов, стектрейсы разорваны, и найти нужный запрос по ID пользователя невозможно, потому что ID в лог никто не клал. Это типичный итог настройки логирования по принципу «работает и ладно». Разберём, где именно она ломается и как это чинить в Python 3.11+ на стандартном модуле logging.

Почему print() и basicConfig не доживают до прода

print() пишет в stdout без уровня, без времени и без имени модуля. Отфильтровать ошибки от отладки нельзя — всё одинаковый текст. logging.basicConfig(level=logging.INFO) лучше, но у него три встроенные проблемы, которые проявляются именно под нагрузкой.

• Текстовый формат. Строку 2024-... ERROR payment failed for user 42 нельзя надёжно распарсить: сегодня в сообщении user 42, завтра кто-то поменял формулировку, и грепы по логам ломаются молча.
• Разорванные стектрейсы. Многострочное исключение при конкурентной записи из нескольких потоков или процессов перемешивается с другими строками.
• Файл растёт бесконечно. basicConfig с filename= пишет в один файл без ротации. За неделю он забьёт диск, и сервис упадёт не от бага, а от No space left on device.

Структурный лог: одна запись — один JSON

Идея структурного логирования: каждая запись — не строка, а набор полей. Время, уровень, сообщение, имя логгера плюс произвольный контекст (ID запроса, ID пользователя, длительность). Тогда логи можно фильтровать и агрегировать в Loki, Elasticsearch или CloudWatch без регулярных выражений.

Стандартный logging.Formatter формата JSON из коробки не даёт, но собрать свой форматтер — десяток строк. Ключевой приём — передавать контекст через параметр extra в вызове логгера, а форматтер вытаскивает эти поля из записи.

# Python 3.11+, только стандартная библиотека
import json
import logging

# Поля, которые LogRecord содержит всегда — их не дублируем в extra
_STANDARD_ATTRS = set(logging.makeLogRecord({}).__dict__.keys())

class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "ts": self.formatTime(record, "%Y-%m-%dT%H:%M:%S%z"),
            "level": record.levelname,
            "logger": record.name,
            "msg": record.getMessage(),
        }
        # Всё, что передали через extra=, добавляем как отдельные поля
        for key, value in record.__dict__.items():
            if key not in _STANDARD_ATTRS:
                payload[key] = value
        # Исключение — одним полем, а не размазанным по строкам
        if record.exc_info:
            payload["exc"] = self.formatException(record.exc_info)
        return json.dumps(payload, ensure_ascii=False)

Вызов с контекстом выглядит так:

logger = logging.getLogger("payment")
logger.info("payment processed", extra={"user_id": 42, "amount": 1990, "currency": "RUB"})

На выходе — {"ts": "...", "level": "INFO", "logger": "payment", "msg": "payment processed", "user_id": 42, "amount": 1990, "currency": "RUB"}. Теперь по user_id: 42 вы найдёте все действия пользователя за минуту.

Подводный камень с extra: ключи в extra не должны совпадать с зарезервированными атрибутами LogRecord (message, args, levelname и другими) — иначе logging бросит KeyError прямо в момент записи лога. Именно поэтому в форматтере выше мы отбрасываем стандартные атрибуты по их множеству, а свои поля называем нейтрально: user_id, а не name или module.

Текстовый лог отвечает на вопрос «что случилось». Структурный отвечает на вопрос «что случилось с этим конкретным запросом» — и делает это через фильтр, а не через прокрутку файла глазами.

Готовые библиотеки: когда свой форматтер не нужен

Если не хочется поддерживать свой форматтер, есть проверенные пакеты. python-json-logger даёт JSON-форматтер для стандартного logging. structlog идёт дальше: строит логи через цепочку процессоров, удобно прокидывать контекст запроса. Оба совместимы со стандартным logging как бэкендом. Точные имена классов и параметры смотрите в документации выбранной версии — API у structlog между мажорными версиями менялся.

Уровни: не всё INFO

Уровень — это не «важность на глаз», а ответ на вопрос «кто и как быстро должен на это реагировать». В Python пять стандартных уровней, и путаница между ними — причина того, что либо алерты молчат при инциденте, либо дежурного будят на каждый чих.

Практическое правило: в проде уровень корневого логгера ставьте на INFO, а шумные библиотеки (тот же urllib3, botocore) глушите до WARNING отдельно: logging.getLogger("urllib3").setLevel(logging.WARNING). Иначе один HTTP-клиент забьёт лог отладочными строками.

Ротация: где она захлёбывается

Ротация нужна, чтобы файл не съел диск. Стандартный logging.handlers даёт два основных класса: RotatingFileHandler (по размеру) и TimedRotatingFileHandler (по времени). Настройка выглядит просто, но есть две ловушки, которые всплывают именно в проде.

from logging.handlers import RotatingFileHandler

handler = RotatingFileHandler(
    "/var/log/myapp/app.log",
    maxBytes=50 * 1024 * 1024,  # 50 МБ на файл
    backupCount=5,              # хранить 5 старых файлов
    encoding="utf-8",
)
handler.setFormatter(JsonFormatter())

root = logging.getLogger()
root.setLevel(logging.INFO)
root.addHandler(handler)

Ловушка первая — несколько процессов на один файл. gunicorn с несколькими воркерами — это несколько процессов. RotatingFileHandler не координирует ротацию между процессами: когда один переименовывает файл, другие продолжают писать в старый дескриптор. Результат — потерянные строки и файлы вроде app.log.1, в которые всё ещё что-то пишется. Стандартный модуль эту проблему не решает.

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

Что делать в многопроцессном проде

• Логировать в stdout, а ротацию отдать инфраструктуре. В контейнерах — писать в stdout/stderr, а сбором и ротацией занимается Docker (драйвер json-file с max-size), Kubernetes или агент вроде Vector/Fluent Bit. Приложение не знает про файлы вообще — это самый устойчивый вариант.
• Отдать ротацию файла системному logrotate. Приложение пишет в один файл в режиме дозаписи, а logrotate ротирует его по расписанию с сигналом на переоткрытие. Тут важно, чтобы обработчик умел переоткрывать файл (режим copytruncate у logrotate обходит эту проблему ценой возможной потери строк в момент копирования).
• Разгрузить запись через QueueHandler. Стандартные logging.handlers.QueueHandler и QueueListener выносят фактическую запись в отдельный поток: воркер кладёт запись в очередь и сразу возвращается к работе, слушатель пишет в файл. Это снимает блокирующий ввод-вывод с обработки запросов.

Что настроить дальше

Базовая связка готова: JSON-форматтер, разумные уровни, ротация через инфраструктуру. Дальше смотрите на три вещи в проде:

• Проброс request_id через весь запрос. Сгенерируйте ID на входе (middleware), положите в contextvars и подмешивайте в каждый лог через фильтр или процессор. Тогда все строки одного запроса связываются одним полем.
• Метрика объёма логов. Следите за байтами логов в секунду. Резкий рост — обычно признак зациклившейся ошибки, которая пишет ERROR в цикле, а не признак нагрузки.
• Отдельный канал для ERROR и выше. Не ищите ошибки грепом по общему потоку — заведите правило в системе сбора логов на уровень >= ERROR с алертом.

Проброс контекста через contextvars и интеграция с трейсингом (OpenTelemetry) — отдельная тема, здесь мы разобрали только сам конвейер логов. Начните с того, чтобы каждая запись стала JSON с уровнем: остальное строится на этом фундаменте.