fix(ops): алерт не теряется от одного сетевого отказа — ретрай в обеих notify() (#3059) #3095
3 changed files with 248 additions and 14 deletions
188
backend/tests/ops/test_3059_alert_retry.py
Normal file
188
backend/tests/ops/test_3059_alert_retry.py
Normal file
|
|
@ -0,0 +1,188 @@
|
|||
"""Regression: алерт больше не теряется от одного сетевого отказа (#3059).
|
||||
|
||||
Что происходит. Путь Selectel→Telegram теряет соединения. Замер 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}"
|
||||
)
|
||||
|
|
@ -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) ----------------------------------
|
||||
|
|
|
|||
|
|
@ -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) ---
|
||||
|
|
|
|||
Loading…
Add table
Reference in a new issue