diff --git a/tradein-mvp/backend/app/main.py b/tradein-mvp/backend/app/main.py index 1e48a282..ab62bddd 100644 --- a/tradein-mvp/backend/app/main.py +++ b/tradein-mvp/backend/app/main.py @@ -19,6 +19,7 @@ from sentry_sdk.integrations.httpx import HttpxIntegration from sentry_sdk.integrations.logging import LoggingIntegration from sentry_sdk.integrations.sqlalchemy import SqlalchemyIntegration from sentry_sdk.integrations.starlette import StarletteIntegration +from sentry_sdk.types import Event, Hint from app.api.public import mera as public_mera from app.api.v1 import ( @@ -79,31 +80,43 @@ install_query_secret_filter() # frontend), отдельного broker нет → мониторить нечего. if settings.glitchtip_dsn: from app.observability.sentry_scrub import ( + drop_payments_disabled_event, redact_telegram_bot_token, scrub_payment_request_body, scrub_public_address, stabilize_retry_error_fingerprint, ) - def _before_send(event: dict[str, object], hint: dict[str, object]) -> dict[str, object] | None: - """Композиция платёжный body-wipe + PII-scrub + Telegram bot-токен redaction + - RetryError fingerprint-стабилизация (#tgsupport-web, PR-D2, glitchtip-noise) — - см. app/tgbot_main.py._before_send (идентичная композиция без последнего шага, - тот бот geocoder не зовёт). Тот же риск: теперь этот процесс тоже держит - TelegramClient в стек-фреймах при ошибке sendMessage, а + def _before_send(event: Event, hint: Hint) -> Event | None: + """Композиция payments-disabled drop + платёжный body-wipe + PII-scrub + + Telegram bot-токен redaction + RetryError fingerprint-стабилизация + (#tgsupport-web, PR-D2, glitchtip-noise, #3471) — см. + app/tgbot_main.py._before_send (идентичная композиция без последнего + шага, тот бот geocoder не зовёт). Тот же риск: теперь этот процесс тоже + держит TelegramClient в стек-фреймах при ошибке sendMessage, а include_local_variables=False ниже — первый рубеж защиты. - PR-D2: платёжный body-wipe идёт ПЕРВЫМ шагом, а не заменяет остальные — - режет `request.data` целиком только для `/payments/*`, остальные пути - (extra/contexts/traceback) по-прежнему проходят ключ-based scrub и - token-redaction. Тот же обработчик передан ОБОИМ каналам ниже - (before_send и before_send_transaction) — вчерашний баг в Птице закрыл - только error-канал, transaction-канал остался вообще без обработчика. + #3471: payments-disabled drop идёт ПЕРВЫМ шагом — это единственный + процесс из трёх entrypoint'ов, который реально держит ASGI-роут + `/api/v1/payments/*`, поэтому именно здесь события возникают; ранний + return None экономит остальную композицию на заведомо отбрасываемом + событии. + + PR-D2: платёжный body-wipe идёт следующим шагом, а не заменяет + остальные — режет `request.data` целиком только для `/payments/*`, + остальные пути (extra/contexts/traceback) по-прежнему проходят + ключ-based scrub и token-redaction. Тот же обработчик передан ОБОИМ + каналам ниже (before_send и before_send_transaction) — вчерашний баг в + Птице закрыл только error-канал, transaction-канал остался вообще без + обработчика. RetryError-стабилизация — этот процесс обслуживает /api/v1/geocode/* (suggest/lookup/reverse), которые ретраят Nominatim через tenacity; см. sentry_scrub.stabilize_retry_error_fingerprint.""" - scrubbed = scrub_payment_request_body(event, hint) # type: ignore[arg-type] + dropped = drop_payments_disabled_event(event, hint) # type: ignore[arg-type] + if dropped is None: + return None + scrubbed = scrub_payment_request_body(dropped, hint) # type: ignore[arg-type] if scrubbed is None: return None # Публичный периметр МЕРЫ: тело запроса — это ровно введённый адрес, а diff --git a/tradein-mvp/backend/app/observability/sentry_scrub.py b/tradein-mvp/backend/app/observability/sentry_scrub.py index 742e14ab..02b34d79 100644 --- a/tradein-mvp/backend/app/observability/sentry_scrub.py +++ b/tradein-mvp/backend/app/observability/sentry_scrub.py @@ -25,6 +25,7 @@ import re from typing import Any from sentry_sdk.types import Event +from starlette.exceptions import HTTPException as _StarletteHTTPException from tenacity import RetryError _REDACTED = "[REDACTED]" @@ -256,6 +257,41 @@ def scrub_payment_request_body(event: Event, _hint: dict[str, Any]) -> Event | N return event +_PAYMENTS_DISABLED_DETAIL = "payments are disabled" + + +def drop_payments_disabled_event(event: Event, hint: dict[str, Any]) -> Event | None: + """before_send-хук: роняет 503 "payments are disabled" из + `payments.py._require_enabled` (issue #3471, GlitchTip-группа TRADE-IN-3GG). + + Источник — внутренний IP смоук-проверки: кнопки оплаты во фронте нет, + клиентского трафика на эти пути нет вообще, а выключенный платёжный контур + (`settings.payments_enabled=False`) штатно отвечает 503 на каждый такой + запрос — 167 событий за 29.08-12.09 размывали ленту, на этом фоне терялась + настоящая ошибка. Само поведение ручки НЕ меняется (503 остаётся) — + фильтруется только репортинг в трекер: sentry_sdk `StarletteIntegration` + репортит любой `HTTPException` с кодом из `failed_request_status_codes` + (по умолчанию весь диапазон 5xx) как error-событие, даже когда исключение + штатно обработано FastAPI и превращено в корректный HTTP-ответ. + + Матчим `isinstance` реального объекта исключения из `hint["exc_info"]` (тот + же контракт, что `stabilize_retry_error_fingerprint` ниже) + точный текст + `detail` — НЕ код 503 сам по себе, чтобы не проглотить другие 503 (напр. + будущий maintenance-режим другого роутера). + """ + if not isinstance(event, dict): + return event + exc_info = hint.get("exc_info") if isinstance(hint, dict) else None + exc_value = exc_info[1] if exc_info and len(exc_info) > 1 else None + if ( + isinstance(exc_value, _StarletteHTTPException) + and exc_value.status_code == 503 + and exc_value.detail == _PAYMENTS_DISABLED_DETAIL + ): + return None + return event + + _PUBLIC_API_URL_SEGMENT = "/api/public/" #: Хосты геокодеров: их URL несёт введённый адрес прямо в query. diff --git a/tradein-mvp/backend/app/scheduler_main.py b/tradein-mvp/backend/app/scheduler_main.py index 57e17551..e279e59a 100644 --- a/tradein-mvp/backend/app/scheduler_main.py +++ b/tradein-mvp/backend/app/scheduler_main.py @@ -43,14 +43,16 @@ if settings.glitchtip_dsn: from sentry_sdk.integrations.httpx import HttpxIntegration from sentry_sdk.integrations.logging import LoggingIntegration from sentry_sdk.integrations.sqlalchemy import SqlalchemyIntegration + from sentry_sdk.types import Event, Hint from app.observability.sentry_scrub import ( + drop_payments_disabled_event, scrub_payment_request_body, scrub_pii_event, stabilize_retry_error_fingerprint, ) - def _before_send(event: dict, hint: dict) -> dict | None: # type: ignore[type-arg] + def _before_send(event: Event, hint: Hint) -> Event | None: """PR-D2: этот процесс не держит ASGI-приложения (нет `request` в event сегодня), но payments_confirm/payments_reconcile (PR-E, тот же `tradein-scraper` контейнер) будут звать Т-Банк API отсюда — belt-and- @@ -58,6 +60,13 @@ if settings.glitchtip_dsn: `request`/`extra`. Тот же обработчик на оба канала ниже — см. app/main.py._before_send (идентичный мотив, не дублировать без причины). + #3471: payments-disabled drop — тот же belt-and-suspenders мотив, что и + payment body-wipe выше по докстрингу: этот процесс сегодня не отвечает + 503 из `_require_enabled` (нет ASGI/роутов), реальный источник шума — + `app/main.py`, но фильтр держим одинаковым во всех трёх entrypoint'ах, + чтобы поведение не разошлось, если payments-код когда-нибудь переедет + сюда же. + PII-scrub + RetryError fingerprint-стабилизация (glitchtip-noise) идут следом за платёжным body-wipe: этот процесс гоняет `geocode_missing_listings` (ночной batch, сотни адресов за прогон) — @@ -66,13 +75,16 @@ if settings.glitchtip_dsn: на КАЖДЫЙ адрес (RetryError.__str__() тащит нестабильный repr() Future). См. sentry_scrub docstring. """ - scrubbed = scrub_payment_request_body(event, hint) # type: ignore[arg-type] + dropped = drop_payments_disabled_event(event, hint) # type: ignore[arg-type] + if dropped is None: + return None + scrubbed = scrub_payment_request_body(dropped, hint) # type: ignore[arg-type] if scrubbed is None: return None - scrubbed = scrub_pii_event(scrubbed, hint) + scrubbed = scrub_pii_event(scrubbed, hint) # type: ignore[arg-type] if scrubbed is None: return None - return stabilize_retry_error_fingerprint(scrubbed, hint) + return stabilize_retry_error_fingerprint(scrubbed, hint) # type: ignore[arg-type,return-value] sentry_sdk.init( dsn=settings.glitchtip_dsn, diff --git a/tradein-mvp/backend/app/services/proxy_pool.py b/tradein-mvp/backend/app/services/proxy_pool.py index dcdd4bb1..437e937c 100644 --- a/tradein-mvp/backend/app/services/proxy_pool.py +++ b/tradein-mvp/backend/app/services/proxy_pool.py @@ -1309,6 +1309,8 @@ async def _probe_proxy(url: str) -> tuple[bool, str | None, int | None, str | No транзиентный сбой узла ≠ перманентный бан, используется пока только для логов): - "timeout" — сеть недоступна/медленная (httpx.TimeoutException) - "connect_error" — прокси не поднят/не слушает/DNS (httpx.ConnectError) + - "proxy_error" — сам прокси отверг соединение (httpx.ProxyError, напр. 407 от + провайдера — это состояние пула, а не инцидент; #3471) - "http_error" — ipify ответил ошибкой через прокси (auth/upstream) - "other" — прочее @@ -1328,6 +1330,14 @@ async def _probe_proxy(url: str) -> tuple[bool, str | None, int | None, str | No except httpx.ConnectError: logger.warning("proxy_pool: health probe connect_error proxy=%s", _mask(url)) return False, None, None, "connect_error" + except httpx.ProxyError as exc: + # #3471: сам прокси-провайдер отверг соединение (чаще всего 407 — + # исчерпан лимит/просрочен пакет) — штатный исход health-пробы, не + # инцидент приложения. Одна строка без трейса: узел + причина текстом + # исключения, полный traceback здесь не несёт новой информации и только + # засорял логи (184 строки/сутки, #3471). + logger.warning("proxy_pool: health probe proxy_error proxy=%s reason=%s", _mask(url), exc) + return False, None, None, "proxy_error" except httpx.HTTPStatusError as exc: logger.warning( "proxy_pool: health probe http_error proxy=%s status=%s", diff --git a/tradein-mvp/backend/app/tgbot_main.py b/tradein-mvp/backend/app/tgbot_main.py index be555a25..7a82e0d0 100644 --- a/tradein-mvp/backend/app/tgbot_main.py +++ b/tradein-mvp/backend/app/tgbot_main.py @@ -26,7 +26,6 @@ import logging import os import signal from contextlib import suppress -from typing import Any from app.core.config import settings from app.core.db import SessionLocal @@ -57,18 +56,20 @@ if settings.glitchtip_dsn: import sentry_sdk from sentry_sdk.integrations.httpx import HttpxIntegration from sentry_sdk.integrations.logging import LoggingIntegration + from sentry_sdk.types import Event, Hint from app.observability.sentry_scrub import ( + drop_payments_disabled_event, redact_telegram_bot_token, scrub_payment_request_body, scrub_pii_event, ) - def _before_send(event: Any, hint: dict[str, Any]) -> Any: - """Композиция платёжный body-wipe (PR-D2) + PII-scrub (form-данные) + - Telegram bot-токен redaction (#tgsupport review). Токен утекает ДВУМЯ - независимыми векторами, которые `include_local_variables=False` ниже и - этот хук закрывают вместе: + def _before_send(event: Event, hint: Hint) -> Event | None: + """Композиция payments-disabled drop (#3471) + платёжный body-wipe (PR-D2) + + PII-scrub (form-данные) + Telegram bot-токен redaction (#tgsupport review). + Токен утекает ДВУМЯ независимыми векторами, которые + `include_local_variables=False` ниже и этот хук закрывают вместе: 1. `include_local_variables=True` (sentry_sdk default) кладёт stack-frame locals (`self._base`/`url` в `TelegramClient._request`) в traceback — закрыто через `include_local_variables=False` в `sentry_sdk.init`. @@ -78,18 +79,22 @@ if settings.glitchtip_dsn: — belt-and-suspenders на случай #1 (если include_local_variables случайно вернут) И на span data. - Платёжный body-wipe — belt-and-suspenders: этот процесс не держит ASGI- - приложения (нет `request` в event сегодня), но тот же обработчик передан - ОБОИМ каналам ниже (before_send/before_send_transaction) ради единообразия - со всеми точками инициализации sentry_sdk в проекте (см. app/main.py). + Payments-disabled drop и платёжный body-wipe — belt-and-suspenders: этот + процесс не держит ASGI-приложения (нет `request`/HTTPException в event + сегодня, реальный источник 503 — app/main.py), но тот же обработчик + передан ОБОИМ каналам ниже (before_send/before_send_transaction) ради + единообразия со всеми точками инициализации sentry_sdk в проекте. """ - scrubbed = scrub_payment_request_body(event, hint) + dropped = drop_payments_disabled_event(event, hint) # type: ignore[arg-type] + if dropped is None: + return None + scrubbed = scrub_payment_request_body(dropped, hint) # type: ignore[arg-type] if scrubbed is None: return None - scrubbed = scrub_pii_event(scrubbed, hint) + scrubbed = scrub_pii_event(scrubbed, hint) # type: ignore[arg-type] if scrubbed is None: return None - return redact_telegram_bot_token(scrubbed, hint) + return redact_telegram_bot_token(scrubbed, hint) # type: ignore[arg-type,return-value] sentry_sdk.init( dsn=settings.glitchtip_dsn, diff --git a/tradein-mvp/backend/tests/services/test_proxy_pool.py b/tradein-mvp/backend/tests/services/test_proxy_pool.py index 1a40a8aa..c5466431 100644 --- a/tradein-mvp/backend/tests/services/test_proxy_pool.py +++ b/tradein-mvp/backend/tests/services/test_proxy_pool.py @@ -50,6 +50,7 @@ os.environ.setdefault("DATABASE_URL", "postgresql+psycopg://test:test@localhost: from datetime import UTC, datetime, timedelta from typing import Any +import httpx import pytest from app.services import proxy_pool @@ -1527,3 +1528,74 @@ def test_clear_source_bans_resets_escalation() -> None: assert ban["ban_count"] == 1 expected = datetime.now(UTC) + timedelta(hours=SOURCE_BAN_BASE_HOURS) assert abs((ban["banned_until"] - expected).total_seconds()) < 60 + + +# ── health-probe failure logging (#3471 — GlitchTip/log noise) ────────────── +# httpx.ProxyError (типично 407 от провайдера) раньше падал в generic +# `except Exception: ... exc_info=True` внутри `_probe_proxy` — полный traceback +# на КАЖДЫЙ провал, хотя это штатное состояние пула (184 строки/сутки на +# проде), а не инцидент приложения. Тесты ниже бьют по РЕАЛЬНОМУ `_probe_proxy` +# (не монки-заглушке, как в тестах `run_proxy_healthcheck` выше) — только так +# видно, что осталось от логирования при живом httpx-исключении. + + +async def test_probe_proxy_proxy_error_logs_single_line_without_traceback( + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, +) -> None: + async def _broken_get(self: httpx.AsyncClient, *args: Any, **kwargs: Any) -> httpx.Response: + raise httpx.ProxyError("407 Proxy Authentication Required") + + monkeypatch.setattr(httpx.AsyncClient, "get", _broken_get) + + with caplog.at_level("WARNING", logger="app.services.proxy_pool"): + ok, exit_ip, latency_ms, fail_kind = await proxy_pool._probe_proxy( + "http://u:p@h1:8080" + ) + + assert ok is False + assert exit_ip is None + assert latency_ms is None + assert fail_kind == "proxy_error" + + records = [r for r in caplog.records if r.name == "app.services.proxy_pool"] + assert len(records) == 1, "провал ipify-пробы обязан лечь ОДНОЙ строкой, не пачкой" + record = records[0] + assert record.exc_info is None, "проба — штатная операция, полный traceback не нужен" + assert "proxy_error" in record.message + assert "407" in record.message # причина (текст исключения) видна без трейса + + +async def test_healthcheck_counts_proxy_error_as_failed_without_traceback( + monkeypatch: pytest.MonkeyPatch, + caplog: pytest.LogCaptureFixture, +) -> None: + """Итоговая строка `checked=.../ok=.../failed=...` не ломается провалом + вида ProxyError, а сам провал не тащит traceback в лог прогона.""" + db = FakeSession([_proxy(1, fails=0)]) + + async def _broken_get(self: httpx.AsyncClient, *args: Any, **kwargs: Any) -> httpx.Response: + raise httpx.ProxyError("407 Proxy Authentication Required") + + monkeypatch.setattr(httpx.AsyncClient, "get", _broken_get) + + # INFO (не WARNING): итоговая сводка `healthcheck done` логируется на INFO — + # порог ниже WARNING нужен, чтобы её тоже поймать в этом же прогоне. + with caplog.at_level("INFO", logger="app.services.proxy_pool"): + counters = await proxy_pool.run_proxy_healthcheck(db) # type: ignore[arg-type] + + assert counters["checked"] == 1 + assert counters["ok"] == 0 + assert counters["failed"] == 1 + assert db._by_id(1)["consecutive_fails"] == 1 + + summary = [ + r + for r in caplog.records + if r.name == "app.services.proxy_pool" and "healthcheck done" in r.message + ] + assert len(summary) == 1 + assert "checked=1" in summary[0].message + assert "ok=0" in summary[0].message + assert "failed=1" in summary[0].message + assert not any(r.exc_info for r in caplog.records if r.name == "app.services.proxy_pool") diff --git a/tradein-mvp/backend/tests/test_sentry_scrub.py b/tradein-mvp/backend/tests/test_sentry_scrub.py index 4925c48d..7abfb4ca 100644 --- a/tradein-mvp/backend/tests/test_sentry_scrub.py +++ b/tradein-mvp/backend/tests/test_sentry_scrub.py @@ -13,6 +13,7 @@ import pytest os.environ.setdefault("DATABASE_URL", "postgresql+psycopg://test:test@localhost:5432/test") from app.observability.sentry_scrub import ( + drop_payments_disabled_event, redact_telegram_bot_token, scrub_payment_request_body, scrub_pii_event, @@ -627,3 +628,63 @@ def test_scrub_pii_event_httpx_url_query_stabilization_leaves_unrelated_text_unt out = scrub_pii_event(event, {}) assert out is not None assert out["extra"]["note"] == benign + + +# ── payments-disabled drop (issue #3471, GlitchTip-группа TRADE-IN-3GG) ───── +# 503 из `payments.py._require_enabled` — штатный ответ выключенного +# kill-switch'а, а не инцидент: sentry_sdk `StarletteIntegration` репортит его +# как error-событие только потому, что 503 попадает в дефолтный диапазон +# `failed_request_status_codes` (5xx), хотя FastAPI обработал исключение +# штатно. 167 событий/2 недели от внутреннего IP смоук-проверки (кнопки оплаты +# во фронте нет) размывали ленту. Фильтр не должен трогать поведение самой +# ручки (503 остаётся) и не должен глотать другие ошибки — включая другие 503. + +from fastapi import HTTPException # noqa: E402 + + +def _exc_info_hint(exc: BaseException) -> dict: + """Та же форма hint, что sentry_sdk реально передаёт в before_send — + `exc_info = (type, value, traceback)` (см. `_hint_for` выше по файлу).""" + return {"exc_info": (type(exc), exc, exc.__traceback__)} + + +def test_drop_payments_disabled_event_drops_the_503() -> None: + exc = HTTPException(status_code=503, detail="payments are disabled") + event = {"level": "error", "exception": {"values": [{"type": "HTTPException"}]}} + assert drop_payments_disabled_event(event, _exc_info_hint(exc)) is None + + +def test_drop_payments_disabled_event_leaves_other_errors_untouched() -> None: + """Обычная ошибка (не платёжный kill-switch) должна долетать до GlitchTip + без изменений — фильтр специфичен по (status_code, detail), а не по 5xx.""" + exc = ValueError("boom") + event = {"level": "error"} + out = drop_payments_disabled_event(event, _exc_info_hint(exc)) + assert out is event + + +def test_drop_payments_disabled_event_leaves_other_503s_untouched() -> None: + """Другой 503 с другим текстом (напр. будущий maintenance-режим другого + роутера) не должен ложно схлопнуться с платёжным kill-switch'ем.""" + exc = HTTPException(status_code=503, detail="service temporarily unavailable") + event = {"level": "error"} + out = drop_payments_disabled_event(event, _exc_info_hint(exc)) + assert out is event + + +def test_drop_payments_disabled_event_leaves_matching_detail_wrong_status_untouched() -> None: + """Тот же текст detail, но другой status_code — не платёжный kill-switch.""" + exc = HTTPException(status_code=500, detail="payments are disabled") + event = {"level": "error"} + out = drop_payments_disabled_event(event, _exc_info_hint(exc)) + assert out is event + + +def test_drop_payments_disabled_event_no_exc_info_untouched() -> None: + event = {"level": "error"} + out = drop_payments_disabled_event(event, {}) + assert out is event + + +def test_drop_payments_disabled_event_handles_non_dict_event() -> None: + assert drop_payments_disabled_event(None, {}) is None # type: ignore[arg-type]