Задание висело сутки: у запроса к стороннему API не было таймаута

MAATRIX

В пятницу вечером мониторинг молчал, деплой прошёл штатно, а в понедельник утром выяснилось, что статусы заказов не обновлялись с пятницы. Один воркер Celery тихо завис на вызове к API курьерской службы и провисел так почти сутки, пока никто не смотрел на очередь. Ниже — как мы это нашли, какие версии отбросили и что изменили, чтобы больше не спать спокойно, полагаясь на "само пройдёт".

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

Система — интернет-магазин с фоновой обработкой заказов через Celery. Раз в пять минут periodic task опрашивает API курьерской службы и обновляет статусы доставки в базе. Воркер запущен с concurrency=4, задача сама по себе лёгкая: пройтись по списку активных заказов, дёрнуть GET /tracking/{id} у стороннего API, записать результат.

В пятницу около 18:40 по логам одна из задач ушла в обработку и не вернулась. Celery beat, как и положено, продолжал каждые пять минут ставить новую задачу того же типа в очередь. Задача была защищена блокировкой через redis (SETNX на ключ sync-tracking-lock с TTL в 10 минут), чтобы два запуска не пересекались — но зависший воркер держал слот concurrency, а не отпускал блокировку истечением TTL: блокировка сама снялась через 10 минут, и следующие задачи начали запускаться, но уже в трёх оставшихся слотах воркера. К субботе утром все четыре слота были заняты подвисшими задачами разных запусков, и с этого момента ни одна новая задача этого типа выполниться не могла — она просто стояла в очереди Redis, а исполнять её было некому.

К утру понедельника в очереди накопилось почти 300 задач синхронизации трекинга, ни одна не выполнилась с пятницы, а active queue length в Flower показывал ровный рост без единого провала — типичная картина "конвейер встал, а на входе продолжают клеить бумагу".

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

Первым делом посмотрели на воркер:

celery -A app inspect active

Показал четыре задачи sync_tracking_statuses, у каждой time_start — разные моменты за последние двое суток, самая старая — с пятницы, 18:41. Ни одна не завершилась и не упала с исключением — просто "висит".

CPU воркера — почти ноль:

top -p $(pgrep -f 'celery worker' | tr '\n' ',')

Все четыре процесса-исполнителя в состоянии S (sleep), а не R — то есть не молотят цикл, а ждут чего-то. Это сразу исключило горячий бесконечный цикл — будь там while True без sleep, CPU был бы под 100% на ядро.

Дальше — сетевые соединения этих процессов:

ss -tnp | grep -E ':(443|80)\b' 

У каждого зависшего PID — по одному TCP-соединению к IP курьерского API в состоянии ESTABLISHED, Recv-Q и Send-Q в нулях. То есть соединение установлено, данных ни туда ни оттуда не идёт, и оно просто существует уже много часов. Через ss -i посмотрели время жизни сокета — у самого старого ESTABLISHED соединения возраст был больше 60 часов.

Логи приложения по этим задачам пустые — ни одной строки после "started tracking sync", потому что следующая строка кода писалась в лог уже после ответа от API, а ответа не было.

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

Первая версия — сеть между нашим сервером и API курьера. Проверили mtr до хоста API, пинги и трассировка проходили нормально, значит, это не был затяжной network partition — маршрут был жив в моменте проверки (правда, это не доказывало, что он был жив всё время зависания, но других признаков сетевой аномалии не нашли).

Вторая версия — блокировка на стороне PostgreSQL: может, задача ждёт лок на строку заказа, который держит другая транзакция. Проверили:

SELECT pid, state, wait_event_type, wait_event, query
FROM pg_stat_activity
WHERE state != 'idle';

Ни одной задачи в wait_event_type = 'Lock'. Более того, у зависших Celery-процессов вообще не было активных запросов к базе на момент проверки — они до базы ещё не дошли, всё зависание было на HTTP-запросе к стороннему API, который в коде идёт раньше записи в БД.

Третья версия — бесконечный цикл ретраев внутри клиентской библиотеки курьера. Открыли исходники обёртки — там действительно был retry декоратор, но с ограничением в 3 попытки и логированием на каждой, а логов не было вообще. Значит, зависли не на ретрае, а на самом первом вызове.

Четвёртая версия, уже ближе к делу — OOM или своп, который тормозит процесс до полной остановки. Проверили dmesg | grep -i kill и free -h — память в порядке, OOM killer не срабатывал, своп не рос.

Реальная причина: HTTP-запрос без таймаута повис на мёртвом соединении

В коде обёртки над API курьера вызов выглядел так:

import requests

def get_tracking_status(order_id: str) -> dict:
    resp = requests.get(
        f"https://api.courier.example/tracking/{order_id}",
        headers={"Authorization": f"Bearer {API_TOKEN}"},
    )
    resp.raise_for_status()
    return resp.json()

Ключевая деталь: у requests.get() не передан параметр timeout. По умолчанию в requests это означает timeout=None — библиотека будет ждать ответа сколько угодно, без ограничения по времени, полагаясь целиком на TCP-стек ОС.

А TCP-стек сам по себе не закрывает "тихо умершее" соединение, если явно не включён keepalive. Наш сервер не выставлял SO_KEEPALIVE на сокете (это тоже не делается автоматически в requests/urllib3), поэтому если на стороне курьерского API соединение оборвалось не штатно — например, их балансировщик перезапустился и не отправил FIN/RST, либо промежуточный NAT/файрвол вытеснил запись о соединении из своей таблицы трансляций и молча начал ронять пакеты — с точки зрения нашего клиента сокет остаётся в состоянии ESTABLISHED бесконечно. Клиент не получает ни данных, ни ошибки — он просто ждёт в recv(), потому что операционная система не считает соединение мёртвым: пакетов нет, но и явного сигнала о разрыве тоже нет.

Убедились в этом через strace на живом (тогда ещё висящем) процессе:

strace -p <PID> -tt

Вывод стоял на одной строке:

14:02:11.442211 recvfrom(7, ...) = ...

и не двигался минутами — процесс блокирован ровно на чтении из сокета, без единой системной ошибки вроде ETIMEDOUT или ECONNRESET, потому что таких ошибок никто и не сгенерировал: с точки зрения ядра соединение просто "тихое", а не разорванное.

Похожую картину подтвердил py-spy:

py-spy dump --pid <PID>

Стек показал, что процесс застрял именно в urllib3.connection.HTTPSConnection.getresponse() → http.client.HTTPResponse.read() → системный вызов recv. Ни строчки прикладного кода — всё ожидание происходит внутри библиотеки, ровно там, где мы не поставили ограничение по времени.

Отдельно проверили у самого курьера историю инцидентов за пятницу — у них действительно было плановое обновление балансировщиков около 18:35, то есть по времени совпадает с моментом, когда у нас зависли первые соединения. По всей видимости, часть уже установленных keep-alive соединений на их стороне была разорвана без корректного TCP-закрытия — какие-то клиенты получили RST и переподключились сами, а нашему клиенту просто "повезло" не получить вообще ничего.

Как раскопали цепочку целиком

Порядок действий, который в итоге привёл к причине:

1. celery inspect active — увидели, какие именно задачи висят и с какого момента.
2. top по PID воркеров — исключили горячий цикл (CPU около нуля).
3. ss -tnp по PID — нашли зависшие TCP-соединения в ESTABLISHED без обмена данными.
4. pg_stat_activity — исключили блокировки в базе.
5. strace -p на живом процессе — увидели блокировку ровно на recvfrom.
6. py-spy dump — увидели, в какой библиотечной функции застряли, без единой прикладной строки в трассировке.
7. Грепнули код на предмет всех вызовов requests. без timeout= — обёртка над API курьера оказалась не единственной.

Отдельно стоит сказать, почему это не поймал ни один алерт заранее: у нас был мониторинг доступности самого API курьера (обычный HTTP-чек раз в минуту с таймаутом 5 секунд), и он был зелёным — API отвечал нормально на новые подключения, проблема была только в уже установленном "подвисшем" соединении конкретного воркера. Мониторинг снаружи не видел внутреннего состояния процесса.

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

Первым делом прошлись по всей кодовой базе и добавили явные таймауты во все вызовы requests:

DEFAULT_TIMEOUT = (5, 30)  # (connect timeout, read timeout) в секундах

def get_tracking_status(order_id: str) -> dict:
    resp = requests.get(
        f"https://api.courier.example/tracking/{order_id}",
        headers={"Authorization": f"Bearer {API_TOKEN}"},
        timeout=DEFAULT_TIMEOUT,
    )
    resp.raise_for_status()
    return resp.json()

Раздельные connect- и read-таймауты важны: на установку соединения обычно достаточно нескольких секунд, а вот ответ сторонний сервис может формировать дольше — не хочется резать легитимные, но небыстрые запросы тем же лимитом, что и зависшее подключение.

Чтобы не полагаться на память каждого разработчика, завели общую requests.Session с таймаутом по умолчанию через кастомный HTTPAdapter, и добавили в CI шаг, который grep'ом ищет requests.get(, requests.post( и подобные вызовы без timeout= в диффе пул-реквеста — это не панацея, но ловит забытые случаи до продакшна.

Добавили страховку на уровне самого Celery — жёсткий лимит времени на задачу, который убьёт процесс, даже если код внутри всё равно где-то зависнет:

app.conf.task_time_limit = 120        # жёсткий kill через SIGKILL
app.conf.task_soft_time_limit = 90    # SoftTimeLimitExceeded для graceful-обработки

from celery.exceptions import SoftTimeLimitExceeded

@app.task(bind=True, max_retries=3)
def sync_tracking_statuses(self):
    try:
        ...
    except SoftTimeLimitExceeded:
        logger.warning("sync_tracking_statuses: soft time limit hit, aborting")
        raise

Включили TCP keepalive на уровне сокета для долгоживущих HTTP-клиентов, чтобы половинчато-мёртвые соединения обнаруживались ядром за минуты, а не висели неопределённо:

import socket
from urllib3.connection import HTTPConnection

HTTPConnection.default_socket_options += [
    (socket.SOL_SOCKET, socket.SO_KEEPALIVE, 1),
    (socket.IPPROTO_TCP, socket.TCP_KEEPIDLE, 30),
    (socket.IPPROTO_TCP, socket.TCP_KEEPINTVL, 10),
    (socket.IPPROTO_TCP, socket.TCP_KEEPCNT, 3),
]

Добавили retry с экспоненциальной паузой и ограничением попыток через tenacity для вызовов к стороннему API — это не про то, что "теперь можно снова ждать вечно", а про то, чтобы кратковременные сбои не превращались в ручной разбор инцидента:

from tenacity import retry, stop_after_attempt, wait_exponential

@retry(stop=stop_after_attempt(3), wait=wait_exponential(multiplier=1, max=10))
def call_courier_api(order_id: str):
    return requests.get(url, timeout=DEFAULT_TIMEOUT)

И, наконец, завели пинг на healthchecks.io прямо внутри задачи: она сообщает о старте и об успешном завершении, а если сигнала завершения нет дольше заданного grace period — приходит алерт в Telegram, а не через двое суток тишины. Это отдельно закрывает класс задач, где очередь фоновых задач разрастается и никто этого не замечает, пока не станет слишком поздно.

Как теперь следим, чтобы не повторилось

Помимо healthchecks.io, добавили в Prometheus метрику возраста самой старой активной задачи в очереди Celery (через celery-exporter) и алерт, если oldest_task_age_seconds > 600 для этого типа задач — при нормальной работе задача живёт секунды, а не минуты. Отдельно вынесли мониторинг cron-задач через healthchecks.io на все периодические джобы в проекте, а не только на ту, что уже подвела.

Осознанно не стали делать общий socket.setdefaulttimeout() на уровне всего процесса — это глобальная настройка, которая аукается неожиданно в других местах (например, в клиентах баз данных, которые сами управляют таймаутами), поэтому предпочли явные таймауты в каждой точке интеграции со сторонними сервисами.

Отдельная неприятная деталь, которую стоит сказать честно: жёсткий task_time_limit — это подстраховка, а не решение первопричины. Если бы мы полагались только на него без явного timeout в самом запросе, задача просто убивалась бы через 120 секунд каждый раз при похожем сбое API курьера, но сама проблема — зависающий на минуты запрос — осталась бы незамеченной под слоем "ну и ладно, Celery перезапустит". Оба уровня защиты нужны вместе: таймаут на уровне HTTP-клиента ловит проблему быстро и с понятной причиной в логе, а лимит на уровне задачи — это последняя линия обороны, если где-то всё равно забыли таймаут.

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