Перейти к содержанию

Как отладить outbox lag

Runbook для ситуации «сработал alert на outbox_forwarder_lag_seconds» или «downstream-сервис жалуется, что не видит недавнее событие». Деталь, как устроен outbox и forwarder, — в ../patterns/outbox.md. Здесь — как быстро локализовать и починить проблему в live-сервисе.

Содержание

Что считается лагом

Outbox lag = время между commit'ом бизнес-транзакции, которая записала строку в outbox, и моментом, когда forwarder её опубликовал в Kafka.

lag = NOW() − MIN(created_at) WHERE offset_acked IS NULL

Нормальные значения:

  • < 1 секунды — штатная работа под нормальной нагрузкой.
  • 1–10 секунд — пиковая нагрузка, временный всплеск.
  • > 60 секунд — сработал alert, начинай разбираться.
  • > 5 минут — инцидент, события реально не доходят до consumer'ов.

Параллельно смотри количество unacked-строк: если их десятки — это «просто притормозили», если тысячи — более серьёзный затор.

Быстрая диагностика

SQL

SELECT
    COUNT(*) FILTER (WHERE offset_acked IS NULL) AS unacked,
    EXTRACT(EPOCH FROM (NOW() - MIN(created_at) FILTER (WHERE offset_acked IS NULL))) AS lag_seconds,
    COUNT(*) FILTER (WHERE offset_acked IS NOT NULL
                       AND created_at > NOW() - INTERVAL '1 hour') AS acked_last_hour
FROM <service>.outbox;

Три числа дают картину сразу: сколько застряло, насколько давно, как быстро forwarder работал в последний час (для сравнения).

Prometheus

outbox_rows_total{service, status="unacked"}       -- то же unacked
outbox_forwarder_lag_seconds{service}              -- то же lag_seconds
outbox_forwarder_errors_total{service, reason}     -- причина сбоя
outbox_forwarder_publish_duration_seconds{service} -- насколько медленно
                                                      идёт publish
events_published_total{service, topic, event_type} -- что успешно уходит

Trace

Открой в Tempo след последнего «зависшего» aggregate_id. Waterfall покажет промежуток между спаном db.InsertOutboxRow и спаном kafka.Publish — это и есть лаг конкретного сообщения.

Типовые причины

1. Forwarder не запущен

Симптом. outbox_forwarder_lag_seconds не публикуется совсем или не обновляется минуты. unacked растёт линейно.

Проверка. В репозитории сервиса forwarder запускается внутри cmd/server/main.go goroutine'ой (см. ../patterns/outbox.md §Forwarder). Если pod жив, но forwarder-goroutine упала — логи покажут panic либо однократный error forwarder exited.

k8s: kubectl get pod -l app=<service> — если статус CrashLoopBackOff или OOMKilled, forwarder не стартует совсем.

Фикс. - OOM: подними memory limit у pod'а; проверь, не течёт ли forwarder (при нормальной нагрузке он ест 20–50 MiB). - Panic после старта: смотри middleware.Recoverer — если он не включён во forwarder-router, panic не перехватывается, goroutine умирает. Добавь.

2. Kafka недоступен

Симптом. outbox_forwarder_errors_total{reason="publish"} растёт, events_published_total не увеличивается, unacked накапливается.

Проверка.

docker compose exec <service> sh -c "nc -zv <kafka-host> 9092"
kafka-topics.sh --bootstrap-server "$KAFKA_BROKERS" --list

Фикс. Восстанови Kafka. Forwarder автоматически разгонится после: строки в outbox остались, SELECT FOR UPDATE SKIP LOCKED заберёт их на следующем тике. Никакого ручного вмешательства не нужно — не делай TRUNCATE outbox, это теряет события.

3. Poll interval слишком большой

Симптом. Лаг стабильно 0.5–2 секунды при низкой нагрузке, но растёт до 10+ секунд под peak QPS. Errors = 0. Publish latency = 0.

Причина. PollInterval forwarder'а = 500 ms (default). При publish rate >> 1000 msg/s один батч читает не всё, что накопилось между poll'ами, и хвост копится.

Фикс.

sqlSub, _ := watermillSQL.NewSubscriber(stdDB, watermillSQL.SubscriberConfig{
    PollInterval: 100 * time.Millisecond, // вместо 500
    // ...
}, watermillLogger)

Уменьшение PollInterval повышает нагрузку на БД (больше SELECT FOR UPDATE запросов). Опуская до 50 ms и ниже — приготовься, что outbox-таблица станет «горячей» точкой. Сначала убедись, что это действительно bottleneck (а не пункт 4).

4. DB pool исчерпан

Симптом. outbox_forwarder_publish_duration_seconds высокий (p99 > 1s), при этом на Kafka-стороне publish-latency микросекунды. Forwarder ждёт соединение к БД — не Kafka.

Причина. Forwarder делит pgxpool с HTTP-handler'ами. Под пиком handler'ы выгребают все соединения, forwarder висит в Acquire.

Фикс. - Выдели forwarder'у отдельный pool с 3–5 соединениями. В cmd/server/main.go:

forwarderPool, _ := pgxpool.New(ctx, cfg.DB.DSN())
forwarderPool.Config().MaxConns = 5
  • Либо подними DB_POOL_MAX общего пула и подключи PgBouncer перед Postgres.

5. Несколько forwarder'ов на один outbox

Симптом. Лаг стабилен, но events_published_total показывает дубли per aggregate (consumer говорит «я видел это сообщение дважды в течение секунды»).

Причина. replicas > 1 у Deployment, внутри каждого — свой forwarder. SELECT FOR UPDATE SKIP LOCKED защищает от одновременной обработки одной строки, но при rebalance/network glitch возможны дубли.

Фикс. - В k8s-манифесте forwarder-сервиса: replicas: 1. Outbox forwarder — singleton per service. - Если нужен HA без простоя в момент рестарта — запускай forwarder как отдельный Deployment (<service>-forwarder) с replicas: 1 и PodDisruptionBudget: minAvailable: 0, либо полагайся на быстрый рестарт pod'а (typical 5–10s gap считаем приемлемым). - Dedup на consumer-стороне (middleware.Deduplicator, см. ../patterns/idempotent-consumer.md) гасит редкие дубли — это штатный путь at-least-once.

6. «Отравленное» сообщение застряло

Симптом. unacked медленно растёт, outbox_forwarder_errors_total{reason="marshal"} или reason="publish" инкрементится на одних и тех же timestamps.

Причина. Одна строка в outbox невалидна (например, payload — не JSON, или Event-Type в metadata отсутствует). Forwarder пытается публиковать, получает ошибку, retry'ит, та же строка каждый раз.

Проверка.

SELECT uuid, created_at, metadata->>'Event-Type' AS event_type,
       LENGTH(payload::text) AS size_bytes
FROM <service>.outbox
WHERE offset_acked IS NULL
ORDER BY created_at
LIMIT 10;

Посмотри на первую строку: payload корректный? Event-Type на месте?

Фикс. - Если payload реально битый (редкий случай, баг в publisher) — строку надо вручную перенести в отдельную таблицу для разбора и пометить как acked, чтобы не блокировала хвост. Никогда не DELETE без архивации:

BEGIN;
INSERT INTO <service>.outbox_quarantine SELECT * FROM <service>.outbox
    WHERE uuid = '<broken-uuid>';
UPDATE <service>.outbox SET offset_acked = offset_consumed
    WHERE uuid = '<broken-uuid>';
COMMIT;

(Таблица outbox_quarantine — та же схема, создаётся отдельной миграцией, используется только для ручного разбора.) - Пофикси publisher, чтобы такие сообщения больше не генерировались.

7. Cleanup job не запускается

Симптом. Таблица outbox содержит миллионы acked-строк, SELECT FOR UPDATE SKIP LOCKED становится медленным из-за разрастания partial-индекса / раздувания heap'а.

Проверка.

SELECT
    COUNT(*) FILTER (WHERE offset_acked IS NOT NULL
                       AND created_at < NOW() - INTERVAL '7 days') AS old_acked,
    pg_size_pretty(pg_total_relation_size('<service>.outbox'))    AS total_size
FROM <service>.outbox;

Если old_acked в миллионах — cleanup не отработал.

Фикс. - Запусти cleanup вручную:

DELETE FROM <service>.outbox
 WHERE offset_acked IS NOT NULL
   AND created_at < NOW() - INTERVAL '7 days';
VACUUM <service>.outbox;

Под нагрузкой делай батчами (по 100k строк), чтобы не держать долгую транзакцию. - Проверь, почему CronJob не отработал: k8s CronJob status, suspended-флаг, расписание. Починь cron-триггер в infra-репо.

8. Long transaction блокирует чтение outbox

Симптом. Лаг растёт, publish errors = 0, при этом pg_stat_activity показывает транзакции idle in transaction длительностью > 1 минуты.

Причина. Бизнес-handler открыл транзакцию, дёрнул внешний API, тот завис без таймаута → BEGIN держится → SELECT FOR UPDATE SKIP LOCKED не может взять свежие строки в этой же транзакции (не может, потому что сам forwarder читает в своей tx, но если бизнес-tx затянулась, она блокирует VACUUM, а тот блокирует индекс — косвенный путь).

Проверка.

SELECT pid, usename, state, xact_start, query
FROM pg_stat_activity
WHERE state = 'idle in transaction'
  AND xact_start < NOW() - INTERVAL '1 minute'
ORDER BY xact_start;

Фикс. - Убей зависшие транзакции: SELECT pg_cancel_backend(<pid>) (мягко) или pg_terminate_backend(<pid>) (жёстко). - Ищи root cause: defer tx.Rollback() забыт, внешний HTTP-клиент без таймаута, select без <-ctx.Done(). См. ../conventions/shutdown.md и ../conventions/db-pgx.md.

Playbook восстановления

  1. Не останавливай записи в outbox. Никогда. Это ломает бизнес-поток без необходимости — outbox как раз предназначен принимать строки, пока forwarder разгребает.
  2. Restart forwarder (рестарт pod'а) — самый быстрый шаг, если непонятно, что именно не так. Занимает секунды.
  3. Если после рестарта лаг продолжает расти — пройди по пунктам 1–8 в указанном порядке.
  4. Если unacked-строк много (десятки тысяч), ждать drain'а — приемлемо. Monitor лаг в реальном времени через SQL раз в минуту; смотри, что unacked убывает.
  5. Если лаг > 1 часа и растёт — это уже инцидент по SLO. Эскалируй согласно процедуре on-call.

Anti-patterns

  • TRUNCATE outbox / DELETE FROM outbox WHERE offset_acked IS NULL. Теряем события, которые ещё не дошли до Kafka. Downstream-сервисы никогда не узнают об этих фактах. Запрещено.
  • Копировать unacked напрямую в Kafka через kafka-console-producer. Потенциально допустимо, если consumer'ы дедуплицируют по Event-Id (что они и должны). Но лучше не делать руками — восстанавливай forwarder и дай ему разгрести штатно.
  • Выключать forwarder на время. Только в пре-продакшене и только если все consumer'ы тоже выключены. В prod — никогда: бизнес-операции пишут в outbox, события копятся молча.
  • Писать в Kafka напрямую из бизнес-логики, пока «чинишь forwarder». Это классический dual-write (см. ../patterns/outbox.md §Anti-patterns). Запрещено.

Превенция

  • Monitor обязателен. Alerts на outbox_forwarder_lag_seconds > 60 (5 минут), outbox_rows_total{status="unacked"} > 1000, rate(outbox_forwarder_errors_total[5m]) > 0. Как добавить alert — add-metric-and-alert.md.
  • Load test. Перед включением сервиса в prod прогоняй нагрузку на ожидаемом peak QPS и фиксируй, какой лаг при этом. Если больше секунды — настраивай pool/poll interval заранее.
  • PodDisruptionBudget. Для forwarder-Deployment minAvailable: 1 (если singleton — maxUnavailable: 1 и replicas 1) — минимизирует окно простоя при rolling update.
  • Cleanup CronJob — обязательная часть setup'а сервиса, не опциональная. Создаётся одновременно с outbox-таблицей.

Связанные разделы