From c7df2732bd1cd60c81b0843da4341d1dc8e2f6be Mon Sep 17 00:00:00 2001 From: bot-backend Date: Wed, 26 Aug 2026 10:02:46 +0300 Subject: [PATCH] =?UTF-8?q?fix(ops):=20=D0=B0=D0=BB=D0=B5=D1=80=D1=82=20?= =?UTF-8?q?=D0=BD=D0=B5=20=D1=82=D0=B5=D1=80=D1=8F=D0=B5=D1=82=D1=81=D1=8F?= =?UTF-8?q?=20=D0=BE=D1=82=20=D0=BE=D0=B4=D0=BD=D0=BE=D0=B3=D0=BE=20=D1=81?= =?UTF-8?q?=D0=B5=D1=82=D0=B5=D0=B2=D0=BE=D0=B3=D0=BE=20=D0=BE=D1=82=D0=BA?= =?UTF-8?q?=D0=B0=D0=B7=D0=B0=20(#3059)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Путь 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. --- backend/tests/ops/test_3059_alert_retry.py | 188 +++++++++++++++++++++ ops/lib-backup.sh | 32 +++- ops/uptime-healthcheck.sh | 42 ++++- 3 files changed, 248 insertions(+), 14 deletions(-) create mode 100644 backend/tests/ops/test_3059_alert_retry.py diff --git a/backend/tests/ops/test_3059_alert_retry.py b/backend/tests/ops/test_3059_alert_retry.py new file mode 100644 index 00000000..071080c1 --- /dev/null +++ b/backend/tests/ops/test_3059_alert_retry.py @@ -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}" + ) diff --git a/ops/lib-backup.sh b/ops/lib-backup.sh index 9d0c4847..c95b4165 100755 --- a/ops/lib-backup.sh +++ b/ops/lib-backup.sh @@ -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) ---------------------------------- diff --git a/ops/uptime-healthcheck.sh b/ops/uptime-healthcheck.sh index 97468d89..783b3fd5 100755 --- a/ops/uptime-healthcheck.sh +++ b/ops/uptime-healthcheck.sh @@ -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) --- -- 2.45.3