Мониторинг микросервисов Tirebase: structlog, Prometheus, Grafana

Когда Redis съел всю память, Autoload Engine перестал обновлять фиды на маркетплейсах. Менеджеры написали, что заказы не оформляются. Я подключился по SSH, посмотрел docker ps — все контейнеры запущены. Каждый сервис писал логи в свой файл, в своём формате. Открыл 6 файлов, grep error — 200 строк, из которых 180 старые. Через 40 минут нашёл причину, решение — одна команда redis-cli FLUSHDB.

После этого инцидента я потратил неделю на построение нормального мониторинга.

Шаг 1: Структурированные логи (structlog)

Первая проблема — логи в свободном формате. Один сервис пишет 2025-12-01 INFO: Feed generated, другой — [ERROR] redis connection failed for feed worker. Парсить это невозможно.

Перевёл все сервисы на structlog — библиотеку для структурированного логирования в Python:

# core/logging.py
import structlog

def setup_logging():
    structlog.configure(
        processors=[
            structlog.contextvars.merge_contextvars,
            structlog.processors.add_log_level,
            structlog.processors.TimeStamper(fmt="iso"),
            structlog.processors.StackInfoRenderer(),
            structlog.processors.format_exc_info,
            structlog.processors.JSONRenderer(),
        ],
        wrapper_class=structlog.make_filtering_bound_logger(logging.INFO),
        context_class=dict,
        logger_factory=structlog.PrintLoggerFactory(),
    )

Теперь каждая строка лога — валидный JSON:

logger = structlog.get_logger()

# В middleware FastAPI
@app.middleware("http")
async def logging_middleware(request: Request, call_next):
    request_id = request.headers.get("X-Request-ID", str(uuid4()))
    structlog.contextvars.clear_contextvars()
    structlog.contextvars.bind_contextvars(
        request_id=request_id,
        method=request.method,
        path=request.url.path,
        service="autoload-engine",
    )

    start = time.perf_counter()
    response = await call_next(request)
    duration = time.perf_counter() - start

    logger.info("request_completed",
        status=response.status_code,
        duration_ms=round(duration * 1000, 2),
    )
    return response

Вывод:

{"request_id": "a1b2c3", "method": "POST", "path": "/feeds/generate", "service": "autoload-engine", "status": 201, "duration_ms": 47.23, "event": "request_completed", "level": "info", "timestamp": "2025-12-20T10:15:32.123Z"}

Каждый лог содержит request_id, имя сервиса, путь, время. Можно фильтровать, агрегировать, искать по запросу через всю цепочку микросервисов.

Шаг 2: Централизованный сбор логов

Логи из всех контейнеров нужно собрать в одно место. Использую связку Docker logging driver + Grafana Loki:

# docker-compose.yml
services:
  autoload-engine:
    image: autoload-engine:latest
    logging:
      driver: loki
      options:
        loki-url: "http://loki:3100/loki/api/v1/push"
        loki-batch-size: "400"
        loki-retries: "3"
        labels: "service"
    labels:
      service: "autoload-engine"

  loki:
    image: grafana/loki:2.9.0
    ports:
      - "3100:3100"
    volumes:
      - loki-data:/loki

Теперь в Grafana я могу написать LogQL-запрос:

{service="autoload-engine"} |= "error" | json | duration_ms > 1000

И мгновенно увидеть все ошибки в Autoload Engine с временем ответа больше секунды.

Шаг 3: Health Check эндпоинты

Каждый сервис получил /health endpoint, который проверяет свои зависимости:

# routes/health.py
from fastapi import APIRouter
import asyncpg
import aioredis

router = APIRouter()

@router.get("/health")
async def health_check():
    checks = {}
    status = "healthy"

    # Проверяем PostgreSQL
    try:
        pool = get_db_pool()
        async with pool.acquire() as conn:
            await conn.fetchval("SELECT 1")
        checks["database"] = {"status": "up", "latency_ms": 2}
    except Exception as e:
        checks["database"] = {"status": "down", "error": str(e)}
        status = "unhealthy"

    # Проверяем Redis
    try:
        redis = get_redis()
        await redis.ping()
        checks["redis"] = {"status": "up"}
    except Exception as e:
        checks["redis"] = {"status": "down", "error": str(e)}
        status = "unhealthy"

    code = 200 if status == "healthy" else 503
    return JSONResponse(
        status_code=code,
        content={"status": status, "checks": checks, "version": settings.APP_VERSION}
    )

Docker использует health check для автоматического перезапуска:

services:
  autoload-engine:
    healthcheck:
      test: ["CMD", "curl", "-f", "http://localhost:8000/health"]
      interval: 15s
      timeout: 5s
      retries: 3
      start_period: 10s

Три неуспешных проверки — контейнер перезапускается. Тот инцидент с Redis решился бы автоматически.

Шаг 4: Метрики в Prometheus

Логи показывают «что произошло», метрики показывают «как дела в целом». Добавил prometheus-fastapi-instrumentator:

# main.py
from prometheus_fastapi_instrumentator import Instrumentator
from prometheus_client import Counter, Histogram

# Автоматические метрики HTTP
Instrumentator().instrument(app).expose(app, endpoint="/metrics")

# Кастомные бизнес-метрики
feeds_generated = Counter(
    "feeds_generated_total", "Total feeds generated", ["marketplace"]
)
feed_generation_time = Histogram(
    "feed_generation_seconds", "Time to generate a feed",
    buckets=[0.5, 1.0, 2.5, 5.0, 10.0, 30.0, 60.0]
)

@app.post("/feeds/generate")
async def generate_feed(feed: FeedRequest):
    with feed_generation_time.time():
        result = await process_feed(feed)
        feeds_generated.labels(marketplace=feed.marketplace).inc()
        return result

Prometheus scrape config:

# prometheus.yml
scrape_configs:
  - job_name: 'microservices'
    docker_sd_configs:
      - host: unix:///var/run/docker.sock
        refresh_interval: 15s
    relabel_configs:
      - source_labels: [__meta_docker_container_label_prometheus_scrape]
        regex: "true"
        action: keep
      - source_labels: [__meta_docker_container_label_service]
        target_label: service

Автоматическое обнаружение контейнеров через Docker SD — не нужно вручную добавлять каждый сервис.

Шаг 5: Grafana-дашборды

Собрал три дашборда, которые покрывают большинство случаев:

Дашборд 1 — Overview: запросы/сек по сервисам, p50/p95/p99 latency, error rate, CPU/RAM. Открываю утром — вижу общую картину за ночь.

Дашборд 2 — Service Detail: детальные метрики конкретного сервиса. Топ-10 медленных эндпоинтов, распределение статус-кодов, активные соединения к БД.

Дашборд 3 — Бизнес-метрики: фиды/час, ошибки синхронизации с маркетплейсами, количество обновлённых товаров. Если фиды перестали генерироваться — значит что-то сломалось, даже если все сервисы «зелёные».

Ключевые PromQL-запросы:

# Error rate по сервису
sum(rate(http_requests_total{status=~"5.."}[5m])) by (service)
/
sum(rate(http_requests_total[5m])) by (service)

# p95 latency
histogram_quantile(0.95, sum(rate(http_request_duration_seconds_bucket[5m])) by (le, service))

Шаг 6: Алерты, которые не надоедают

Главная ошибка — алерты на каждый чих. Через неделю их начинают игнорировать. Мои правила:

# alerting_rules.yml
groups:
  - name: critical
    rules:
      - alert: ServiceDown
        expr: up == 0
        for: 1m
        labels:
          severity: critical
        annotations:
          summary: "{{ $labels.service }} не отвечает"

      - alert: HighErrorRate
        expr: |
          sum(rate(http_requests_total{status=~"5.."}[5m])) by (service)
          / sum(rate(http_requests_total[5m])) by (service) > 0.05
        for: 3m
        labels:
          severity: warning
        annotations:
          summary: "{{ $labels.service }}: error rate {{ $value | humanizePercentage }}"

      - alert: SlowResponses
        expr: histogram_quantile(0.95, sum(rate(http_request_duration_seconds_bucket[5m])) by (le, service)) > 2
        for: 5m
        labels:
          severity: warning

Три уровня: critical (будит ночью), warning (Telegram-канал), info (только в дашборде). Critical — только если сервис упал совсем или error rate выше 10%.

Результат

Вот как выглядит диагностика теперь:

1. Приходит алерт в Telegram: «autoload-engine: error rate 8%»
2. Открываю Grafana, вижу всплеск 5xx на графике
3. Переключаюсь на Service Detail, вижу: конкретный эндпоинт, ошибка в downstream-зависимости
4. Смотрю логи в Loki с фильтром по request_id
5. Знаю причину, могу чинить

В идеальном случае это занимает минуту-две. Было — 40 минут с SSH и grep. Не всегда всё так гладко: иногда проблема не в одном сервисе, а в цепочке, и приходится покопаться. Но разница с тем, что было раньше — огромная.

Честно говоря, дашборд с бизнес-метриками (заказы/час, конверсия) пока больше в планах, чем в реальности. Основное, что работает и спасает — это structlog + Loki + алерты. Prometheus-метрики собираю, но смотрю в них реже, чем хотелось бы.