Один воркер завис на блокирующем вызове и утянул всю очередь

MAATRIX

В пятницу вечером очередь исходящих вебхуков начала расти линейно и без остановки — не рывками, как при обычных всплесках нагрузки, а ровной прямой вверх. Все воркеры были живы, процессы отвечали на systemctl status, CPU и память в норме, база не жаловалась на нагрузку. При этом ни одна новая задача не обрабатывалась. Разбор занял два с половиной часа и уткнулся в один процесс, который держал общую блокировку и молча ждал ответа от чужого сервера без единого таймаута.

Что сломалось

Первый сигнал прилетел из мониторинга очереди: метрика queue_depth для очереди webhook_delivery начала расти около 21:40 и не останавливалась — с обычных 20-50 задач в буфере до нескольких тысяч за час. Обычно такой рост случается при всплеске входящих событий (например, массовая рассылка триггерит вебхуки для сотен клиентов разом), и график быстро выходит на полку, когда воркеры разгребают накопленное. Здесь полки не было вообще — линия шла строго вверх с постоянным наклоном.

Второй сигнал — алерт от аптайм-монитора клиента: вебхуки о смене статуса заказа перестали доходить. Саппорт получил несколько тикетов от интеграторов в течение 20 минут. Задержка доставки вебхука выросла с обычных 1-3 секунд до бесконечности — задачи просто не выполнялись.

При этом все внешние признаки говорили, что сервис жив:

• 6 процессов воркера в systemctl status webhook-worker — все active (running), ни одного рестарта;
• CPU по всем воркерам — 1-3%, память стабильна, ни одного OOM в dmesg;
• подключение к очереди (Redis) — PING отвечает, redis-cli info clients показывает нормальное число подключений;
• подключение к базе — pg_stat_activity без признаков перегрузки по количеству активных сессий.

Ни один стандартный дашборд не показывал ничего похожего на инцидент, кроме одной метрики — глубины очереди. Это и сбивало с толку: обычно рост очереди сопровождается ростом CPU (воркеры пытаются успеть) либо ростом числа соединений к базе. Здесь всё было тихо, будто воркеры просто перестали существовать, оставаясь при этом «живыми» с точки зрения systemd.

Как была устроена очередь до инцидента

Чтобы понять, почему один зависший воркер положил всю систему, нужно на секунду остановиться на архитектуре. Очередь задач хранилась не в брокере с честным round-robin распределением, а в таблице PostgreSQL — классический паттерн «очередь на базе» (outbox/job table), выбранный когда-то ради простоты и транзакционной согласованности с основной бизнес-логикой.

Схема claim-а задачи выглядела так:

BEGIN;
SELECT pg_advisory_lock(42);  -- глобальный лок на "выдачу следующей задачи"

SELECT id, payload FROM webhook_jobs
WHERE status = 'pending'
ORDER BY created_at
LIMIT 1
FOR UPDATE SKIP LOCKED;

UPDATE webhook_jobs SET status = 'processing', worker_id = :pid
WHERE id = :job_id;

COMMIT;

Идея advisory-лока была в том, чтобы гарантировать строгий порядок выдачи задач (FIFO) и не полагаться только на SKIP LOCKED, который допускает случаи, когда два воркера почти одновременно видят одну и ту же «верхнюю» строку до коммита друг друга. Разработчик, добавивший pg_advisory_lock(42) полгода назад, хотел временно подстраховаться от гонки при выдаче — и это должно было быть узким местом на миллисекунды: захватили лок, взяли строку, отпустили лок, пошли обрабатывать задачу уже без него.

Проблема была не в самой идее, а в реализации: pg_advisory_unlock(42) вызывался не сразу после COMMIT, а в блоке finally в самом конце обработки задачи — после того, как воркер уже успевал сходить в HTTP-клиент клиента и получить ответ. То есть лок держался не миллисекунды на выдачу, а на всё время доставки вебхука, включая сетевой вызов к серверу клиента. Это оставалось незамеченным полгода, потому что HTTP-вызовы обычно укладывались в 200-800 мс — лок держался коротко, и никто не заметил, что архитектурно он защищает не то, что должен.

Что видели в логах и метриках при расследовании

Первым делом посмотрели на сами процессы воркеров — py-spy dump --pid <pid> (инструмент для снятия стека выполнения живого Python-процесса без остановки) на каждом из 6 PID показал одинаковую картину для пяти воркеров:

Thread 0x7f2a1c0 (idle): "MainThread"
    acquire (threading.py:263)
    pg_advisory_lock (db/queue.py:41)
    claim_next_job (db/queue.py:58)
    run (worker.py:112)

Пять процессов ждали на pg_advisory_lock — это было ожидаемо, раз лок кто-то держит. Шестой процесс показал другую картину:

Thread 0x7f2a1d0 (running): "MainThread"
    recv_into (ssl.py:1174)
    read (http/client.py:466)
    getresponse (http/client.py:1348)
    send (requests/adapters.py:486)
    deliver_webhook (workers/webhook.py:73)

Этот процесс сидел внутри socket.recv(), ожидая данные от TCP-соединения, которое к тому моменту уже не отвечало. Через pg_stat_activity и pg_locks подтвердили: этот же PID действительно держит pg_advisory_lock(42), и именно на нём выстроилась очередь остальных пяти воркеров плюс планировщик новых задач, который тоже пытался взять этот лок для служебных целей.

SELECT pid, granted, mode, objid
FROM pg_locks
WHERE locktype = 'advisory';

Показал одну строку с granted = true (наш зависший воркер) и пять строк с granted = false — все остальные воркеры, выстроившиеся в очередь за тем же локом.

Дальше через ss -tnp | grep <pid зависшего воркера> посмотрели состояние TCP-соединения — оно было ESTABLISHED, без каких-либо признаков разрыва. Соединение к серверу клиента, который принимает вебхуки, физически осталось «открытым» на уровне TCP, но сервер клиента перестал отправлять данные — ни ответа, ни FIN, ни RST. Классический «чёрный ящик»: пакеты уходят, но обратно ничего не возвращается, и на прикладном уровне это неотличимо от «сервер очень долго думает».

Гипотезы, которые отбросили

Перегрузка базы. Первая мысль — деградация PostgreSQL из-за роста числа задач в таблице webhook_jobs. Проверили pg_stat_activity, pg_stat_statements по времени выполнения запросов claim-а — среднее время SELECT ... FOR UPDATE SKIP LOCKED было в пределах 1-2 мс, никакой деградации по I/O не было, iostat на сервере базы был почти в простое. Гипотезу отбросили в первые 10 минут.

Падение Redis. Воркеры также использовали Redis для дедупликации задач (чтобы не отправить один и тот же вебхук дважды при ретраях планировщика). redis-cli --latency показал задержки в пределах 0.3 мс, INFO stats — обычное число команд в секунду. Redis был ни при чём, хотя изначально казался логичным подозреваемым — очередь на базе и дедупликация на Redis работают в связке, и было соблазнительно списать всё на связку между ними.

Сетевой сбой между воркерами и базой. Проверили pg_stat_activity.wait_event_type — если бы был сетевой затык между воркером и базой, увидели бы много сессий в состоянии idle с давним state_change, либо ошибки разрыва соединения в логах postgresql.log. Ничего подобного не было — соединения к базе у всех воркеров были в порядке, лог PostgreSQL был чист от ошибок сети.

Утечка памяти или деградация GC. Раз CPU был низким, а не высоким, гипотеза о зависании из-за сборщика мусора или утечки не подтверждалась сразу, но её всё равно проверили через py-spy dump — если бы процесс был занят GC, стек показал бы это явно. Стек показывал чистое ожидание на сетевом сокете, никакого CPU-bound кода.

Каждую гипотезу проверяли конкретной командой и конкретной метрикой, а не «на глаз» — так неверные направления исключались быстрее, чем при попытке чинить наугад.

Настоящая причина

Настоящая причина — комбинация из двух независимых по отдельности безобидных решений, которые вместе дали катастрофу:

1. HTTP-клиент внутри deliver_webhook() вызывал requests.post(url, json=payload) без параметра timeout. По умолчанию requests не ограничивает время ожидания ответа вообще — если сервер принял TCP-соединение и просто перестал отвечать, вызов может висеть неограниченно долго.
2. Сервер клиента, принимающий вебхук, за несколько дней до инцидента переехал на новый балансировщик с более строгими правилами файрвола. Новое правило безопасности молча дропало пакеты вместо того, чтобы отвечать RST или ICMP unreachable — соединение оставалось ESTABLISHED на нашей стороне бесконечно, потому что операционная система не получала никакого сигнала о разрыве. Обычный ретрай-таймаут HTTP-клиента здесь не спасал именно потому, что клиент никакого таймаута не задавал.

По отдельности ни одна из этих проблем не была бы серьёзной: без блокировки один зависший воркер просто перестал бы забирать новые задачи, а пять остальных продолжали бы разгребать очередь — деградация, а не остановка. Без advisory-лока, держащегося на всё время обработки, зависание одного HTTP-вызова осталось бы локальной проблемой одного воркера. Вместе они дали классический эффект «одна точка отказа тянет за собой всю систему»: shared-ресурс, который должен защищать миллисекундную операцию, оказался завязан на операцию с неограниченным временем выполнения.

Что изменили после инцидента

Сразу после восстановления (перезапуск зависшего процесса и pg_advisory_unlock_all() от имени суперпользователя, что немедленно разблокировало остальных пять воркеров и очередь начала разгребаться за минуты) занялись причинами по порядку:

Таймауты на все внешние вызовы. Прошлись grep -rn "requests\.\(get\|post\|put\|delete\)" . по всему кодовому базе и добавили обязательный timeout=(3, 10) (3 секунды на коннект, 10 на чтение) везде, где его не было. Дополнительно завели общую requests.Session с адаптером, у которого таймаут задан на уровне класса — конкретно, обёртку-клиент, через которую ходит весь код, чтобы новый вызов без таймаута физически нельзя было написать по умолчанию.

Убрали advisory-лок из-под сетевого вызова. Переписали claim задачи так, чтобы лок держался ровно на время SELECT ... FOR UPDATE SKIP LOCKED + UPDATE, а не на всё время обработки:

def claim_next_job(conn):
    with conn.cursor() as cur:
        cur.execute("SELECT pg_advisory_lock(42)")
        try:
            cur.execute("""
                SELECT id, payload FROM webhook_jobs
                WHERE status = 'pending'
                ORDER BY created_at LIMIT 1
                FOR UPDATE SKIP LOCKED
            """)
            job = cur.fetchone()
            if job:
                cur.execute(
                    "UPDATE webhook_jobs SET status='processing' WHERE id=%s",
                    (job.id,),
                )
            conn.commit()
            return job
        finally:
            cur.execute("SELECT pg_advisory_unlock(42)")

Теперь HTTP-вызов к клиенту происходит уже после того, как функция claim_next_job вернула управление и лок отпущен. Отдельно обсуждали, не убрать ли advisory-лок вообще в пользу чистого SKIP LOCKED — по факту он действительно почти избыточен, но команда решила оставить его как есть с коротким временем удержания, а вопрос полного отказа от него вынесли в отдельную задачу с более осторожным тестированием.

Watchdog по времени выполнения задачи. Добавили ограничение на максимальное время обработки одной задачи на уровне воркера — если задача выполняется дольше 30 секунд, воркер убивает себя по SIGALRM и перезапускается через systemd (Restart=always), а задача возвращается в очередь через тот же механизм, что обрабатывает штатные ретраи.

Алерты на рост очереди без роста CPU. Раньше алертили только на абсолютную глубину очереди. Добавили вторую метрику — производную d(queue_depth)/dt в сочетании с суммарным CPU воркеров: если очередь растёт, а CPU воркеров не растёт вместе с ней, это подозрительный паттерн (воркеры не работают, а не просто не успевают), и алерт уходит с более высоким приоритетом.

Отдельный лог по времени удержания advisory-локов. Добавили периодический запрос к pg_locks (раз в минуту через cron на самой базе), который логирует любую advisory-блокировку, удерживаемую дольше 5 секунд — такого раньше не существовало вообще, и именно поэтому расследование заняло почти час только на то, чтобы понять, что дело в локе, а не в самой базе.

Частые вопросы