Middleware в FastAPI: как один слой сломал latency на проде

Что случилось: 200 мс превращаются в 600

Сервис на FastAPI 0.111 (Starlette 0.37, Python 3.12, Uvicorn 0.30) обрабатывал около 800 запросов в секунду. После добавления middleware для логирования тела запроса и ответа p99 latency вырос с 200 мс до 580–620 мс. CPU при этом почти не изменился, а память на воркерах подросла на 15–20%. Проблема воспроизводилась только под нагрузкой — на единичных запросах всё выглядело нормально.

Как устроен middleware-стек в FastAPI

FastAPI — надстройка над Starlette, и middleware здесь работает по правилам ASGI. Каждый входящий запрос проходит через цепочку middleware-слоёв сверху вниз, доходит до роутера, а ответ возвращается снизу вверх через ту же цепочку. Порядок добавления имеет значение: слой, добавленный последним через app.add_middleware(), оборачивает всё остальное и выполняется первым.

Два способа написать middleware

FastAPI предлагает два подхода, и разница между ними — не стилистическая, а архитектурная.

Именно BaseHTTPMiddleware стал источником проблемы в нашем кейсе. Об этом — ниже.

Механизм: почему BaseHTTPMiddleware читает тело дважды

Когда вы вызываете await request.body() внутри dispatch, Starlette считывает весь поток receive и сохраняет результат в атрибуте объекта Request. Но дальше по цепочке — в эндпоинте — FastAPI создаёт новый объект Request (или работает с телом через Pydantic-модель), и тело читается снова. Starlette подставляет буфер, но сам процесс создания промежуточных объектов, копирования байтов и повторного парсинга JSON складывается в заметную задержку.

Middleware, который «просто логирует», на деле буферизует каждый байт запроса и ответа в памяти. Под нагрузкой это означает сотни мегабайт аллокаций в секунду, которые GC не успевает собрать вовремя.

Проблема усугубляется, если тело запроса велико — загрузка файлов, batch-запросы с массивами объектов. В нашем случае средний размер тела составлял около 12 КБ, но при 800 RPS это давало порядка 19 МБ/с дополнительных аллокаций только на буферизацию в middleware.

Ответ тоже буферизуется

BaseHTTPMiddleware перехватывает call_next и собирает весь ответ в память до того, как отдаст его клиенту. Для обычных JSON-ответов это терпимо. Но если в приложении есть эндпоинты с StreamingResponse — например, отдача сгенерированных отчётов — middleware молча превращает стриминг в буферизованную отдачу, убивая его смысл.

Как починили: переход на Pure ASGI middleware

Решение — написать middleware как чистый ASGI-класс, который перехватывает нужные данные без полной буферизации.

# logging_middleware.py
# Совместимо с Starlette 0.37+ / FastAPI 0.111+
import time
import logging
from starlette.types import ASGIApp, Receive, Scope, Send, Message

logger = logging.getLogger("api.access")


class AccessLogMiddleware:
    """ASGI middleware: логирует метод, путь и время обработки
    без буферизации тела запроса и ответа."""

    def __init__(self, app: ASGIApp) -> None:
        self.app = app

    async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None:
        if scope["type"] != "http":
            await self.app(scope, receive, send)
            return

        start = time.perf_counter()
        status_code = 0

        async def send_wrapper(message: Message) -> None:
            nonlocal status_code
            if message["type"] == "http.response.start":
                status_code = message["status"]
            await send(message)

        await self.app(scope, receive, send_wrapper)

        duration_ms = (time.perf_counter() - start) * 1000
        method = scope.get("method", "?")
        path = scope.get("path", "?")
        logger.info("%s %s → %d (%.1f ms)", method, path, status_code, duration_ms)

Подключение:

# main.py
from fastapi import FastAPI
from logging_middleware import AccessLogMiddleware

app = FastAPI()
app.add_middleware(AccessLogMiddleware)

Проверка: после запуска Uvicorn каждый запрос должен порождать строку в логе вида GET /api/items → 200 (14.3 ms). Если строки нет — убедитесь, что уровень логгера api.access выставлен не выше INFO.

Что изменилось в цифрах

После замены p99 latency вернулся к 210 мс — почти к базовому уровню. Потребление памяти снизилось на те же 15–20%. Стриминговые эндпоинты заработали корректно.

Когда тело запроса всё-таки нужно в middleware

Бывает, что middleware обязан видеть тело — например, для подписи запросов, валидации HMAC или аудита. В этом случае чистый ASGI-подход тоже работает, но требует аккуратности: нужно перехватить чанки receive, склеить, обработать — и подставить обратно, чтобы следующий слой мог прочитать тело без потерь.

# Схематично: перехват тела без потери для нижних слоёв
async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None:
    if scope["type"] != "http":
        await self.app(scope, receive, send)
        return

    body_chunks: list[bytes] = []
    body_complete = False

    async def receive_wrapper() -> Message:
        nonlocal body_complete
        message = await receive()
        if message["type"] == "http.request":
            body_chunks.append(message.get("body", b""))
            if not message.get("more_body", False):
                body_complete = True
        return message

    await self.app(scope, receive_wrapper, send)

    full_body = b"".join(body_chunks)
    # Здесь full_body доступен для логирования или проверки подписи

Этот вариант всё ещё буферизует тело, но делает это один раз и не создаёт повторного чтения. Для больших тел (загрузка файлов) такой подход не подходит — там стоит логировать только метаданные.

Где подход ломается

• WebSocket. Middleware на уровне HTTP не перехватывает WebSocket-соединения. Если scope["type"] не проверять, middleware упадёт с ошибкой при первом WS-подключении. Всегда добавляйте ранний return для не-HTTP scope, как в примерах выше.
• Порядок слоёв. CORS-middleware (CORSMiddleware из Starlette) должен оборачивать всё остальное — иначе preflight-запросы не получат нужных заголовков. Если ваш кастомный middleware добавлен после CORS, он выполнится раньше и может вернуть ответ без CORS-заголовков.
• Исключения до send. Если приложение бросает необработанное исключение, send_wrapper не вызовется и status_code останется нулевым. Оборачивайте вызов self.app в try/except и логируйте ошибку отдельно.
• Множественные middleware с буферизацией. Два middleware, каждый из которых читает тело, — это тройное чтение (два middleware + эндпоинт). Проблема масштабируется линейно с числом слоёв.

ASGI (Asynchronous Server Gateway Interface) — спецификация взаимодействия между Python-веб-сервером и приложением, асинхронный наследник WSGI. Определяет три вызываемых объекта: scope (описание соединения), receive (входящие сообщения) и send (исходящие сообщения).

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

• Проведите аудит текущих middleware: если хотя бы один наследует BaseHTTPMiddleware и работает с телом запроса или ответа, замерьте latency до и после его отключения — разница может удивить.
• Для замеров используйте time.perf_counter() внутри middleware и внешний инструмент вроде wrk или locust, чтобы видеть картину и изнутри, и снаружи.
• Изучите раздел Middleware в документации Starlette — именно Starlette, не FastAPI, потому что вся механика живёт там.
• Если проект использует StreamingResponse — проверьте, не буферизует ли его какой-то middleware. Простой тест: отдайте через стриминг файл в 100 МБ и посмотрите потребление памяти воркера.