lekss361/gendesign

Fork 0

Алерты GlitchTip: медленный отказ Telegram отвечает 502 и уходит в фон, а не обрывается на 10-й секунде #3555

Merged

bot-backend merged 1 commit from fix/glitchtip-delivery into main

2026-09-17 09:22:11 +00:00

bot-backend commented

2026-09-17 07:42:19 +00:00

Collaborator

#3157 — доставка алертов GlitchTip: медленный отказ Telegram больше не рвётся на таймауте отправителя

Что было

На приёмнике (tradein-mvp/backend/app/api/v1/glitchtip.py) у синхронной пересылки в Telegram был таймаут только на один HTTP-запрос (_INTERACTIVE_SEND_TIMEOUT_S=8). После ретранслятора (#3471) попыток стало больше одной: запрос через relay, при отказе ещё один напрямую, пауза 2 с, повтор. В худшем случае это заметно больше 10 с. GlitchTip ждёт ответ ровно 10 с: в glitchtip-worker apps/alerts/webhooks.py send_webhook стоит aiohttp.ClientTimeout(total=10), а TimeoutError там молча проглатывается.

Улики с прода, 16.09.2026, UTC

Проверено 17.09 через Loki, Prometheus и контейнеры, только чтение.

GlitchTip отправил уведомление в 16:42:39. Caddy (gendesign-caddy-1) записал этот POST на /ops/glitchtip-webhook так: status=0, duration=10.16, size=0. Отправитель оборвал соединение.
tradein-backend:
- 16:42:47.688 «ретранслятор недоступен, одна попытка напрямую к Telegram» (relay упал через 8 с);
- 16:42:52.690 «network error (попытка 1/1): ConnectTimeout — retry через 2.0s».
  После этого ни «не удалось переслать», ни 502, ни фоновой доставки.
Процесс перезапустился в 16:41:20 (process_start_time_seconds). Ряд http_requests_total{route="/ops/glitchtip-webhook",status="200"} появился в скрейпе 16:42:58 со значением 1. Другого POST на вебхук в Caddy за 16:40–16:45 нет, так что по всем признакам это тот же запрос. Вторая попытка прошла около 16:42:55, и хендлер досчитал себе 200 уже после того, как отправитель ушёл.
Строки access-log для этого запроса нет. uvicorn 0.49.0 в RequestResponseCycle.send при self.disconnected делает return до записи access-log, то есть ответ разорванному клиенту просто выбрасывается.

Поправка к триажу. В разборе было сказано «алерт пропал, счётчик не инкрементировался». Счётчик инкрементировался как 200, это спрятал сброс при рестарте в 16:41:20. Алерт, скорее всего, дошёл в Telegram примерно через 5 с после того, как GlitchTip сдался. Прямо проверить доставку в Telegram нечем. Сам дефект от этого не меняется: отправитель видит обрыв (status=0, is_sent=True), приёмник записывает 200 без строки в access-log, и эти три источника расходятся в исходе. А если бы и вторая попытка не прошла, 502 и фоновый повтор отработали бы уже в пустоту.

Что сделано

Минимальный дифф в glitchtip.py:

вся синхронная попытка (лимитер, relay, прямой путь, пауза, повтор) обёрнута в async with asyncio.timeout(_INTERACTIVE_SEND_DEADLINE_S), где потолок 7 с. Запас 3 с до 10 с GlitchTip оставлен на Caddy и чтение тела;
TimeoutError ловится вместе с TelegramError и идёт тем же путём: logger.exception, JSONResponse(502) и BackgroundTask(retry_forward_alert). Фоновая доставка работает по воркерной политике (relay, потом напрямую, до 3×5 попыток) и пишет свой итог: «доставлено фоном» или «текст потерян».

Цена: попытка, оборванная потолком, могла на самом деле дойти до Telegram, тогда фоновая доставка создаст дубль сообщения. Этот риск at-least-once уже был принят для ретраев ReadTimeout в _request.

Тесты

Новый tests/test_glitchtip_alert_retry.py::test_slow_telegram_answers_502_before_sender_gives_up. Фейковый клиент зависает на 5 с, потолок уменьшен до 0.2 с. Проверяется: ответ 502; время ответа меньше 2 с; 2 вызова send_message (зависшая синхронная попытка и доставка фоном тем же текстом); боевой потолок _INTERACTIVE_SEND_DEADLINE_S не больше 8 (10 с GlitchTip минус запас).
tests/test_glitchtip_alert_retry.py tests/test_glitchtip_webhook.py: 24 passed, rc=0.
Весь сьют МЕРА backend: DATABASE_URL=... uv run python -m pytest tests/ -q -p no:cacheprovider — 6226 passed, 42 skipped, rc=0 (121 с).
uv run ruff check app tests: All checks passed, rc=0. ruff format --check по двум изменённым файлам: already formatted, rc=0.

Фальсификация

Копия исходника лежала в scratchpad, после каждого прогона восстановлена, diff -q чистый.

Потолок снят (async with asyncio.timeout(...) заменён на if True:):

>       assert r.status_code == 502
E       assert 200 == 502
E        +  where 200 = <Response [200 OK]>.status_code
1 failed, 4 passed, 1 warning in 5.78s

Хендлер честно ждёт зависший Telegram все 5 с и отвечает 200. Это ровно 16.09.

Потолок оставлен, но TimeoutError не ловится (except TelegramError:):

E           asyncio.exceptions.CancelledError
E                   TimeoutError
1 failed, 4 passed, 1 warning in 1.22s

На проде это был бы 500 без фоновой доставки.

Чего PR не делает (поэтому issue не закрывается)

Отказы до приложения приёмник не посчитает по построению. Пример: 12.09 13:52:48 Caddy отдал 503 за 1.5 мс, пока tradein-backend перезапускался. Такие отказы есть только в access-логе Caddy в Loki, агрегации и алерта по ним нет.
Периодической сверки alerts_notification (GlitchTip) с исходами приёмника нет. Сверка за 7 суток из триажа (161 против 153) была разовой и ручной.
increase() по счётчику теряет запросы на рестартах: 14 сбросов за 7 суток.

Это отдельная задача. Лучше всего её решает сверка «alert-ack получил, tradein-backend нет» или правило по access-логу Caddy.

Приёмка на проде (после деплоя, проверить до 2026-09-25)

Код в контейнере: docker exec tradein-backend grep -c _INTERACTIVE_SEND_DEADLINE_S app/api/v1/glitchtip.py ≥ 1. На 17.09 там 0.
Loki, {container="gendesign-caddy-1"} |~ "glitchtip-webhook" за неделю после деплоя: нет записей со status=0 и duration ≥ 10. Каждый POST на вебхук даёт 200 или 502.
На каждый 502 в логах tradein-backend есть «не удалось переслать алерт в Telegram» и затем «доставлено фоном» или «текст потерян».
Число записей alerts_notification за неделю минус (200 + 502 в access-логе Caddy) расходится только на окна рестартов tradein-backend.

Refs #3157

🤖 Generated with Claude Code

## #3157 — доставка алертов GlitchTip: медленный отказ Telegram больше не рвётся на таймауте отправителя ### Что было На приёмнике (`tradein-mvp/backend/app/api/v1/glitchtip.py`) у синхронной пересылки в Telegram был таймаут только на один HTTP-запрос (`_INTERACTIVE_SEND_TIMEOUT_S=8`). После ретранслятора (#3471) попыток стало больше одной: запрос через relay, при отказе ещё один напрямую, пауза 2 с, повтор. В худшем случае это заметно больше 10 с. GlitchTip ждёт ответ ровно 10 с: в `glitchtip-worker` `apps/alerts/webhooks.py` `send_webhook` стоит `aiohttp.ClientTimeout(total=10)`, а `TimeoutError` там молча проглатывается. ### Улики с прода, 16.09.2026, UTC Проверено 17.09 через Loki, Prometheus и контейнеры, только чтение. - GlitchTip отправил уведомление в 16:42:39. Caddy (`gendesign-caddy-1`) записал этот POST на `/ops/glitchtip-webhook` так: `status=0`, `duration=10.16`, `size=0`. Отправитель оборвал соединение. - `tradein-backend`: - 16:42:47.688 «ретранслятор недоступен, одна попытка напрямую к Telegram» (relay упал через 8 с); - 16:42:52.690 «network error (попытка 1/1): ConnectTimeout — retry через 2.0s». После этого ни «не удалось переслать», ни 502, ни фоновой доставки. - Процесс перезапустился в 16:41:20 (`process_start_time_seconds`). Ряд `http_requests_total{route="/ops/glitchtip-webhook",status="200"}` появился в скрейпе 16:42:58 со значением 1. Другого POST на вебхук в Caddy за 16:40–16:45 нет, так что по всем признакам это тот же запрос. Вторая попытка прошла около 16:42:55, и хендлер **досчитал себе 200 уже после того, как отправитель ушёл**. - Строки access-log для этого запроса нет. uvicorn 0.49.0 в `RequestResponseCycle.send` при `self.disconnected` делает `return` до записи access-log, то есть ответ разорванному клиенту просто выбрасывается. **Поправка к триажу.** В разборе было сказано «алерт пропал, счётчик не инкрементировался». Счётчик инкрементировался как 200, это спрятал сброс при рестарте в 16:41:20. Алерт, скорее всего, дошёл в Telegram примерно через 5 с после того, как GlitchTip сдался. Прямо проверить доставку в Telegram нечем. Сам дефект от этого не меняется: отправитель видит обрыв (`status=0`, `is_sent=True`), приёмник записывает 200 без строки в access-log, и эти три источника расходятся в исходе. А если бы и вторая попытка не прошла, 502 и фоновый повтор отработали бы уже в пустоту. ### Что сделано Минимальный дифф в `glitchtip.py`: - вся синхронная попытка (лимитер, relay, прямой путь, пауза, повтор) обёрнута в `async with asyncio.timeout(_INTERACTIVE_SEND_DEADLINE_S)`, где потолок 7 с. Запас 3 с до 10 с GlitchTip оставлен на Caddy и чтение тела; - `TimeoutError` ловится вместе с `TelegramError` и идёт тем же путём: `logger.exception`, `JSONResponse(502)` и `BackgroundTask(retry_forward_alert)`. Фоновая доставка работает по воркерной политике (relay, потом напрямую, до 3×5 попыток) и пишет свой итог: «доставлено фоном» или «текст потерян». Цена: попытка, оборванная потолком, могла на самом деле дойти до Telegram, тогда фоновая доставка создаст дубль сообщения. Этот риск at-least-once уже был принят для ретраев `ReadTimeout` в `_request`. ### Тесты - Новый `tests/test_glitchtip_alert_retry.py::test_slow_telegram_answers_502_before_sender_gives_up`. Фейковый клиент зависает на 5 с, потолок уменьшен до 0.2 с. Проверяется: ответ 502; время ответа меньше 2 с; 2 вызова `send_message` (зависшая синхронная попытка и доставка фоном тем же текстом); боевой потолок `_INTERACTIVE_SEND_DEADLINE_S` не больше 8 (10 с GlitchTip минус запас). - `tests/test_glitchtip_alert_retry.py tests/test_glitchtip_webhook.py`: 24 passed, rc=0. - Весь сьют МЕРА backend: `DATABASE_URL=... uv run python -m pytest tests/ -q -p no:cacheprovider` — **6226 passed, 42 skipped, rc=0** (121 с). - `uv run ruff check app tests`: All checks passed, rc=0. `ruff format --check` по двум изменённым файлам: already formatted, rc=0. ### Фальсификация Копия исходника лежала в scratchpad, после каждого прогона восстановлена, `diff -q` чистый. 1. Потолок снят (`async with asyncio.timeout(...)` заменён на `if True:`): ``` > assert r.status_code == 502 E assert 200 == 502 E + where 200 = <Response [200 OK]>.status_code 1 failed, 4 passed, 1 warning in 5.78s ``` Хендлер честно ждёт зависший Telegram все 5 с и отвечает 200. Это ровно 16.09. 2. Потолок оставлен, но `TimeoutError` не ловится (`except TelegramError:`): ``` E asyncio.exceptions.CancelledError E TimeoutError 1 failed, 4 passed, 1 warning in 1.22s ``` На проде это был бы 500 без фоновой доставки. ### Чего PR не делает (поэтому issue не закрывается) - Отказы **до** приложения приёмник не посчитает по построению. Пример: 12.09 13:52:48 Caddy отдал 503 за 1.5 мс, пока `tradein-backend` перезапускался. Такие отказы есть только в access-логе Caddy в Loki, агрегации и алерта по ним нет. - Периодической сверки `alerts_notification` (GlitchTip) с исходами приёмника нет. Сверка за 7 суток из триажа (161 против 153) была разовой и ручной. - `increase()` по счётчику теряет запросы на рестартах: 14 сбросов за 7 суток. Это отдельная задача. Лучше всего её решает сверка «alert-ack получил, tradein-backend нет» или правило по access-логу Caddy. ### Приёмка на проде (после деплоя, проверить до 2026-09-25) 1. Код в контейнере: `docker exec tradein-backend grep -c _INTERACTIVE_SEND_DEADLINE_S app/api/v1/glitchtip.py` ≥ 1. На 17.09 там 0. 2. Loki, `{container="gendesign-caddy-1"} |~ "glitchtip-webhook"` за неделю после деплоя: нет записей со `status=0` и `duration ≥ 10`. Каждый POST на вебхук даёт 200 или 502. 3. На каждый 502 в логах `tradein-backend` есть «не удалось переслать алерт в Telegram» и затем «доставлено фоном» или «текст потерян». 4. Число записей `alerts_notification` за неделю минус (200 + 502 в access-логе Caddy) расходится только на окна рестартов `tradein-backend`. Refs #3157 🤖 Generated with [Claude Code](https://claude.com/claude-code)

bot-backend added 1 commit 2026-09-17 07:42:21 +00:00

fix(glitchtip): медленный отказ Telegram отвечает 502 до таймаута GlitchTip (#3157 )

CI Trade-In / changes (pull_request) Successful in 28s

Details

CI / changes (pull_request) Successful in 33s

Details

CI Trade-In / browser-tests (pull_request) Has been skipped

Details

CI Trade-In / frontend-checks (pull_request) Has been skipped

Details

CI / backend-tests (pull_request) Has been skipped

Details

CI / openapi-codegen-check (pull_request) Has been skipped

Details

CI / frontend-tests (pull_request) Has been skipped

Details

CI Trade-In / backend-tests (pull_request) Successful in 6m25s

Details

bc0ef9536e

Синхронная пересылка алерта была ограничена таймаутом одного HTTP-запроса
(8 с), а попыток после ретранслятора (#3471) больше одной: relay, прямой путь,
пауза 2 с, повтор. 16.09.2026 16:42 UTC отказ шёл медленно, GlitchTip
(aiohttp ClientTimeout total=10) оборвал запрос на 10-й секунде, Caddy записал
status=0, а хендлер досчитал 200 уже разорванному клиенту: uvicorn такой ответ
выбрасывает вместе со строкой access-log. Исход у отправителя и приёмника
расходился, 502 и фоновая доставка не срабатывали.

Вся синхронная попытка теперь под asyncio.timeout(7 с). TimeoutError идёт тем
же путём, что TelegramError: logger.exception, 502, фоновая доставка.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>