fix(ops): алерт не теряется от одного сетевого отказа (#3059)
All checks were successful
CI / changes (pull_request) Successful in 10s
CI Trade-In / changes (pull_request) Successful in 8s
CI Trade-In / backend-tests (pull_request) Has been skipped
CI Trade-In / browser-tests (pull_request) Has been skipped
CI Trade-In / frontend-checks (pull_request) Has been skipped
CI / frontend-tests (pull_request) Has been skipped
CI / openapi-codegen-check (pull_request) Successful in 1m48s
CI / backend-tests (pull_request) Successful in 22m26s

Путь Selectel-Telegram теряет соединения. Замер 26.08 с Poincare, 40
подключений к закреплённому (#3093) 149.154.167.220:

    успешно 37 из 40, отказов 3 (7.5%) - все TimeoutError
    время успешных: min 0.14s, медиана 0.15s, max 0.17s

Отказы происходят на стадии ПОДКЛЮЧЕНИЯ - быстрые стабильные успехи на фоне
редких таймаутов. Три остальных дата-центра Telegram с Selectel недостижимы
вовсе, так что закрепление адреса потери убрать не может: запасного адреса
нет. Бот это переживает своими ретраями (106 таймаутов за сутки, 97 лечатся
первой же повторной попыткой), а вот алерты - нет.

uptime-healthcheck.sh: был один curl и `|| log WARN` - каждый отказ терял
уведомление целиком. Сторож, который не может дозваться, - худший вид
самоскрывающейся поломки: чем хуже дела на проде, тем выше шанс, что о них
не сообщат. Ирония в том, что ниже в этом же файле HTTP-проверки уже
повторяются циклом: ретраили то, что измеряют, но не то, чем докладывают.

lib-backup.sh: тоже один curl, но с падением в почту (#3070). Алерт не
терялся, зато каждый транзиентный таймаут впустую сжигал последнее средство
вместо простого переподключения.

Стало: цикл из трёх попыток в обеих notify(). Не `curl --retry` - семантика
--max-time при ретраях зависит от версии curl, а цикл даёт таймаут на КАЖДУЮ
попытку и повторяет идиому, уже принятую в uptime-healthcheck.sh.

Дубль вместо потери - осознанный размен: sendMessage не идемпотентен, но
отказ случается ДО отправки запроса, так что повтор почти никогда не
продублирует доставленное. Лишний алерт безвреден, пропущенный - нет.

Тесты (backend/tests/ops/test_3059_alert_retry.py, 7 шт) исполняют РЕАЛЬНЫЕ
notify(), извлечённые из обоих скриптов, с подставным curl, отказывающим
заданное число раз, и считают фактическое число попыток.

Фальсификация: на исходных скриптах краснеют 6 из 7. Проходит только
test_backup_falls_back_to_mail_when_telegram_is_really_down - он фиксирует
сохранённое поведение, а не регресс.

Проверено: `bash -n` обоих скриптов (та же проверка, что в CI - shellcheck
там нет); конструкция `[[ ]] && cmd` в конце тела цикла безопасна под
`set -euo pipefail`, который стоит в uptime-healthcheck.sh:25 (проверено
исполнением, не рассуждением); tests/ops целиком - 22 passed.
This commit is contained in:
bot-backend 2026-08-26 10:02:46 +03:00
parent 729e9acc52
commit c7df2732bd
3 changed files with 248 additions and 14 deletions

View file

@ -0,0 +1,188 @@
"""Regression: алерт больше не теряется от одного сетевого отказа (#3059).
Что происходит. Путь SelectelTelegram теряет соединения. Замер 26.08.2026 с
Poincare, 40 подключений к ЗАКРЕПЛЁННОМУ (#3093) 149.154.167.220:
успешно 37 из 40, отказов 3 (7.5%) все TimeoutError
время успешных: min 0.14s, медиана 0.15s, max 0.17s
Отказы происходят на СТАДИИ ПОДКЛЮЧЕНИЯ (быстрые и стабильные успешные
попытки на фоне редких таймаутов), а не от перегрузки Telegram. Три остальных
дата-центра с Selectel недостижимы вовсе, поэтому запасного адреса нет и
закрепление (#3093) потери убрать не может — оно лишь выбирает единственный
работающий адрес.
Как это ломало алерты:
* `ops/uptime-healthcheck.sh` ОДИН `curl`, дальше `|| log WARN`. Каждый
отказ терял уведомление целиком. Watchdog, который не может дозваться,
худший вид самоскрывающейся поломки: чем хуже дела на проде, тем выше шанс,
что о них не сообщат. При этом сам файл ниже повторяет свои HTTP-ПРОВЕРКИ
циклом `for attempt in $(seq 1 ...)` то есть ретраил то, что измеряет, но
не то, чем докладывает.
* `ops/lib-backup.sh` тоже один `curl`, но с падением в запасной канал
(почта, #3070). Формально алерт не терялся, фактически КАЖДЫЙ транзиентный
таймаут впустую сжигал последнее средство вместо простого переподключения.
Фикс цикл из трёх попыток в обеих `notify()`. Не `curl --retry`: семантика
`--max-time` при ретраях зависит от версии curl, а цикл гарантирует таймаут
на КАЖДУЮ попытку и повторяет идиому, уже принятую в uptime-healthcheck.sh.
Дубль вместо потери осознанный размен: `sendMessage` не идемпотентен, но
отказ случается ДО отправки запроса, так что повтор почти никогда не
продублирует доставленное. Лишний алерт безвреден, пропущенный нет.
ПОЧЕМУ ЭТОТ КЛАСС БАГОВ НЕ ЛОВИЛСЯ: одиночный `curl ... || log WARN` выглядит
безобидно при чтении «ошибку же логируем». Виден он только замером частоты
отказов канала. Тесты ниже исполняют РЕАЛЬНЫЕ `notify()`, извлечённые из обоих
скриптов, с подставным `curl`, который отказывает заданное число раз, и
считают ФАКТИЧЕСКОЕ число попыток. Возврат к одиночному вызову уронит их
немедленно.
"""
from __future__ import annotations
import shutil
import subprocess
from pathlib import Path
import pytest
# backend/tests/ops/<этот файл> → корень репозитория
REPO_ROOT = Path(__file__).resolve().parents[3]
UPTIME = "ops/uptime-healthcheck.sh"
LIB_BACKUP = "ops/lib-backup.sh"
# См. подробное обоснование shutil.which в
# backend/tests/ops/test_2203_backup_trailer_grep_dashdash.py: голое "bash" на
# Windows с WSL резолвится в System32\bash.exe и ломает многокомандный `-c`.
BASH = shutil.which("bash")
if BASH is None: # pragma: no cover - окружение без bash не запустит эти тесты
pytest.skip("bash не найден в PATH — тест требует shell-исполнения", allow_module_level=True)
def _extract_function(script_rel: str, name: str = "notify") -> str:
"""Достаёт тело одной функции из скрипта — не весь файл.
Весь скрипт source'ить нельзя: uptime-healthcheck.sh ниже функций реально
ходит по прод-URL, а lib-backup.sh рассчитан на вызов из backup.sh.
Сопоставление точное (`name() {`), иначе `notify` поймал бы
`notify_fallback_mail` соседнюю функцию в том же файле.
"""
path = REPO_ROOT / script_rel
assert path.is_file(), f"нет {path} — скрипт переехал, гейт ослеп"
lines = path.read_text(encoding="utf-8").splitlines()
head = f"{name}() {{"
start = next((i for i, line in enumerate(lines) if line.startswith(head)), None)
assert start is not None, f"{script_rel}: не нашёл функцию {name}()"
end = next((i for i in range(start + 1, len(lines)) if lines[i] == "}"), None)
assert end is not None, f"{script_rel}: не нашёл конец функции {name}()"
body = "\n".join(lines[start : end + 1])
assert "curl" in body, f"{script_rel}: извлечённое тело {name}() не содержит curl"
return body
# Заглушка curl: считает вызовы и отказывает первые $FAIL_TIMES раз.
# Код 28 — curl'овский "operation timeout", ровно то, что наблюдалось в замере.
_HARNESS = r"""
set -u
stubdir=$(mktemp -d)
trap 'rm -rf "$stubdir"' EXIT
export COUNTER="$stubdir/calls"
echo 0 > "$COUNTER"
export FAIL_TIMES=@@FAIL_TIMES@@
cat > "$stubdir/curl" <<'STUB'
#!/usr/bin/env bash
n=$(cat "$COUNTER")
n=$((n + 1))
echo "$n" > "$COUNTER"
if [ "$n" -le "$FAIL_TIMES" ]; then exit 28; fi
exit 0
STUB
chmod +x "$stubdir/curl"
export PATH="$stubdir:$PATH"
log() { echo "LOG: $*" >&2; }
notify_fallback_mail() { echo "FALLBACK_MAIL_CALLED" >&2; }
TELEGRAM_BOT_TOKEN=stub-token
TELEGRAM_CHAT_ID=stub-chat
CURL_TIMEOUT=1
NOTIFY_RETRY_DELAY=0
@@FUNC@@
notify "тестовый алерт"
echo "RC=$?"
echo "CURL_CALLS=$(cat "$COUNTER")"
"""
def _run_notify(script_rel: str, fail_times: int) -> tuple[int, str, str]:
"""Гоняет РЕАЛЬНУЮ notify() из скрипта с curl, падающим fail_times раз.
Возвращает (сколько раз позван curl, stdout, stderr).
"""
harness = _HARNESS.replace("@@FUNC@@", _extract_function(script_rel)).replace(
"@@FAIL_TIMES@@", str(fail_times)
)
proc = subprocess.run([BASH, "-c", harness], capture_output=True, timeout=30)
out = proc.stdout.decode("utf-8", errors="replace")
err = proc.stderr.decode("utf-8", errors="replace")
calls = next(
(int(line.split("=", 1)[1]) for line in out.splitlines() if line.startswith("CURL_CALLS=")),
-1,
)
assert calls >= 0, f"харнесс не отработал.\nstdout:\n{out}\nstderr:\n{err}"
return calls, out, err
@pytest.mark.parametrize("script_rel", [UPTIME, LIB_BACKUP])
def test_transient_failure_is_retried_not_lost(script_rel: str) -> None:
"""Один отказ — алерт всё равно доставляется со второй попытки.
Это ядро регресса: до фикса curl звался РОВНО ОДИН раз и первый же
таймаут (7.5% по замеру) означал потерю уведомления.
"""
calls, out, err = _run_notify(script_rel, fail_times=1)
assert calls == 2, f"{script_rel}: ожидалась повторная попытка, а curl позван {calls} раз"
assert "RC=0" in out, f"{script_rel}: notify() должна вернуть успех.\nstderr:\n{err}"
assert "НЕ ДОСТАВЛЕН" not in err, f"{script_rel}: доставленный алерт помечен потерянным"
@pytest.mark.parametrize("script_rel", [UPTIME, LIB_BACKUP])
def test_gives_up_after_three_attempts(script_rel: str) -> None:
"""Повторы ограничены: три попытки, а не бесконечный цикл.
Верхняя граница важна не меньше нижней hourly-крон не должен зависать
на недоступном Telegram.
"""
calls, _out, _err = _run_notify(script_rel, fail_times=99)
assert calls == 3, f"{script_rel}: ожидалось ровно 3 попытки, а curl позван {calls} раз"
def test_uptime_reports_undelivered_alert_loudly() -> None:
"""Когда все три попытки провалились — это видно в логе, а не молча."""
_calls, _out, err = _run_notify(UPTIME, fail_times=99)
assert "НЕ ДОСТАВЛЕН" in err, f"недоставленный алерт должен логироваться громко.\n{err}"
def test_backup_does_not_burn_fallback_on_a_single_timeout() -> None:
"""Транзиентный таймаут не должен трогать запасной канал.
Почта (#3070) — последнее средство на случай, когда Telegram недоступен
ПО-НАСТОЯЩЕМУ. До фикса её дёргал каждый пропущенный SYN.
"""
_calls, _out, err = _run_notify(LIB_BACKUP, fail_times=1)
assert "FALLBACK_MAIL_CALLED" not in err, "запасной канал сожжён на одном транзиентном отказе"
def test_backup_falls_back_to_mail_when_telegram_is_really_down() -> None:
"""А когда Telegram действительно недоступен — почта всё-таки уходит."""
_calls, _out, err = _run_notify(LIB_BACKUP, fail_times=99)
assert err.count("FALLBACK_MAIL_CALLED") == 1, (
f"после трёх отказов ожидался ровно один вызов запасного канала.\n{err}"
)

View file

@ -45,13 +45,31 @@ notify() {
return 0
fi
curl -fsS --max-time 15 \
-X POST "https://api.telegram.org/bot${TELEGRAM_BOT_TOKEN}/sendMessage" \
-d "chat_id=${TELEGRAM_CHAT_ID}" \
-d "disable_web_page_preview=true" \
--data-urlencode "text=${text}" \
>/dev/null 2>&1 \
|| { log "WARN: telegram sendMessage failed — пробую запасной канал"; notify_fallback_mail "$text"; }
# #3059: одиночный curl отправлял алерт «на удачу». Замер 26.08 с Poincare —
# 3 отказа на 40 подключений (7.5%) к закреплённому (#3093) 149.154.167.220,
# все таймаутом на СТАДИИ ПОДКЛЮЧЕНИЯ. То есть каждый двадцатый-тридцатый
# алерт впустую сжигал запасной канал (почту) вместо того, чтобы просто
# переподключиться: почта — последнее средство на случай, когда Telegram
# недоступен ПО-НАСТОЯЩЕМУ, а не пропустил один SYN.
#
# Повтор безопасен: отказ происходит до отправки запроса, поэтому дубль
# сообщения практически исключён, а пропущенный алерт о неудавшемся бэкапе
# — именно то, ради предотвращения чего этот файл и существует.
local attempt
for attempt in 1 2 3; do
if curl -fsS --max-time 15 \
-X POST "https://api.telegram.org/bot${TELEGRAM_BOT_TOKEN}/sendMessage" \
-d "chat_id=${TELEGRAM_CHAT_ID}" \
-d "disable_web_page_preview=true" \
--data-urlencode "text=${text}" \
>/dev/null 2>&1; then
[[ "$attempt" -gt 1 ]] && log "telegram sendMessage: доставлено с попытки ${attempt}"
return 0
fi
[[ "$attempt" -lt 3 ]] && sleep "${NOTIFY_RETRY_DELAY:-2}"
done
log "WARN: telegram sendMessage failed — 3 попытки подряд, пробую запасной канал"
notify_fallback_mail "$text"
}
# --- запасной канал оповещения (#3059) ----------------------------------

View file

@ -58,13 +58,41 @@ notify() {
log "NOTIFY (telegram disabled — no token/chat): $text"
return 0
fi
curl -fsS --max-time "$CURL_TIMEOUT" \
-X POST "https://api.telegram.org/bot${TELEGRAM_BOT_TOKEN}/sendMessage" \
-d "chat_id=${TELEGRAM_CHAT_ID}" \
-d "disable_web_page_preview=true" \
--data-urlencode "text=${text}" \
>/dev/null 2>&1 \
|| log "WARN: telegram sendMessage failed"
# #3059: путь до Telegram теряет соединения. Замер 26.08 с Poincare — 40
# подключений к ЗАКРЕПЛЁННОМУ (#3093) 149.154.167.220: 3 отказа (7.5%), все
# таймаутом на установке соединения; успешные при этом стабильны (0.14-0.17 с).
# Три остальных дата-центра Telegram с Selectel недостижимы вовсе, так что
# запасного адреса нет — потери на единственном рабочем неустранимы сетью.
#
# Раньше здесь был ОДИН curl, и `|| log WARN` означал, что каждый такой отказ
# ТЕРЯЕТ алерт целиком: уведомление о падении прода не приходит, остаётся
# строка в логе, который читают уже после аварии. Watchdog, который сам себя
# не может дозваться, — худший вид самоскрывающейся поломки: чем хуже дела,
# тем вероятнее, что о них не сообщат.
#
# Цикл, а не `curl --retry`: ниже в этом же файле проверки уже повторяются
# ровно такой конструкцией (см. `for attempt in $(seq 1 ...)`), и семантика
# `--max-time` при ретраях curl зависит от версии. Здесь таймаут заведомо
# применяется к КАЖДОЙ попытке.
#
# Дубль вместо потери — осознанный размен: sendMessage не идемпотентен, но
# замер показал, что отказы происходят на СТАДИИ ПОДКЛЮЧЕНИЯ, до отправки
# запроса, так что повтор почти никогда не дублирует уже доставленное
# сообщение. А продублированный алерт безвреден, пропущенный — нет.
local attempt
for attempt in 1 2 3; do
if curl -fsS --max-time "$CURL_TIMEOUT" \
-X POST "https://api.telegram.org/bot${TELEGRAM_BOT_TOKEN}/sendMessage" \
-d "chat_id=${TELEGRAM_CHAT_ID}" \
-d "disable_web_page_preview=true" \
--data-urlencode "text=${text}" \
>/dev/null 2>&1; then
[[ "$attempt" -gt 1 ]] && log "telegram sendMessage: доставлено с попытки ${attempt}"
return 0
fi
[[ "$attempt" -lt 3 ]] && sleep "${NOTIFY_RETRY_DELAY:-2}"
done
log "WARN: telegram sendMessage failed — 3 попытки подряд, алерт НЕ ДОСТАВЛЕН"
}
# --- state helpers (last status per check) ---