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
|
return 0
|
||||||
fi
|
fi
|
||||||
|
|
||||||
curl -fsS --max-time 15 \
|
# #3059: одиночный curl отправлял алерт «на удачу». Замер 26.08 с Poincare —
|
||||||
-X POST "https://api.telegram.org/bot${TELEGRAM_BOT_TOKEN}/sendMessage" \
|
# 3 отказа на 40 подключений (7.5%) к закреплённому (#3093) 149.154.167.220,
|
||||||
-d "chat_id=${TELEGRAM_CHAT_ID}" \
|
# все таймаутом на СТАДИИ ПОДКЛЮЧЕНИЯ. То есть каждый двадцатый-тридцатый
|
||||||
-d "disable_web_page_preview=true" \
|
# алерт впустую сжигал запасной канал (почту) вместо того, чтобы просто
|
||||||
--data-urlencode "text=${text}" \
|
# переподключиться: почта — последнее средство на случай, когда Telegram
|
||||||
>/dev/null 2>&1 \
|
# недоступен ПО-НАСТОЯЩЕМУ, а не пропустил один SYN.
|
||||||
|| { log "WARN: telegram sendMessage failed — пробую запасной канал"; notify_fallback_mail "$text"; }
|
#
|
||||||
|
# Повтор безопасен: отказ происходит до отправки запроса, поэтому дубль
|
||||||
|
# сообщения практически исключён, а пропущенный алерт о неудавшемся бэкапе
|
||||||
|
# — именно то, ради предотвращения чего этот файл и существует.
|
||||||
|
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) ----------------------------------
|
# --- запасной канал оповещения (#3059) ----------------------------------
|
||||||
|
|
|
||||||
|
|
@ -58,13 +58,41 @@ notify() {
|
||||||
log "NOTIFY (telegram disabled — no token/chat): $text"
|
log "NOTIFY (telegram disabled — no token/chat): $text"
|
||||||
return 0
|
return 0
|
||||||
fi
|
fi
|
||||||
curl -fsS --max-time "$CURL_TIMEOUT" \
|
# #3059: путь до Telegram теряет соединения. Замер 26.08 с Poincare — 40
|
||||||
-X POST "https://api.telegram.org/bot${TELEGRAM_BOT_TOKEN}/sendMessage" \
|
# подключений к ЗАКРЕПЛЁННОМУ (#3093) 149.154.167.220: 3 отказа (7.5%), все
|
||||||
-d "chat_id=${TELEGRAM_CHAT_ID}" \
|
# таймаутом на установке соединения; успешные при этом стабильны (0.14-0.17 с).
|
||||||
-d "disable_web_page_preview=true" \
|
# Три остальных дата-центра Telegram с Selectel недостижимы вовсе, так что
|
||||||
--data-urlencode "text=${text}" \
|
# запасного адреса нет — потери на единственном рабочем неустранимы сетью.
|
||||||
>/dev/null 2>&1 \
|
#
|
||||||
|| log "WARN: telegram sendMessage failed"
|
# Раньше здесь был ОДИН 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) ---
|
# --- state helpers (last status per check) ---
|
||||||
|
|
|
||||||
Loading…
Add table
Reference in a new issue