From 64a79755493f97a77e64190e12e98bbfbb5e4db2 Mon Sep 17 00:00:00 2001 From: bot-backend Date: Thu, 6 Aug 2026 12:50:24 +0000 Subject: [PATCH 1/6] =?UTF-8?q?fix(tradein/proxy):=20=D0=BF=D1=80=D0=BE?= =?UTF-8?q?=D0=B1=D0=B0=20=D1=83=D0=B7=D0=BB=D0=B0=20=D1=85=D0=BE=D0=B4?= =?UTF-8?q?=D0=B8=D1=82=20=D0=B1=D1=80=D0=B0=D1=83=D0=B7=D0=B5=D1=80=D0=BD?= =?UTF-8?q?=D1=8B=D0=BC=20=D1=82=D1=80=D0=B0=D0=BA=D1=82=D0=BE=D0=BC,=20?= =?UTF-8?q?=D0=B2=D0=B5=D1=80=D0=B4=D0=B8=D0=BA=D1=82=20=D0=B6=D0=B8=D0=B2?= =?UTF-8?q?=D1=91=D1=82=20=D0=BE=D1=82=D0=B4=D0=B5=D0=BB=D1=8C=D0=BD=D0=BE?= =?UTF-8?q?=20=D0=BE=D1=82=20HTTP-=D0=BF=D1=80=D0=BE=D0=B1=D1=8B=20(#2723)?= =?UTF-8?q?=20(#2736)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../backend/app/services/proxy_pool.py | 283 ++++++++++++++- .../sql/228_scrape_proxies_browser_health.sql | 66 ++++ .../backend/tests/services/test_proxy_pool.py | 68 +++- .../backend/tests/test_2723_browser_probe.py | 329 ++++++++++++++++++ .../src/scraper_kit/browser_fetcher.py | 109 ++++++ 5 files changed, 844 insertions(+), 11 deletions(-) create mode 100644 tradein-mvp/backend/data/sql/228_scrape_proxies_browser_health.sql create mode 100644 tradein-mvp/backend/tests/test_2723_browser_probe.py diff --git a/tradein-mvp/backend/app/services/proxy_pool.py b/tradein-mvp/backend/app/services/proxy_pool.py index 0e7e503d..ed40dc63 100644 --- a/tradein-mvp/backend/app/services/proxy_pool.py +++ b/tradein-mvp/backend/app/services/proxy_pool.py @@ -77,6 +77,20 @@ Sticky session lease (browser-путь, живая регрессия 2026-08): на каждый /fetch, чтобы reap_stale_leases не отобрал прокси у многочасового прогона. +Два тракта — два диагноза (#2723): + - ipify-проба (`_probe_proxy`) отвечает на «узел жив вообще» и владеет + consecutive_fails / enabled / exit_ip. Такт — каждый прогон healthcheck (30 мин). + - браузерная проба (`_run_browser_probe` → сайдкар → camoufox с ЭТИМ прокси → + навигация) отвечает на «через узел работает браузерный тракт» и владеет + browser_fail_streak / browser_unfit_since / browser_check_at (миграция 228). + Такт свой, редкий (BROWSER_PROBE_MINUTES) — она стоит запуска camoufox. + Пересечения нет: успешная ipify-проба НЕ обнуляет browser_fail_streak (иначе + дешёвая проба каждые 30 минут стирает вердикт дорогого тракта — узел, мёртвый для + браузера, вечно возвращается в выдачу), провал браузерной пробы НЕ выключает узел + (он жив, просто не для этого тракта). Схлопнуть их в один флаг = повторить #2686. + «Непригоден для браузера» — это НЕ исключение из пула: acquire() лишь отдаёт такой + узел последним (ORDER BY), потому что при 4 узлах (#2638) голодание хуже. + psycopg v3 / SQLAlchemy text(): все параметры через CAST(:x AS type), НЕ :x::type. """ @@ -90,9 +104,13 @@ import httpx from sqlalchemy import text from sqlalchemy.orm import Session +from app.core.config import settings as _settings + logger = logging.getLogger(__name__) __all__ = [ + "BROWSER_PROBE_MINUTES", + "BROWSER_UNFIT_THRESHOLD", "DISABLED_RECHECK_MINUTES", "DISABLE_THRESHOLD", "MAX_CONSECUTIVE_FAILS", @@ -105,6 +123,7 @@ __all__ = [ "acquire", "clear_source_bans", "mark_banned", + "mark_browser_health", "mark_health", "reap_stale_leases", "release", @@ -155,6 +174,27 @@ SOURCE_BAN_PURGE_DAYS = 7 _HEALTH_PROBE_URL = "https://api.ipify.org" _HEALTH_PROBE_TIMEOUT_S = 10.0 +# ── браузерная проба узла (#2723) ──────────────────────────────────────────── +# Такт браузерной пробы. Решено по замеру, не по ощущению (прод, 06.08.2026): +# - одна браузерная проба = 8.3с и один запуск camoufox; +# - боевая нагрузка сайдкара = ~42 /fetch и ~8 запусков camoufox в час +# (≈1000 и ≈190 в сутки); +# - такт ipify-пробы = 30 мин → 48 прогонов healthcheck в сутки. +# Гнать браузерную пробу каждым прогоном по 4 узлам = +192 запуска camoufox в сутки, +# то есть УДВОЕНИЕ самой дорогой операции сайдкара ради диагностики. 360 мин даёт +# 4 пробы на узел в сутки: +16 запусков (+8% к запускам, +1.6% к запросам) — цена, +# которую видно только в логе. Отказ, пойманный с задержкой до 6 часов, всё равно +# ловится в разы раньше, чем сейчас (не ловится вовсе). +BROWSER_PROBE_MINUTES = 360 + +# Столько подряд-провалов браузерной пробы (атрибутированных узлу) переводят узел в +# browser_unfit. Не 1: запуск camoufox бывает флаки сам по себе, а пометка — операция +# с последствиями при пуле из 4 узлов. Не 5 (как DISABLE_THRESHOLD): при редком такте +# это были бы сутки. Второе подтверждение приходит на СЛЕДУЮЩЕМ прогоне healthcheck +# (~30 мин), а не через полный такт — browser_check_at на неподтверждённом провале +# намеренно не обновляется (см. mark_browser_health). +BROWSER_UNFIT_THRESHOLD = 2 + # deep-review fix 2 (#2600 п.1): фиксированный ключ pg_advisory_xact_lock для # mark_banned (см. её докстринг). Один произвольный int64 — не завязан ни на что # в схеме (не id таблицы/строки), выбран как "случайное" число, чтобы не @@ -213,7 +253,7 @@ def acquire(db: Session, provider: str, *, run_id: int | None = None) -> ProxyLe db.execute( text( """ - SELECT id, url, kind, rotate_url + SELECT id, url, kind, rotate_url, browser_unfit_since FROM scrape_proxies WHERE enabled AND consecutive_fails < CAST(:max_fails AS integer) @@ -226,7 +266,9 @@ def acquire(db: Session, provider: str, *, run_id: int | None = None) -> ProxyLe AND b.source = :provider AND b.banned_until > now() ) - ORDER BY last_ok_at NULLS LAST, id + -- browser_unfit последним (#2723): узел, живой для HTTP, но не для + -- браузера, из пула НЕ исключается — только уходит в конец очереди. + ORDER BY (browser_unfit_since IS NOT NULL), last_ok_at NULLS LAST, id FOR UPDATE SKIP LOCKED LIMIT 1 """ @@ -247,7 +289,7 @@ def acquire(db: Session, provider: str, *, run_id: int | None = None) -> ProxyLe db.execute( text( """ - SELECT sp.id, sp.url, sp.kind, sp.rotate_url + SELECT sp.id, sp.url, sp.kind, sp.rotate_url, sp.browser_unfit_since FROM scrape_proxies AS sp WHERE sp.enabled AND sp.consecutive_fails < CAST(:max_fails AS integer) @@ -283,7 +325,8 @@ def acquire(db: Session, provider: str, *, run_id: int | None = None) -> ProxyLe ) ) ) - ORDER BY sp.last_ok_at NULLS LAST, sp.id + -- см. ORDER BY основного запроса (#2723) + ORDER BY (sp.browser_unfit_since IS NOT NULL), sp.last_ok_at NULLS LAST, sp.id FOR UPDATE SKIP LOCKED LIMIT 1 """ @@ -323,6 +366,19 @@ def acquire(db: Session, provider: str, *, run_id: int | None = None) -> ProxyLe logger.info( "proxy_pool: leased proxy id=%d provider=%s by=%s", proxy_id, provider, lease_marker ) + if row["browser_unfit_since"] is not None: + # Узел помечен непригодным для браузера (#2723), но всё равно выдан — значит + # пригодных свободных не осталось. Голодание хуже работы через плохой узел + # (та же политика, что у защиты последнего узла в mark_banned), но молчать об + # этом нельзя: для браузерного источника это заведомо обречённый прогон. + logger.warning( + "proxy_pool: leased proxy id=%d provider=%s — узел BROWSER-UNFIT с %s " + "(жив для HTTP, браузерный тракт через него не работает). Выдан потому, " + "что пригодных свободных узлов нет — пул надо пополнять (#2638).", + proxy_id, + provider, + row["browser_unfit_since"], + ) return ProxyLease( id=proxy_id, url=str(row["url"]), @@ -480,6 +536,145 @@ def mark_health( ) +def mark_browser_health( + db: Session, + proxy_id: int, + ok: bool, + *, + fail_kind: str | None = None, + detail: str = "", +) -> str: + """Записать результат БРАУЗЕРНОЙ пробы узла (#2723). Returns исход для счётчиков. + + ЧЕМ ОТЛИЧАЕТСЯ ОТ mark_health: тем же, чем «нас забанила площадка» отличается от + «у нас упал сайдкар» (#2686/#2711) — это ДРУГОЙ диагноз, а не другое значение того + же. mark_health отвечает на «узел жив вообще» и владеет + consecutive_fails/enabled/exit_ip. Эта функция отвечает на «через узел работает + браузерный тракт» и владеет browser_fail_streak/browser_unfit_since/ + browser_check_at. Пересечения нет НИ В ОДНУ сторону, и это главное: + + - успешная ipify-проба НЕ обнуляет browser_fail_streak. До #2723 обнуляла бы + (через consecutive_fails=0) — узел, мёртвый для браузера, выходил из карантина + каждые ≤30 минут и снова забирал прогон; + - провал браузерной пробы НЕ инкрементит consecutive_fails и НЕ выключает узел: + он жив, просто не для этого тракта. + + ЧТО СЧИТАЕТСЯ ПРОВАЛОМ УЗЛА: только fail_kind == "proxy" (см. + scraper_kit.browser_fetcher.classify_browser_probe). "sidecar" (сайдкар лежит) и + "page" (площадка отдала пустое) узлу не принадлежат — засчитывать их значило бы + пометить непригодными ВСЕ узлы разом при одной упавшей общей зависимости, то есть + повторить #2686 ещё раз и уже с последствиями для всего пула. + + ТАКТ ПРИ ПРОВАЛЕ: browser_check_at обновляется только когда провал ПОДТВЕРЖДЁН + (streak дошёл до BROWSER_UNFIT_THRESHOLD). На первом, ещё не подтверждённом + провале поле остаётся старым → следующий же прогон healthcheck (~30 мин) повторит + пробу и либо подтвердит отказ, либо снимет подозрение. Иначе подтверждения ждали бы + полный BROWSER_PROBE_MINUTES. + + Returns: "ok" | "refit" (узел был непригоден и починился) | "unfit" (только что + помечен непригодным) | "fail" (провал засчитан, порог не достигнут) | "ignored" + (провал не принадлежит узлу). + """ + if ok: + row = ( + db.execute( + text( + """ + UPDATE scrape_proxies AS sp + SET browser_fail_streak = 0, + browser_unfit_since = NULL, + browser_check_at = now(), + updated_at = now() + -- prev — pre-image строки: RETURNING отдаёт УЖЕ обновлённые + -- значения (browser_unfit_since там всегда NULL), а нам нужно + -- знать, была ли это реанимация непригодного узла. + FROM ( + SELECT id, browser_unfit_since + FROM scrape_proxies + WHERE id = CAST(:id AS bigint) + ) AS prev + WHERE sp.id = prev.id + RETURNING (prev.browser_unfit_since IS NOT NULL) AS was_unfit + """ + ), + {"id": proxy_id}, + ) + .mappings() + .fetchone() + ) + db.commit() + was_unfit = bool(row["was_unfit"]) if row is not None else False + logger.info( + "proxy_pool: browser probe OK id=%d (%s)%s", + proxy_id, + detail, + " — узел снова пригоден для браузера" if was_unfit else "", + ) + return "refit" if was_unfit else "ok" + + if fail_kind != "proxy": + logger.warning( + "proxy_pool: browser probe FAILED id=%d, но отказ НЕ принадлежит узлу " + "(fail_kind=%s): %s — browser_fail_streak не трогаем", + proxy_id, + fail_kind, + detail, + ) + return "ignored" + + row = ( + db.execute( + text( + """ + UPDATE scrape_proxies + SET browser_fail_streak = browser_fail_streak + 1, + browser_unfit_since = CASE + WHEN browser_fail_streak + 1 >= CAST(:threshold AS integer) + AND browser_unfit_since IS NULL + THEN now() ELSE browser_unfit_since + END, + browser_check_at = CASE + WHEN browser_fail_streak + 1 >= CAST(:threshold AS integer) + THEN now() ELSE browser_check_at + END, + updated_at = now() + WHERE id = CAST(:id AS bigint) + RETURNING browser_fail_streak, browser_unfit_since + """ + ), + {"threshold": BROWSER_UNFIT_THRESHOLD, "id": proxy_id}, + ) + .mappings() + .fetchone() + ) + db.commit() + if row is None: + logger.warning("proxy_pool: mark_browser_health id=%d not found — no-op", proxy_id) + return "ignored" + + streak = int(row["browser_fail_streak"]) + if streak >= BROWSER_UNFIT_THRESHOLD: + logger.warning( + "proxy_pool: proxy id=%d BROWSER-UNFIT (browser_fail_streak=%d) — жив для " + "обычного HTTP, но браузерный тракт через него не работает: %s. Узел " + "ОСТАЁТСЯ в пуле (enabled не тронут, curl-путь работает), но acquire() " + "теперь отдаёт его последним (#2723).", + proxy_id, + streak, + detail, + ) + return "unfit" + logger.warning( + "proxy_pool: browser probe FAILED id=%d (browser_fail_streak=%d/%d, порог не " + "достигнут — перепроверим на следующем прогоне): %s", + proxy_id, + streak, + BROWSER_UNFIT_THRESHOLD, + detail, + ) + return "fail" + + def mark_banned(db: Session, proxy_id: int, *, source: str) -> None: """Записать бан узла площадкой `source` — по ПАРЕ (proxy_id, source), #2600 п.2. @@ -645,8 +840,7 @@ def mark_banned(db: Session, proxy_id: int, *, source: str) -> None: current = ( db.execute( text( - "SELECT enabled, disabled_reason FROM scrape_proxies " - "WHERE id = CAST(:id AS bigint)" + "SELECT enabled, disabled_reason FROM scrape_proxies WHERE id = CAST(:id AS bigint)" ), {"id": proxy_id}, ) @@ -775,6 +969,29 @@ async def _probe_proxy(url: str) -> tuple[bool, str | None, int | None, str | No return False, None, None, "other" +async def _run_browser_probe(db: Session, proxy_id: int, url: str, kind: str) -> str: + """Одна браузерная проба узла + запись вердикта. Returns исход mark_browser_health. + + Best-effort: любой сбой самой пробы (импорт, неожиданное исключение) НЕ роняет + healthcheck — ipify-часть уже отработала и её результат записан. Диагностика не + имеет права ломать то, что диагностирует. + """ + from scraper_kit.browser_fetcher import probe_proxy_via_browser + + try: + ok, fail_kind, detail = await probe_proxy_via_browser( + _settings.browser_http_endpoint, url, proxy_kind=kind + ) + except Exception: + logger.warning( + "proxy_pool: browser probe crashed for proxy id=%d — вердикт не записан", + proxy_id, + exc_info=True, + ) + return "ignored" + return mark_browser_health(db, proxy_id, ok, fail_kind=fail_kind, detail=detail) + + def _mask(url: str) -> str: """Скрыть пароль в proxy-url для логов (scheme://user:***@host).""" if "@" not in url or "//" not in url: @@ -808,9 +1025,18 @@ async def run_proxy_healthcheck(db: Session) -> dict[str, int]: В конце — purge бан-строк (#2600 п.2), истёкших дольше SOURCE_BAN_PURGE_DAYS назад (см. комментарий у самого DELETE: отложенность — это и есть сброс ban_count). + БРАУЗЕРНАЯ ПРОБА (#2723): узлам, прошедшим ipify и не проверявшимся браузером + дольше BROWSER_PROBE_MINUTES, дополнительно гоняется проба ЧЕРЕЗ САЙДКАР (тот же + тракт, что у боевого сбора: camoufox стартует с этим прокси, потом навигация на + robots.txt площадки). Её вердикт идёт в ОТДЕЛЬНЫЕ поля (mark_browser_health) и + никогда не смешивается с consecutive_fails/enabled. Гейт — settings. + use_proxy_pool_browser: при выключенном флаге браузер ходит мимо пула и проба + измеряла бы то, чем никто не пользуется. + Пробы идут последовательно — пул небольшой (десятки узлов), а параллельный залп на один и тот же upstream-endpoint (ipify) не нужен. Returns counters - {reaped, checked, ok, failed, revived, bans_purged}. + {reaped, checked, ok, failed, revived, bans_purged, browser_checked, browser_ok, + browser_unfit, browser_refit}. """ reaped = reap_stale_leases(db) @@ -818,7 +1044,11 @@ async def run_proxy_healthcheck(db: Session) -> dict[str, int]: db.execute( text( """ - SELECT id, url, kind, enabled, disabled_reason + SELECT id, url, kind, enabled, disabled_reason, + (browser_check_at IS NULL + OR browser_check_at < now() - make_interval( + mins => CAST(:browser_probe_minutes AS integer) + )) AS browser_probe_due FROM scrape_proxies WHERE enabled OR last_check_at IS NULL @@ -828,7 +1058,10 @@ async def run_proxy_healthcheck(db: Session) -> dict[str, int]: ORDER BY id """ ), - {"disabled_recheck_minutes": DISABLED_RECHECK_MINUTES}, + { + "disabled_recheck_minutes": DISABLED_RECHECK_MINUTES, + "browser_probe_minutes": BROWSER_PROBE_MINUTES, + }, ) .mappings() .all() @@ -838,6 +1071,10 @@ async def run_proxy_healthcheck(db: Session) -> dict[str, int]: ok_count = 0 failed = 0 revived = 0 + browser_checked = 0 + browser_ok = 0 + browser_unfit = 0 + browser_refit = 0 for row in proxies: proxy_id = int(row["id"]) url = str(row["url"]) @@ -860,6 +1097,22 @@ async def run_proxy_healthcheck(db: Session) -> dict[str, int]: else: failed += 1 + # Браузерная проба (#2723) — только если ipify прошла: провалившая ipify нода + # мертва целиком, диагноз уже поставлен, а запуск camoufox через неё — чистая + # трата 8 секунд. Гейт по use_proxy_pool_browser: при выключенном флаге браузер + # ходит мимо пула (через env-прокси сайдкара), и вердикт об узлах пула был бы + # вердиктом о том, чем никто не пользуется — ровно то расхождение «проба меряет + # не тот узел», из-за которого #2723 и появилась. + if ok and row["browser_probe_due"] and _settings.use_proxy_pool_browser: + outcome = await _run_browser_probe(db, proxy_id, url, str(row["kind"])) + browser_checked += 1 + if outcome in ("ok", "refit"): + browser_ok += 1 + if outcome == "refit": + browser_refit += 1 + elif outcome == "unfit": + browser_unfit += 1 + # Purge ДАВНО истёкших бан-строк (#2600 п.2). Порог — banned_until + SOURCE_BAN_PURGE_DAYS, # НЕ просто `banned_until < now()`: строка после истечения бана ещё ничего не блокирует # (acquire фильтрует по banned_until > now()), но хранит ban_count — память об эскалации. @@ -882,13 +1135,17 @@ async def run_proxy_healthcheck(db: Session) -> dict[str, int]: logger.info( "proxy_pool: healthcheck done — reaped=%d checked=%d ok=%d failed=%d revived=%d " - "bans_purged=%d", + "bans_purged=%d browser_checked=%d browser_ok=%d browser_unfit=%d browser_refit=%d", reaped, checked, ok_count, failed, revived, purged, + browser_checked, + browser_ok, + browser_unfit, + browser_refit, ) return { "reaped": reaped, @@ -897,4 +1154,10 @@ async def run_proxy_healthcheck(db: Session) -> dict[str, int]: "failed": failed, "revived": revived, "bans_purged": purged, + # Счётчики браузерной пробы (#2723) — намеренно ОТДЕЛЬНЫЕ от checked/ok/failed: + # схлопнув их в общие, мы бы своими руками сделали то, за что чиним этот модуль. + "browser_checked": browser_checked, + "browser_ok": browser_ok, + "browser_unfit": browser_unfit, + "browser_refit": browser_refit, } diff --git a/tradein-mvp/backend/data/sql/228_scrape_proxies_browser_health.sql b/tradein-mvp/backend/data/sql/228_scrape_proxies_browser_health.sql new file mode 100644 index 00000000..71b4cd62 --- /dev/null +++ b/tradein-mvp/backend/data/sql/228_scrape_proxies_browser_health.sql @@ -0,0 +1,66 @@ +-- 228_scrape_proxies_browser_health.sql +-- Здоровье узла ОТДЕЛЬНО для браузерного тракта (#2723). +-- +-- WHY: +-- `run_proxy_healthcheck` гоняет через узел обычный httpx-GET к ipify. Боевой сбор +-- Авито с 02.08 (#2637) ходит через сайдкар браузером: camoufox стартует С ЭТИМ +-- прокси (geoip-lookup на launch), потом навигация. Это разные свойства узла: +-- крошечный GET проходит там, где launch/навигация падает (`browser unavailable +-- (proxy may be down)` — все 90 записанных обрывов сбора именно такие). +-- +-- Хуже того, оба свойства писались в ОДИН счётчик: боевой /fetch репортит +-- mark_health(ok=False) → consecutive_fails++, но следующая (≤30 мин) успешная +-- ipify-проба делает consecutive_fails=0 + enabled=true. Дешёвая проба СТИРАЛА +-- вердикт дорогого тракта, и узел, мёртвый для браузера, вечно возвращался в +-- выдачу. Это ровно ошибка #2686 (схлопывание двух диагнозов в один флаг) в +-- другом месте; разводим её тем же приёмом, что #2711 (`scrape_runs.ban_kind`) — +-- поле РЯДОМ, а не новое значение существующего флага. +-- +-- WHAT (три колонки, ни одна не участвует в enabled/consecutive_fails): +-- browser_fail_streak — подряд-провалы ИМЕННО браузерной пробы, и только те, что +-- атрибутируются узлу (сайдкар лежит / страница пустая — +-- не считаются, см. proxy_pool._classify_browser_probe). +-- Успешная ipify-проба его НЕ обнуляет — в этом весь смысл. +-- browser_unfit_since — момент, когда streak дошёл до порога. NOT NULL = «жив для +-- HTTP, непригоден для браузера». acquire() такой узел НЕ +-- исключает (голодание хуже — #2600/#2638, пул 4 узла), а +-- отправляет в КОНЕЦ очереди выдачи: его возьмут, только +-- если свободных пригодных нет. +-- browser_check_at — когда браузерную пробу гоняли последний раз. Такт у неё +-- свой, редкий (BROWSER_PROBE_MINUTES): она стоит запуска +-- camoufox (~8с замерено на проде), ipify — миллисекунды. +-- +-- IDEMPOTENCY / SAFETY: +-- ADD COLUMN IF NOT EXISTS × 3, аддитивно, без backfill'а: NULL/0 = «браузерную +-- пробу ещё не гоняли», ровно то состояние, в котором пул и находится. Ни одна +-- существующая выборка не меняет результат (все три колонки новые). Повторный +-- прогон — no-op (auto-apply strict на деплое это требует). +-- +-- Dependencies: 157_scrape_proxies.sql + +BEGIN; + +ALTER TABLE scrape_proxies + ADD COLUMN IF NOT EXISTS browser_fail_streak integer NOT NULL DEFAULT 0, + ADD COLUMN IF NOT EXISTS browser_unfit_since timestamptz, + ADD COLUMN IF NOT EXISTS browser_check_at timestamptz; + +COMMENT ON COLUMN scrape_proxies.browser_fail_streak IS + 'Подряд-провалы браузерной пробы (сайдкар + camoufox через ЭТОТ узел), ' + 'атрибутированные узлу. НЕ обнуляется успешной ipify-пробой — иначе дешёвая ' + 'проба стирает вердикт дорогого тракта (#2723). Обнуляется успешной браузерной ' + 'пробой. Порог → browser_unfit_since, см. proxy_pool.BROWSER_UNFIT_THRESHOLD.'; + +COMMENT ON COLUMN scrape_proxies.browser_unfit_since IS + 'NOT NULL = узел жив для обычного HTTP, но браузерный тракт через него не ' + 'работает (#2723). Это НЕ enabled=false: узел остаётся в пуле и обслуживает ' + 'curl-путь, а acquire() лишь отдаёт его последним. Полное выключение по-прежнему ' + 'значит «узел мёртв целиком» (серия транспортных сбоев) либо решение оператора.'; + +COMMENT ON COLUMN scrape_proxies.browser_check_at IS + 'Последняя браузерная проба. Такт свой, редкий (proxy_pool.BROWSER_PROBE_MINUTES): ' + 'одна такая проба = запуск camoufox (~8с на проде), против миллисекунд у ipify. ' + 'На неподтверждённом провале НЕ обновляется — чтобы следующий же цикл ' + 'healthcheck подтвердил/опроверг отказ, а не ждал полный такт.'; + +COMMIT; diff --git a/tradein-mvp/backend/tests/services/test_proxy_pool.py b/tradein-mvp/backend/tests/services/test_proxy_pool.py index ca25dc81..a62f9886 100644 --- a/tradein-mvp/backend/tests/services/test_proxy_pool.py +++ b/tradein-mvp/backend/tests/services/test_proxy_pool.py @@ -188,9 +188,14 @@ class FakeSession: and _not_banned(r) and (not protects_last_node or _has_backup(r)) ] - # ORDER BY last_ok_at NULLS LAST, id + # ORDER BY (browser_unfit_since IS NOT NULL), last_ok_at NULLS LAST, id. + # Первый ключ гейтим по подстроке самого SQL (как ban-фильтры выше): иначе + # мок сортировал бы «правильно» независимо от боевого запроса и не отличил + # бы код до #2723 от кода после. + deprioritises_unfit = "browser_unfit_since IS NOT NULL" in sql cands.sort( key=lambda r: ( + bool(deprioritises_unfit and r.get("browser_unfit_since") is not None), r["last_ok_at"] is None, r["last_ok_at"] or datetime.min.replace(tzinfo=UTC), r["id"], @@ -250,6 +255,14 @@ class FakeSession: row["enabled"] = True elif "enabled" in sql: row["enabled"] = True + # #2723: если боевой mark_health когда-нибудь снова начнёт обнулять + # ещё и браузерный вердикт (как делал до фикса — тот жил в общем + # consecutive_fails), мок обязан это воспроизвести, иначе + # test_ipify_success_does_not_erase_browser_verdict останется зелёным + # на сломанном коде. + if "browser_fail_streak = 0" in sql: + row["browser_fail_streak"] = 0 + row["browser_unfit_since"] = None if "RETURNING disabled_reason" in sql: return _FakeResult([{"disabled_reason": row.get("disabled_reason")}]) return _FakeResult([]) @@ -272,8 +285,54 @@ class FakeSession: if r["enabled"] or r.get("last_check_at") is None or r["last_check_at"] < cutoff ] rows = sorted(cands, key=lambda r: r["id"]) + # #2723: браузерная проба со своим тактом. Признак считаем, только если + # боевой SQL его реально запрашивает (см. гейты по подстрокам выше). + if "browser_probe_due" in sql: + b_cutoff = datetime.now(UTC) - timedelta(minutes=p["browser_probe_minutes"]) + return _FakeResult( + [ + dict( + r, + browser_probe_due=( + r.get("browser_check_at") is None + or r["browser_check_at"] < b_cutoff + ), + ) + for r in rows + ] + ) return _FakeResult([dict(r) for r in rows]) + if "SET browser_fail_streak = 0" in sql: # mark_browser_health ok (#2723) + row = self._by_id(p["id"]) + if row is None: + return _FakeResult([]) + was_unfit = row.get("browser_unfit_since") is not None + row["browser_fail_streak"] = 0 + row["browser_unfit_since"] = None + row["browser_check_at"] = datetime.now(UTC) + return _FakeResult([{"was_unfit": was_unfit}]) + + if "browser_fail_streak = browser_fail_streak + 1" in sql: # mark_browser_health fail + row = self._by_id(p["id"]) + if row is None: + return _FakeResult([]) + row["browser_fail_streak"] = row.get("browser_fail_streak", 0) + 1 + if row["browser_fail_streak"] >= p["threshold"]: + if row.get("browser_unfit_since") is None: + row["browser_unfit_since"] = datetime.now(UTC) + # такт двигаем ТОЛЬКО на подтверждённом провале — иначе неподтверждённое + # подозрение ждало бы полный BROWSER_PROBE_MINUTES (#2723) + row["browser_check_at"] = datetime.now(UTC) + return _FakeResult( + [ + { + "browser_fail_streak": row["browser_fail_streak"], + "browser_unfit_since": row.get("browser_unfit_since"), + } + ] + ) + if "pg_advisory_xact_lock" in sql: # deep-review fix 2 (#2600) — mark_banned serialize self.advisory_lock_calls.append(p["key"]) return _FakeResult([]) @@ -384,6 +443,9 @@ def _proxy( kind: str = "http", rotate_url: str | None = None, disabled_reason: str | None = None, + browser_unfit_since: datetime | None = None, + browser_fail_streak: int = 0, + browser_check_at: datetime | None = None, ) -> dict[str, Any]: return { "id": pid, @@ -400,6 +462,10 @@ def _proxy( "last_check_at": last_check_at, "exit_ip": None, "latency_ms": None, + # #2723: здоровье браузерного тракта — отдельные поля, миграция 228. + "browser_unfit_since": browser_unfit_since, + "browser_fail_streak": browser_fail_streak, + "browser_check_at": browser_check_at, } diff --git a/tradein-mvp/backend/tests/test_2723_browser_probe.py b/tradein-mvp/backend/tests/test_2723_browser_probe.py new file mode 100644 index 00000000..0bfb8dae --- /dev/null +++ b/tradein-mvp/backend/tests/test_2723_browser_probe.py @@ -0,0 +1,329 @@ +"""#2723 — проба здоровья прокси ходит тем же трактом, что и работа. + +Что сторожится (каждый тест падает на коде origin/main): + + 1. Классификация отказа браузерной пробы: узлу принадлежит ТОЛЬКО отказ прокси + (503 «browser unavailable», 500 NS_ERROR_PROXY_*). Лежащий сайдкар и пустая + страница — не его вина. Без этого одна упавшая общая зависимость пометила бы + непригодными ВСЕ узлы разом — #2686 в третий раз. + 2. Тракт пробы: POST /fetch (одна навигация) на robots.txt, с прокси узла в теле. + Не /fetch-json (тот сначала грузит ГЛАВНУЮ площадки) и не выдача. + 3. Главное: успешная ipify-проба НЕ стирает вердикт браузерного тракта. На коде до + фикса узел, мёртвый для браузера, выходил из карантина каждые ≤30 минут + (mark_health(ok=True) → consecutive_fails=0 + enabled=true) и снова забирал прогон. + 4. Два диагноза разведены в обе стороны: провал браузерной пробы НЕ выключает узел + и НЕ трогает consecutive_fails; провал ipify не пишет ничего в browser-поля. + 5. Пометка непригодности НЕ выводит узел из пула: acquire() отдаёт его последним, + но при отсутствии пригодных всё равно выдаёт (голодание хуже) — пул из 4 узлов. + 6. Реанимация: успешная браузерная проба снимает пометку (browser_refit). + 7. Такт: браузерная проба идёт реже ipify (BROWSER_PROBE_MINUTES) и только по узлам, + прошедшим ipify — иначе на каждый прогон приходился бы запуск camoufox на узел. +""" + +from __future__ import annotations + +import os + +os.environ.setdefault("DATABASE_URL", "postgresql+psycopg://test:test@localhost:5432/test") + +from datetime import UTC, datetime, timedelta +from pathlib import Path +from typing import Any + +import pytest +from scraper_kit.browser_fetcher import classify_browser_probe + +from app.services import proxy_pool +from app.services.proxy_pool import BROWSER_PROBE_MINUTES, BROWSER_UNFIT_THRESHOLD, acquire +from tests.services.test_proxy_pool import FakeSession, _proxy + +# ── 1. классификация отказа ────────────────────────────────────────────────── + + +@pytest.mark.parametrize( + ("status", "detail", "expected"), + [ + # Ровно тот текст, которым сайдкар отвечал на все 90 записанных обрывов сбора. + (503, '{"error": "browser unavailable (proxy may be down)"}', "proxy"), + (500, '{"error": "Error: Page.goto: NS_ERROR_PROXY_BAD_GATEWAY ..."}', "proxy"), + (500, '{"error": "Error: Page.goto: NS_ERROR_UNKNOWN_PROXY_HOST"}', "proxy"), + # Сайдкар не сконфигурирован / лежит / отвечает чем-то ещё — узел ни при чём. + (503, '{"error": "no proxy configured — refusing direct connection (prod)"}', "sidecar"), + (502, "bad gateway", "sidecar"), + (None, "ConnectError: [Errno 111] Connection refused", "sidecar"), + # Тракт сработал, но ответ не похож на страницу — вопрос к площадке, не к пулу. + (200, "", "page"), + ], +) +def test_classify_browser_probe(status: int | None, detail: str, expected: str) -> None: + assert classify_browser_probe(status, detail) == expected + + +def test_sidecar_error_literals_still_exist() -> None: + """Тripwire: классификация опирается на текст отказа сайдкара — сторожим его. + + Если browser/server.py переименует сообщение, «proxy» перестанет распознаваться и + непригодный узел молча останется первосортным. Тест падает СРАЗУ, а не через месяц + зелёных проб (ровно тот сценарий, из-за которого задача и появилась). + """ + server_py = Path(__file__).resolve().parents[2] / "browser" / "server.py" + src = server_py.read_text(encoding="utf-8") + assert "browser unavailable (proxy may be down)" in src + + +# ── 2. тракт пробы ─────────────────────────────────────────────────────────── + + +async def test_probe_goes_through_sidecar_with_node_proxy(monkeypatch: pytest.MonkeyPatch) -> None: + """Проба = POST /fetch на robots.txt с прокси УЗЛА в теле, а не httpx-GET мимо всех.""" + seen: dict[str, Any] = {} + + class _Resp: + status_code = 200 + text = '{"html": "User-agent: *"}' + + @staticmethod + def json() -> dict[str, str]: + return {"html": "User-agent: *"} + + class _Client: + def __init__(self, **kw: Any) -> None: + seen["timeout"] = kw.get("timeout") + + async def __aenter__(self) -> _Client: + return self + + async def __aexit__(self, *_: object) -> None: + return None + + async def post(self, url: str, json: dict[str, Any]) -> _Resp: + seen["url"] = url + seen["payload"] = json + return _Resp() + + import scraper_kit.browser_fetcher as bf + + monkeypatch.setattr(bf.httpx, "AsyncClient", _Client) + ok, fail_kind, _detail = await bf.probe_proxy_via_browser( + "http://tradein-browser:3000", "http://u:p@node:8080", proxy_kind="http" + ) + + assert ok is True + assert fail_kind is None + # тот же сайдкар и тот же эндпоинт, что у боевого сбора + assert seen["url"] == "http://tradein-browser:3000/fetch" + # НЕ /fetch-json: он делает goto на главную площадки — это уже нагрузка на неё + assert not seen["url"].endswith("/fetch-json") + # прокси проверяемого узла уезжает в тело — иначе camoufox пойдёт через env-прокси + # и проба снова будет измерять не тот узел + assert seen["payload"]["proxy"] == "http://u:p@node:8080" + # адрес — robots.txt площадки, не выдача и не карточка + assert seen["payload"]["url"].endswith("/robots.txt") + assert "avito.ru" in seen["payload"]["url"] + + +# ── 3-4. два диагноза разведены ────────────────────────────────────────────── + + +def test_ipify_success_does_not_erase_browser_verdict() -> None: + """ГЛАВНОЕ: успешная ipify-проба не воскрешает узел, мёртвый для браузера. + + До #2723 браузерный вердикт жил в consecutive_fails, и mark_health(ok=True) + обнулял его каждые ≤30 минут вместе с enabled=true. + """ + db = FakeSession([_proxy(1)]) + for _ in range(BROWSER_UNFIT_THRESHOLD): + proxy_pool.mark_browser_health(db, 1, False, fail_kind="proxy", detail="503") + row = db._by_id(1) + assert row["browser_unfit_since"] is not None + + proxy_pool.mark_health(db, 1, True, exit_ip="1.2.3.4", latency_ms=100) + + row = db._by_id(1) + assert row["consecutive_fails"] == 0 # HTTP-диагноз сброшен, как и раньше + assert row["browser_unfit_since"] is not None # а браузерный — НЕТ + assert row["browser_fail_streak"] >= BROWSER_UNFIT_THRESHOLD + + +def test_browser_failure_does_not_disable_node() -> None: + """Обратная сторона: провал браузерного тракта не выключает живой узел.""" + db = FakeSession([_proxy(1)]) + for _ in range(BROWSER_UNFIT_THRESHOLD + 3): + proxy_pool.mark_browser_health(db, 1, False, fail_kind="proxy", detail="503") + row = db._by_id(1) + assert row["enabled"] is True # узел жив для HTTP — из пула не выводим + assert row["consecutive_fails"] == 0 # и транспортный счётчик не трогаем + assert row["browser_unfit_since"] is not None + + +def test_sidecar_outage_blames_nobody() -> None: + """Лежащий сайдкар не должен пометить непригодными все узлы разом (#2686-класс).""" + db = FakeSession([_proxy(1), _proxy(2)]) + for pid in (1, 2): + for _ in range(BROWSER_UNFIT_THRESHOLD + 1): + outcome = proxy_pool.mark_browser_health( + db, pid, False, fail_kind="sidecar", detail="ConnectError" + ) + assert outcome == "ignored" + for pid in (1, 2): + assert db._by_id(pid)["browser_unfit_since"] is None + assert db._by_id(pid)["browser_fail_streak"] == 0 + + +def test_unconfirmed_failure_keeps_check_at_stale() -> None: + """Первый (неподтверждённый) провал не двигает такт — перепроверка на след. прогоне.""" + db = FakeSession([_proxy(1, browser_check_at=None)]) + proxy_pool.mark_browser_health(db, 1, False, fail_kind="proxy", detail="503") + assert db._by_id(1)["browser_fail_streak"] == 1 + assert db._by_id(1)["browser_check_at"] is None # такт не сдвинут + proxy_pool.mark_browser_health(db, 1, False, fail_kind="proxy", detail="503") + assert db._by_id(1)["browser_unfit_since"] is not None + assert db._by_id(1)["browser_check_at"] is not None # подтверждён → ждём полный такт + + +# ── 5. пометка не выводит узел из пула ─────────────────────────────────────── + + +def test_unfit_node_is_last_in_queue_but_still_reachable() -> None: + old = datetime.now(UTC) - timedelta(hours=5) + db = FakeSession( + [ + # непригодный, но «давно не использованный» → до #2723 выдавался ПЕРВЫМ + _proxy(1, last_ok_at=old, browser_unfit_since=datetime.now(UTC)), + _proxy(2, last_ok_at=datetime.now(UTC)), + ] + ) + lease = acquire(db, "avito") # type: ignore[arg-type] + assert lease is not None + assert lease.id == 2 # пригодный вперёд, несмотря на ORDER BY last_ok_at + + +def test_all_unfit_still_yields_a_proxy() -> None: + """Все узлы непригодны — система НЕ остаётся без прокси (голодание хуже).""" + db = FakeSession( + [ + _proxy(1, browser_unfit_since=datetime.now(UTC)), + _proxy(2, browser_unfit_since=datetime.now(UTC)), + ] + ) + lease = acquire(db, "avito") # type: ignore[arg-type] + assert lease is not None + + +# ── 6-7. healthcheck: такт, гейт, реанимация ───────────────────────────────── + + +def _patch_probes( + monkeypatch: pytest.MonkeyPatch, + *, + http_ok: bool = True, + browser: tuple[bool, str | None, str] = (True, None, "html_len=100"), + calls: list[str] | None = None, +) -> None: + async def _fake_http(url: str) -> tuple[bool, str | None, int | None, str | None]: + return (True, "1.2.3.4", 10, None) if http_ok else (False, None, None, "timeout") + + async def _fake_browser( + endpoint: str, proxy_url: str, **_kw: Any + ) -> tuple[bool, str | None, str]: + if calls is not None: + calls.append(proxy_url) + return browser + + monkeypatch.setattr(proxy_pool, "_probe_proxy", _fake_http) + monkeypatch.setattr(proxy_pool._settings, "use_proxy_pool_browser", True) + import scraper_kit.browser_fetcher as bf + + monkeypatch.setattr(bf, "probe_proxy_via_browser", _fake_browser) + + +async def test_healthcheck_marks_unfit_when_http_green_browser_red( + monkeypatch: pytest.MonkeyPatch, +) -> None: + """Исторический случай целиком: ipify зелёная, браузер красный → диагноз ставится.""" + calls: list[str] = [] + _patch_probes( + monkeypatch, + http_ok=True, + browser=(False, "proxy", "503 browser unavailable (proxy may be down)"), + calls=calls, + ) + db = FakeSession([_proxy(1)]) + + first = await proxy_pool.run_proxy_healthcheck(db) # type: ignore[arg-type] + assert first["ok"] == 1 and first["failed"] == 0 # HTTP-проба по-прежнему зелёная + assert first["browser_checked"] == 1 + assert db._by_id(1)["browser_unfit_since"] is None # один провал ещё не приговор + + second = await proxy_pool.run_proxy_healthcheck(db) # type: ignore[arg-type] + assert second["browser_unfit"] == 1 + row = db._by_id(1) + assert row["browser_unfit_since"] is not None + assert row["enabled"] is True and row["consecutive_fails"] == 0 + assert len(calls) == 2 + + +async def test_healthcheck_browser_probe_respects_slow_tick( + monkeypatch: pytest.MonkeyPatch, +) -> None: + """Успешная проба сдвигает такт: следующий прогон healthcheck её не повторяет.""" + calls: list[str] = [] + _patch_probes(monkeypatch, calls=calls) + db = FakeSession([_proxy(1)]) + + await proxy_pool.run_proxy_healthcheck(db) # type: ignore[arg-type] + assert len(calls) == 1 + await proxy_pool.run_proxy_healthcheck(db) # type: ignore[arg-type] + assert len(calls) == 1, "браузерная проба обязана идти реже ipify — она стоит camoufox" + + db._by_id(1)["browser_check_at"] = datetime.now(UTC) - timedelta( + minutes=BROWSER_PROBE_MINUTES + 1 + ) + await proxy_pool.run_proxy_healthcheck(db) # type: ignore[arg-type] + assert len(calls) == 2 + + +async def test_healthcheck_skips_browser_probe_when_http_dead( + monkeypatch: pytest.MonkeyPatch, +) -> None: + """Узел, не прошедший ipify, мёртв целиком — жечь на него запуск camoufox незачем.""" + calls: list[str] = [] + _patch_probes(monkeypatch, http_ok=False, calls=calls) + db = FakeSession([_proxy(1)]) + counters = await proxy_pool.run_proxy_healthcheck(db) # type: ignore[arg-type] + assert counters["failed"] == 1 + assert counters["browser_checked"] == 0 + assert calls == [] + + +async def test_healthcheck_skips_browser_probe_when_pool_not_wired( + monkeypatch: pytest.MonkeyPatch, +) -> None: + """Флаг выключен → браузер ходит мимо пула, вердикт об узлах пула бессмыслен.""" + calls: list[str] = [] + _patch_probes(monkeypatch, calls=calls) + monkeypatch.setattr(proxy_pool._settings, "use_proxy_pool_browser", False) + db = FakeSession([_proxy(1)]) + counters = await proxy_pool.run_proxy_healthcheck(db) # type: ignore[arg-type] + assert counters["browser_checked"] == 0 + assert calls == [] + + +async def test_healthcheck_revives_unfit_node(monkeypatch: pytest.MonkeyPatch) -> None: + """Путь обратно: успешная браузерная проба снимает пометку непригодности.""" + _patch_probes(monkeypatch) + db = FakeSession( + [ + _proxy( + 1, + browser_unfit_since=datetime.now(UTC) - timedelta(days=1), + browser_fail_streak=4, + browser_check_at=datetime.now(UTC) - timedelta(minutes=BROWSER_PROBE_MINUTES + 1), + ) + ] + ) + counters = await proxy_pool.run_proxy_healthcheck(db) # type: ignore[arg-type] + assert counters["browser_refit"] == 1 + row = db._by_id(1) + assert row["browser_unfit_since"] is None + assert row["browser_fail_streak"] == 0 diff --git a/tradein-mvp/packages/scraper-kit/src/scraper_kit/browser_fetcher.py b/tradein-mvp/packages/scraper-kit/src/scraper_kit/browser_fetcher.py index c58ed589..640f7492 100644 --- a/tradein-mvp/packages/scraper-kit/src/scraper_kit/browser_fetcher.py +++ b/tradein-mvp/packages/scraper-kit/src/scraper_kit/browser_fetcher.py @@ -36,6 +36,42 @@ logger = logging.getLogger(__name__) _RETRY_SLEEP_S: float = 1.0 _HTTP_TIMEOUT_S: float = 120.0 # навигация медленная → щедрый таймаут +# ── проба узла ПО БРАУЗЕРНОМУ ТРАКТУ (#2723) ───────────────────────────────── +# Адрес пробы. Требования к нему ровно три, и robots.txt Авито им отвечает: +# 1) тот же тракт, что у работы — сайдкар, camoufox, ЭТОТ прокси, настоящая +# навигация. Все 90 записанных обрывов сбора («browser unavailable (proxy may +# be down)») рождались на launch'е camoufox с прокси — проба обязана его делать; +# 2) та же площадка, что реально отказывает (100% обрывов — avito): TLS-рукопожатие +# и маршрут до её edge, а не до нейтрального хоста; +# 3) НУЛЕВАЯ нагрузка на площадку: robots.txt — статический файл ~4КБ, который +# автоматическим клиентам читать прямо предписано. НЕ выдача и НЕ карточка. +# Такт пробы редкий (proxy_pool.BROWSER_PROBE_MINUTES) — при 4 узлах это ~16 +# запросов в сутки против ~1000 боевых /fetch (замер на проде 06.08). +_PROXY_PROBE_URL: str = "https://www.avito.ru/robots.txt" +# source='generic' НАМЕРЕННО, хотя адрес авитовский: сайдкар держит по инстансу +# camoufox на провайдера с отдельным локом, и проба с source='avito' забирала бы лок +# боевого инстанса и релончила его (прокси пробы ≠ прокси сессии) — ровно тот +# relaunch-шторм, который лечил sticky-lease фикс. 'generic' — свой инстанс, боевые +# развёртки его не используют. +_PROXY_PROBE_SOURCE: str = "generic" +# Щедрее ipify-пробы (10с) на порядок: сюда входит холодный запуск camoufox — 8.3с +# замерено на проде вместе с релончем, плюс запас на медленный узел. +_PROXY_PROBE_TIMEOUT_S: float = 90.0 + +# Маркеры отказов, которые сайдкар порождает ИМЕННО из-за прокси (browser/server.py: +# fetch_handler 503 после _ensure_browser → camoufox не поднялся с этим прокси; +# 500 с NS_ERROR_PROXY_* → навигация не прошла через прокси). Всё остальное — +# не про узел (сайдкар недоступен, конфиг сайдкара, пустая страница). +# ponytail: подстроки, а не машинный код отказа — сайдкар не отдаёт поле причины. +# Тест test_2723_browser_probe.py::test_sidecar_error_literals_still_exist сторожит +# расхождение с исходником сайдкара; при следующей правке browser/server.py дешевле +# добавить туда {"fail_kind": "proxy"} и читать его здесь. +_PROXY_FAIL_MARKERS: tuple[str, ...] = ( + "browser unavailable (proxy may be down)", + "NS_ERROR_PROXY", + "NS_ERROR_UNKNOWN_PROXY_HOST", +) + # Живая регрессия 2026-08: после скольких подряд провалившихся /fetch ТЕКУЩИЙ session-lease # считается плохим (бан/сетевая труха) и ОСОЗНАННО меняется один раз (release+acquire), вместо # того чтобы менять прокси на каждый /fetch как раньше. Camoufox релончится ТОЛЬКО при реальной @@ -78,6 +114,79 @@ def _raise_for_sidecar_status(resp: httpx.Response) -> None: ) from exc +def classify_browser_probe(status: int | None, detail: str) -> str: + """Кому принадлежит отказ браузерной пробы: узлу, сайдкару или странице (#2723). + + Разведение обязательно, иначе повторяется #2686 в третий раз: лежащий сайдкар + пометил бы НЕПРИГОДНЫМИ ВСЕ узлы разом, хотя ни один из них не при чём. + + - "proxy" — отказ порождён прокси: camoufox не поднялся с ним (503 «browser + unavailable (proxy may be down)») либо навигация не прошла через + него (500 NS_ERROR_PROXY_*). ТОЛЬКО этот исход копит + browser_fail_streak. + - "sidecar" — сайдкар недоступен/не сконфигурирован (connect error, таймаут, + 503 «no proxy configured», прочие 5xx). Узел не виноват. + - "page" — тракт сработал, но ответ не похож на страницу (пустое тело). + Узел не виноват; повод посмотреть на площадку, не на пул. + """ + if status is None: + return "sidecar" # до ответа не дошло — сайдкар/сеть контейнера + if any(marker in detail for marker in _PROXY_FAIL_MARKERS): + return "proxy" + if status >= 400: + return "sidecar" + return "page" + + +async def probe_proxy_via_browser( + endpoint: str, + proxy_url: str, + *, + proxy_kind: str = "http", + url: str = _PROXY_PROBE_URL, + timeout_s: float = _PROXY_PROBE_TIMEOUT_S, +) -> tuple[bool, str | None, str]: + """Проверить узел ТЕМ ЖЕ трактом, которым идёт работа: сайдкар → camoufox → прокси. + + Standalone (не метод `BrowserFetcher`) и БЕЗ пула: аренда узла здесь не нужна и + вредна — health-checker проверяет узлы, в том числе арендованные, и не должен + конкурировать за lease с боевым прогоном. + + Используется `/fetch` (одна навигация), а НЕ `/fetch-json`: последний сначала + делает goto на origin, т.е. на ГЛАВНУЮ страницу площадки — это уже заметная + нагрузка на неё, ради которой проба и затевалась бы наоборот. + + Returns: + (ok, fail_kind, detail). ok=True → fail_kind=None. Иначе fail_kind — + "proxy" / "sidecar" / "page" (см. classify_browser_probe), detail — + обрезанный текст для лога. + """ + payload: dict[str, object] = { + "url": url, + "source": _PROXY_PROBE_SOURCE, + "proxy": proxy_url, + "proxy_kind": proxy_kind, + } + try: + async with httpx.AsyncClient(timeout=timeout_s) as client: + resp = await client.post(f"{endpoint}/fetch", json=payload) + except Exception as exc: + detail = f"{type(exc).__name__}: {str(exc)[:200]}" + return False, classify_browser_probe(None, detail), detail + + detail = " ".join((resp.text or "").split())[:300] + if resp.status_code != 200: + return False, classify_browser_probe(resp.status_code, detail), detail + + try: + html = resp.json().get("html") or "" + except Exception: + html = "" + if not html: + return False, classify_browser_probe(resp.status_code, detail), "empty html" + return True, None, f"html_len={len(html)}" + + class BrowserFetcher: """Async context manager: HTTP-клиент к tradein-browser HTTP-сервису. From 90e328df66fa4631a898f0c7d4c795763c14c8ef Mon Sep 17 00:00:00 2001 From: bot-backend Date: Thu, 6 Aug 2026 14:27:26 +0000 Subject: [PATCH 2/6] =?UTF-8?q?fix(tradein/auth):=20=D0=BE=D1=82=D0=BA?= =?UTF-8?q?=D0=B0=D0=B7=20=D0=BF=D0=BE=20=D0=BD=D0=B0=D1=81=D1=8B=D1=89?= =?UTF-8?q?=D0=B5=D0=BD=D0=B8=D1=8E=20=E2=80=94=20=D0=B4=D0=BE=20=D0=B2?= =?UTF-8?q?=D1=8B=D0=B1=D0=BE=D1=80=D0=BA=D0=B8=20=D0=B8=D0=B7=20=D0=91?= =?UTF-8?q?=D0=94=20=D0=B8=20=D1=81=20=D0=B0=D0=B3=D1=80=D0=B5=D0=B3=D0=B8?= =?UTF-8?q?=D1=80=D0=BE=D0=B2=D0=B0=D0=BD=D0=BD=D1=8B=D0=BC=20=D1=81=D0=BB?= =?UTF-8?q?=D0=B5=D0=B4=D0=BE=D0=BC=20(#2715)=20(#2734)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- tradein-mvp/backend/app/api/v1/audit.py | 17 +- tradein-mvp/backend/app/api/v1/auth.py | 147 ++++++++++++++-- tradein-mvp/backend/app/core/password.py | 33 +++- tradein-mvp/backend/tests/test_audit_api.py | 33 ++++ tradein-mvp/backend/tests/test_auth_api.py | 182 ++++++++++++++++++++ 5 files changed, 394 insertions(+), 18 deletions(-) diff --git a/tradein-mvp/backend/app/api/v1/audit.py b/tradein-mvp/backend/app/api/v1/audit.py index e592d5b1..feac11aa 100644 --- a/tradein-mvp/backend/app/api/v1/audit.py +++ b/tradein-mvp/backend/app/api/v1/audit.py @@ -58,6 +58,12 @@ async def list_accounts( count(*) FILTER (WHERE event_type = 'api_request') AS request_count, count(*) FILTER (WHERE event_type = 'estimate_request') AS search_count FROM user_events + -- Событие без имени — не аккаунт (#2715: `login_verify_saturated` + -- пишется с пустым именем намеренно — отказ случается ДО того, как + -- на имя посмотрели). Без фильтра строка встала бы ПЕРВОЙ (её + -- last_seen_at — момент атаки), а её кнопка в UI раскрывалась бы в + -- /audit/accounts/{username} с `min_length=1`, то есть в ошибку. + WHERE username <> '' GROUP BY username ORDER BY last_seen_at DESC """ @@ -182,12 +188,16 @@ async def analytics_dashboard( db.execute( text( """ + -- NULLIF(username, ''): безымянные события (#2715) — СОБЫТИЯ, они + -- честно входят в total_events, но не люди: count(DISTINCT) их + -- игнорирует по NULL, иначе первая же атака навсегда добавила бы + -- фантомного пользователя в счётчик уникальных. SELECT count(*) AS total_events, - count(DISTINCT username) AS distinct_users, + count(DISTINCT NULLIF(username, '')) AS distinct_users, count(*) FILTER ( WHERE created_at >= now() - INTERVAL '24 hours' ) AS events_last_24h, - count(DISTINCT username) FILTER ( + count(DISTINCT NULLIF(username, '')) FILTER ( WHERE created_at >= now() - INTERVAL '24 hours' ) AS active_users_last_24h FROM user_events @@ -204,7 +214,7 @@ async def analytics_dashboard( """ SELECT date_trunc('day', created_at)::date AS day, count(*) AS events, - count(DISTINCT username) AS users + count(DISTINCT NULLIF(username, '')) AS users -- см. выше (#2715) FROM user_events WHERE created_at >= now() - make_interval(days => CAST(:days AS int)) GROUP BY date_trunc('day', created_at)::date @@ -261,6 +271,7 @@ async def analytics_dashboard( count(*) FILTER (WHERE event_type = 'estimate_request') AS searches, max(created_at) AS last_seen FROM user_events + WHERE username <> '' -- не аккаунт, см. /audit/accounts выше (#2715) GROUP BY username ORDER BY events DESC LIMIT 50 diff --git a/tradein-mvp/backend/app/api/v1/auth.py b/tradein-mvp/backend/app/api/v1/auth.py index bfe43cf6..af346cde 100644 --- a/tradein-mvp/backend/app/api/v1/auth.py +++ b/tradein-mvp/backend/app/api/v1/auth.py @@ -40,6 +40,10 @@ Security: флуда получал 429 столько раз, сколько пытался. Ключ — IP, поэтому защита поднимает стоимость атаки, но не закрывает её (подделка за вторым прокси, общий адрес за NAT, ротация через ботнет) — см. docstring той же функции. + Отказ по насыщению выдаётся ДО выборки из реестра (#2715): иначе на этом + пути оставалась бы единственная работа, время которой зависит от того, + существует ли имя, — а bcrypt, который эту разницу ровняет, до него уже не + доходит. След инцидента — агрегированный, `_saturated_429`. - Поверх него — ГЛОБАЛЬНЫЙ счётчик неудач на ИМЯ, без IP в ключе (#2571): лимит по паре (username, IP) распределённый перебор обходит целиком, просто меняя адрес. Превышение порога не блокирует вход, а замедляет ответ @@ -54,6 +58,7 @@ from __future__ import annotations import asyncio import logging import secrets +import time from typing import Annotated from fastapi import APIRouter, Depends, HTTPException, Request, Response @@ -61,7 +66,12 @@ from pydantic import BaseModel, Field from sqlalchemy.orm import Session from app.core.config import settings -from app.core.password import PasswordVerifyOverloadedError, hash_password, verify_password_bounded +from app.core.password import ( + PasswordVerifyOverloadedError, + hash_password, + verify_password_bounded, + verify_slots_saturated, +) from app.core.ratelimit import SlidingWindowLimiter, _client_ip from app.services.auth_session import create_session, get_user_by_username, revoke_session from app.services.identity_store import AccessState, get_identity_db @@ -174,6 +184,115 @@ def _throttle_delay_s(fails_in_window: int) -> float: return min(settings.login_username_throttle_max_delay_s, 2.0 ** min(excess - 1, 16)) +# Не чаще одной записи в это окно на ВСЕ отказы по насыщению (#2715). Окно, а не +# запись на запрос, потому что лог у бэкенда общий и ограниченный (docker +# json-file, max-size 20m × max-file 3): при флуде в сотни запросов в секунду +# строка на каждый отказ прокручивает 60 МБ за минуты и выселяет ВСЕ остальные +# логи ровно во время атаки — то есть в момент, когда они нужнее всего. +# Значение не в настройках намеренно: это не тюнинг, а «человек читает лог», и +# крутить его нечем — меньше секунды возвращает исходную проблему, больше +# ухудшает разрешение по времени, не давая взамен ничего. +_SATURATION_REPORT_WINDOW_S = 1.0 + +# Отказов с прошлой записи и когда была прошлая запись (monotonic; None — записи +# ещё не было). Обычные глобалы без лока — по той же причине, что и счётчик +# слотов в `app.core.password`: обе строчки исполняются в потоке событийного +# цикла и между чтением и записью нет `await`. +_saturation_rejected = 0 +_saturation_reported_at: float | None = None + + +def _saturated_429(ip: str) -> HTTPException: + """429 «слоты сверки заняты» + АГРЕГИРОВАННЫЙ след инцидента. + + Событие неудачного входа тут не пишется и бюджет неудач по имени не + тратится сознательно (#2712): пароль не проверялся, это не попытка входа, а + трата бюджета означала бы, что насыщением можно заблокировать чужую учётку. + Но тогда весь инцидент виден ровно здесь, и до #2715 — только строкой в + логе на каждый отклонённый запрос (см. `_SATURATION_REPORT_WINDOW_S`). + + Поэтому на окно приходится одна строка в лог И одно событие + `login_verify_saturated` в `user_events` — с числом отказов, накопленных с + прошлой записи. Событие важнее строки: аудит переживает и ротацию логов, и + редеплой. Первый отказ отчитывается сразу, а не в конце окна: одиночная + аномалия обязана быть видна, даже если продолжения не будет. + + `since_prev_s` в payload — НЕ дубль `created_at`, а единственный способ + прочитать счётчик правильно. Хвост копится, пока не придёт следующий отказ: + атака кончилась в 03:00, 900 отказов остались неотчитанными — и во вторник + одиночный 429 соседа по NAT унёс бы их все в запись, датированную вторником + и подписанную АДРЕСОМ СОСЕДА. С `since_prev_s` видно, что 901 отказ + накоплен за неделю, а не за секунду, и что читать `ip` в этой записи не + надо. `None` — первая запись за жизнь процесса, сравнивать не с чем. + + Уровень ERROR, а не WARNING, — не косметика: бэкенд поднят с + `LoggingIntegration(level=INFO, event_level=ERROR)` (app/main.py), то есть + ровно с ERROR запись становится событием GlitchTip, а WARNING остаётся + строкой в docker-логе, которая умирает с ротацией и редеплоем. Цена + прецедента известна (#2674): монитор писал WARNING про протухшие куки — и + событий было ноль. Спама не будет: запись не чаще раза в окно, и все они + группируются в один issue (шаблон сообщения один). + + Чего это НЕ делает: у GlitchTip-проекта нет ни правил, ни получателей + (#2673), так что уведомление никому не уйдёт — событие будет видно в + интерфейсе, но не в чьём-то телефоне. Проверить доставку поведенчески + сейчас не на чем, и утверждать её здесь было бы враньём. + + `username=""` — не заглушка: имя не пишем ПОТОМУ, что отказ случился до + того, как мы на него посмотрели. Записывай мы присланное, атакующий + наполнял бы аудит строками с любым именем на выбор. Пустое имя — не аккаунт, + и списки аудита его отфильтровывают (`WHERE username <> ''` в + `app/api/v1/audit.py`), иначе оно встало бы первой строкой в списке + аккаунтов и фантомом в `count(DISTINCT username)`. `ip` — адрес последнего + отклонённого запроса, то есть ОБРАЗЕЦ: при распределённом флуде адресов + много, и по одной записи их не восстановить (счётчик — восстановит). + + Потолок объёма: час непрерывной атаки — это 3600 строк в `user_events` + (в таблице за всю её жизнь ~3.4 тысячи), сутки — под 86 тысяч. Retention у + таблицы нет, а `GET /audit/accounts` делает полный `GROUP BY` без фильтра по + времени. То же давление уходит на квоту проекта в GlitchTip — тот же + механизм вытеснения чужого сигнала, только в другом ведре. Дойдёт до этого — + окно агрегации растёт с длительностью атаки (экспонента с потолком, как у + `_throttle_delay_s`), это следующий шаг, а не сегодняшний. + """ + global _saturation_rejected, _saturation_reported_at + + _saturation_rejected += 1 + now = time.monotonic() + since_prev = None if _saturation_reported_at is None else now - _saturation_reported_at + if since_prev is None or since_prev >= _SATURATION_REPORT_WINDOW_S: + rejected, _saturation_rejected = _saturation_rejected, 0 + _saturation_reported_at = now + logger.error( + "login rejected: password verify saturated — %d отказов, " + "с прошлой записи %s с, последний ip=%s", + rejected, + "—" if since_prev is None else f"{since_prev:.1f}", + ip, + ) + schedule_event( + event_type="login_verify_saturated", + username="", + ip=ip, + path="/api/v1/auth/login", + method="POST", + payload={ + "rejected": rejected, + # Считается ДО сдвига `_saturation_reported_at` — иначе всегда 0. + "since_prev_s": None if since_prev is None else round(since_prev, 1), + }, + ) + + # Retry-After 1с — порядок времени одной сверки, не окно соседнего + # `_LOGIN_LIMITER`. Ответ ОДИН И ТОТ ЖЕ для любого имени: отказ приходит до + # сверки и потому ничего не сообщает о том, существует ли учётка. + return HTTPException( + status_code=429, + detail="слишком много попыток входа, попробуйте позже", + headers={"Retry-After": "1"}, + ) + + async def _reject_invalid_credentials( db: Session, username: str, ip: str, user_agent: str | None ) -> HTTPException: @@ -256,6 +375,16 @@ async def login( headers={"Retry-After": str(int(retry_after) + 1)}, ) + # Гейт насыщения — ДО выборки из реестра (#2715). Заведомо отклоняемый + # запрос не берёт соединение из пула и не делает SELECT по имени: под + # насыщением это была бы единственная работа на пути отказа, а значит и + # единственное, чьё время зависит от существования учётки — bcrypt, который + # эту разницу ровняет, до отказанного запроса не доходит вовсе. Решение + # всё равно остаётся за `verify_password_bounded` ниже (тот же предикат, + # `except` под ним никуда не делся) — здесь только экономия похода в базу. + if verify_slots_saturated(ip): + raise _saturated_429(ip) + user = get_user_by_username(db, body.username) hash_to_check = ( user["password_hash"] @@ -274,17 +403,11 @@ async def login( password_ok = await verify_password_bounded(body.password, hash_to_check, key=ip) except PasswordVerifyOverloadedError: # Настоящий потолок темпа (#2665): слоты проверки заняты, ждать нельзя — - # ждущий держит соединение к БД. Отказ ОДИНАКОВ для любого имени и - # случается ДО сверки, поэтому оракулом существования учётки не служит и - # бюджет неудач по имени не тратит (это не попытка входа: пароль не - # проверялся). Retry-After 1с — порядок времени одной проверки, не окно - # соседнего `_LOGIN_LIMITER`. - logger.warning("login rejected: password verify saturated ip=%s", ip) - raise HTTPException( - status_code=429, - detail="слишком много попыток входа, попробуйте позже", - headers={"Retry-After": "1"}, - ) from None + # ждущий держит соединение к БД. Предчек выше сюда почти всё и отсекает, + # но авторитетен ИМЕННО ЭТОТ отказ, поэтому ветка остаётся. Ответ — + # тот же самый и с той же аргументацией, что у предчека: один helper, + # чтобы две ветки не разъехались (одинаковость 429 — часть защиты). + raise _saturated_429(ip) from None # Пароль проверен ВЫШЕ и безусловно — только теперь смотрим на состояние # доступа. Порядок несущий, а не стилистический: см. модульный docstring. diff --git a/tradein-mvp/backend/app/core/password.py b/tradein-mvp/backend/app/core/password.py index 2cec3ada..374d55a2 100644 --- a/tradein-mvp/backend/app/core/password.py +++ b/tradein-mvp/backend/app/core/password.py @@ -123,6 +123,32 @@ def _per_key_slot_cap() -> int: return max(1, settings.login_password_verify_max_inflight // 2) +def verify_slots_saturated(key: str) -> bool: + """Тот же предикат, по которому отказывает `verify_password_bounded`, но БЕЗ взятия слота. + + Нужен вызывающему ровно затем, чтобы отказать ДО похода в БД (#2715). Гейт + стоял ПОСЛЕ выборки пользователя, и каждый заведомо отклоняемый запрос всё + равно брал соединение из пула и делал SELECT по имени — тогда, когда система + уже перегружена. Хуже того, под насыщением эта выборка оставалась + ЕДИНСТВЕННОЙ работой на пути отказа: bcrypt, который ровняет время ответа + для существующего и несуществующего имени, ниже по течению и до него не + доходит, так что разницу «строка найдена / не найдена» ничто не маскировало. + + Предчек, а не решение: авторитетная проверка остаётся внутри + `verify_password_bounded` — она зовёт ЭТУ ЖЕ функцию, так что разъехаться + двум условиям нечем, и инвариант «одна точка выноса = одна точка учёта» + цел (слот здесь не резервируется и не отдаётся). + + Учитывает и общий потолок, и долю на ключ (#2714) — иначе предчек не + покрывал бы главный случай: при флуде с ОДНОГО адреса первым упирается + именно доля, и большинство отказов снова ходило бы в базу. + """ + return ( + _verify_inflight >= settings.login_password_verify_max_inflight + or _verify_inflight_by_key.get(key, 0) >= _per_key_slot_cap() + ) + + async def verify_password_bounded(plain: str, hashed: str, *, key: str) -> bool: """`verify_password`, унесённая с событийного цикла И с сознательным потолком темпа (#2665). @@ -193,9 +219,10 @@ async def verify_password_bounded(plain: str, hashed: str, *, key: str) -> bool: """ global _verify_inflight - if _verify_inflight >= settings.login_password_verify_max_inflight: - raise PasswordVerifyOverloadedError - if _verify_inflight_by_key.get(key, 0) >= _per_key_slot_cap(): + # АВТОРИТЕТНАЯ проверка. Вызывающий может спросить то же самое заранее + # (`verify_slots_saturated`, #2715), но решение принимается здесь и только + # здесь — предчек экономит поход в БД, а не заменяет этот отказ. + if verify_slots_saturated(key): raise PasswordVerifyOverloadedError loop = asyncio.get_running_loop() diff --git a/tradein-mvp/backend/tests/test_audit_api.py b/tradein-mvp/backend/tests/test_audit_api.py index 78ec6684..a3226678 100644 --- a/tradein-mvp/backend/tests/test_audit_api.py +++ b/tradein-mvp/backend/tests/test_audit_api.py @@ -53,6 +53,39 @@ def test_days_param_uses_cast_as_int() -> None: assert "CAST(:days AS int)" in _AUDIT_SRC +def test_every_group_by_username_filters_out_the_nameless() -> None: + """Каждая выборка «по аккаунтам» отбрасывает строки с пустым именем (#2715). + + Пустое имя пишет `login_verify_saturated`: отказ по насыщению случается ДО + того, как мы посмотрели на присланное имя, и записать его нельзя — иначе + атакующий набивал бы аудит строками с любым именем на выбор. Но аккаунтом + такая строка от этого не становится: без фильтра она встаёт ПЕРВОЙ в списке + (её `last_seen_at` — момент атаки), даёт фантома в `count(DISTINCT + username)`, а раскрытие уходит в `/audit/accounts/{username}` с + `min_length=1` — то есть в ошибку. + + То же и со счётчиками уникальных: `count(DISTINCT username)` считал бы + безымянного за человека, и первая же атака НАВСЕГДА добавила бы +1 к числу + пользователей (строка остаётся в таблице). `NULLIF(username, '')` роняет её + в NULL, который `count(DISTINCT)` не считает. Сами события при этом из + `total_events` не исчезают — они события, просто не люди. + + Сравнение ЧИСЛОМ, а не поиском подстроки: так сторож ловит и НОВУЮ выборку, + добавленную без фильтра, а не только сегодняшние. На проде пустых имён + сейчас 0 из 3365 строк — то есть это ново. + """ + grouped = _AUDIT_SRC.count("GROUP BY username") + filtered = _AUDIT_SRC.count("WHERE username <> ''") + assert grouped == filtered, ( + f"{grouped} выборок GROUP BY username, из них с фильтром {filtered} — " + "безымянная строка попадёт в список аккаунтов" + ) + assert "count(DISTINCT username)" not in _AUDIT_SRC, ( + "count(DISTINCT username) считает безымянные события за людей — " + "нужен count(DISTINCT NULLIF(username, ''))" + ) + + # --------------------------------------------------------------------------- # Fakes — mirror the mocked-DB convention used across tests/test_user_events.py etc. # --------------------------------------------------------------------------- diff --git a/tradein-mvp/backend/tests/test_auth_api.py b/tradein-mvp/backend/tests/test_auth_api.py index 090b9422..17b0930e 100644 --- a/tradein-mvp/backend/tests/test_auth_api.py +++ b/tradein-mvp/backend/tests/test_auth_api.py @@ -32,6 +32,7 @@ in-memory fake DB standing in for the identity registry: from __future__ import annotations import asyncio +import logging import os import re import time @@ -259,6 +260,10 @@ def _reset_state(monkeypatch: pytest.MonkeyPatch) -> None: auth_mod.reset_cache_for_tests() auth_router._LOGIN_LIMITER._hits.clear() auth_router._USERNAME_FAIL_LIMITER._hits.clear() + # Агрегатор отказов по насыщению (#2715) — тоже глобал процесса: без сброса + # недосчитанные отказы одного теста всплывают в записи другого. + monkeypatch.setattr(auth_router, "_saturation_rejected", 0) + monkeypatch.setattr(auth_router, "_saturation_reported_at", None) monkeypatch.setattr(config.settings, "auth_mode", "dual") # Каждый тест стартует в ДЕФОЛТНОМ режиме реестра (сегодняшний прод), даже # если предыдущий переключался на `auth`. @@ -958,6 +963,183 @@ async def test_flood_from_one_ip_leaves_login_open_for_another_ip( ) +# --------------------------------------------------------------------------- +# #2715 — отказ по насыщению: до похода в БД и со следом, который не выселяет лог +# --------------------------------------------------------------------------- + + +def _saturate_verify_slots(monkeypatch: pytest.MonkeyPatch) -> None: + """Слоты сверки заняты — снаружи ровно то же, что живой флуд, но без гонок. + + Именно счётчик, а не мок `verify_password_bounded`: проверяем настоящий + предикат отказа (`verify_slots_saturated` читает этот же глобал), а не + собственную заглушку. + """ + monkeypatch.setattr(password_mod, "_verify_inflight", 999) + + +def test_saturated_login_answers_before_touching_the_registry( + client: TestClient, store: _Store, monkeypatch: pytest.MonkeyPatch +) -> None: + """Под насыщением отказ приходит ДО выборки пользователя (#2715). + + Гейт стоял после SELECT'а, и каждый заведомо отклоняемый запрос всё равно + брал соединение из пула — тогда, когда система уже перегружена. Хуже того, + эта выборка оставалась ЕДИНСТВЕННОЙ работой на пути отказа: bcrypt, ровняющий + время ответа для существующего и несуществующего имени, до отказанного + запроса не доходит вовсе, так что разницу маскировать было нечем. + + Мерим не тайминг (в CI флейкует), а сам факт похода в реестр — и заодно + побайтовую одинаковость ответа для живого и выдуманного имени. + """ + store.add_user("alice", hash_password("Secret123!"), role="employee") + _capture_events(monkeypatch) + + lookups: list[str] = [] + real_lookup = auth_router.get_user_by_username + + def _spy(db: Any, username: str) -> Any: + lookups.append(username) + return real_lookup(db, username) + + monkeypatch.setattr(auth_router, "get_user_by_username", _spy) + _saturate_verify_slots(monkeypatch) + + bodies = [] + for name in ("alice", "ghost"): + resp = client.post( + "/api/v1/auth/login", + json={"username": name, "password": "x"}, + headers={"x-forwarded-for": "203.0.113.5"}, + ) + assert resp.status_code == 429, resp.text + assert resp.headers["Retry-After"] == "1" + bodies.append(resp.text) + + assert lookups == [], f"под насыщением всё-таки сходили в реестр: {lookups}" + # Существующее и несуществующее имя — неразличимы (#2571 на этом пути тоже). + assert bodies[0] == bodies[1] + + +def test_key_share_alone_also_answers_before_the_registry( + client: TestClient, store: _Store, monkeypatch: pytest.MonkeyPatch +) -> None: + """Долю на ключ предчек проверяет ТОЖЕ — и это главный случай, а не запасной. + + Соседний тест занимает ОБЩИЙ счётчик, а `or` в `verify_slots_saturated` + коротит на первой половине: выброси вторую — и тот тест останется зелёным. + Между тем при флуде с ОДНОГО адреса (#2714) общий потолок не выбирается + вовсе, первой упирается именно доля, и без неё в базу ходили бы почти все + отклонённые запросы. + """ + store.add_user("alice", hash_password("Secret123!"), role="employee") + _capture_events(monkeypatch) + + lookups: list[str] = [] + real_lookup = auth_router.get_user_by_username + + def _spy(db: Any, username: str) -> Any: + lookups.append(username) + return real_lookup(db, username) + + monkeypatch.setattr(auth_router, "get_user_by_username", _spy) + # Общий котёл (4) НЕ выбран: занято 2 из 4, и оба — одним адресом. Это ровно + # его доля (`_per_key_slot_cap` = 4 // 2), больше ему не дают. + monkeypatch.setattr(password_mod, "_verify_inflight", 2) + monkeypatch.setattr(password_mod, "_verify_inflight_by_key", {"203.0.113.5": 2}) + assert password_mod._per_key_slot_cap() == 2 # исходные условия теста + + flooder = client.post( + "/api/v1/auth/login", + json={"username": "alice", "password": "x"}, + headers={"x-forwarded-for": "203.0.113.5"}, + ) + assert flooder.status_code == 429, flooder.text + assert lookups == [], f"доля исчерпана, а в реестр всё-таки сходили: {lookups}" + + # И тут же — доказательство, что предчек не отказывает всем подряд: с + # ДРУГОГО адреса свободные слоты есть, запрос идёт дальше, в реестр. + other = client.post( + "/api/v1/auth/login", + json={"username": "alice", "password": "wrong"}, + headers={"x-forwarded-for": "198.51.100.10"}, + ) + assert other.status_code == 401, other.text + assert lookups == ["alice"] + + +def test_saturation_is_reported_once_per_window_and_lands_in_audit( + client: TestClient, store: _Store, monkeypatch: pytest.MonkeyPatch, caplog: Any +) -> None: + """Двадцать отказов — одна запись в лог и одно событие в аудит, со счётчиком. + + Строка на каждый отказ делила с остальным бэкендом `json-file max-size 20m × + max-file 3`: при флуде в сотни запросов в секунду 60 МБ прокручиваются за + минуты и выселяют ВСЕ остальные логи ровно во время атаки. Поэтому окно. + + А событие в `user_events` — потому что до #2715 инцидент не оставлял в + аудите ни строчки: событие неудачного входа тут не пишется намеренно + (пароль не проверялся, и трата бюджета неудач дала бы блокировку чужой + учётки насыщением) — значит нужен отдельный тип события, и он обязан + появляться независимо от того, ротировался лог или нет. + """ + # ЛИТЕРАЛ, а не арифметика от настройки: окно — компромисс «видно вовремя» + # против «не выселяет лог», и подъём его до минут прячет атаку целиком. + assert auth_router._SATURATION_REPORT_WINDOW_S == 1.0 + + events = _capture_events(monkeypatch) + _saturate_verify_slots(monkeypatch) + # Окно на весь тест — иначе медленный CI разбил бы 20 запросов на два окна + # и число записей стало бы функцией скорости раннера. + monkeypatch.setattr(auth_router, "_SATURATION_REPORT_WINDOW_S", 60.0) + caplog.set_level(logging.WARNING, logger="app.api.v1.auth") + + for i in range(20): + resp = client.post( + "/api/v1/auth/login", + json={"username": f"ghost{i}", "password": "x"}, + headers={"x-forwarded-for": "203.0.113.5"}, + ) + assert resp.status_code == 429, resp.text + + lines = [r for r in caplog.records if "saturated" in r.getMessage()] + assert len(lines) == 1, f"20 отказов дали {len(lines)} строк в логе — агрегации нет" + # ERROR, а не WARNING: бэкенд поднят с LoggingIntegration(event_level=ERROR) + # (app/main.py), и только с ERROR запись становится событием GlitchTip. + # Понижение уровня выключило бы канал молча — прецедент #2674. + assert lines[0].levelno == logging.ERROR + + saturated = [e for e in events if e["event_type"] == "login_verify_saturated"] + assert len(saturated) == 1, saturated + # Первый отказ отчитывается сразу (одиночная аномалия обязана быть видна), + # поэтому в первой записи он один — накопленное придёт следующей. + assert saturated[0]["payload"] == {"rejected": 1, "since_prev_s": None} + assert saturated[0]["ip"] == "203.0.113.5" + # Имя не пишем: отказ случился ДО того, как мы на него посмотрели, а запись + # присланного дала бы атакующему аудит-строки с любым именем на выбор. + assert saturated[0]["username"] == "" + + # Бюджет неудач по имени не тронут — иначе насыщением блокируют чужой вход. + assert [e for e in events if e["event_type"] == "login_failed"] == [] + assert not auth_router._USERNAME_FAIL_LIMITER._hits + + # Окно прошло — следующий отказ приносит НАКОПЛЕННОЕ, а не единицу. + monkeypatch.setattr(auth_router, "_saturation_reported_at", time.monotonic() - 61.0) + resp = client.post( + "/api/v1/auth/login", + json={"username": "ghost-last", "password": "x"}, + headers={"x-forwarded-for": "203.0.113.5"}, + ) + assert resp.status_code == 429 + saturated = [e for e in events if e["event_type"] == "login_verify_saturated"] + assert len(saturated) == 2 + assert saturated[1]["payload"]["rejected"] == 20, "счётчик за окно потерян" + # Без этого числа 20 отказов читались бы как «20 за секунду», хотя копились + # они минуту: хвост уезжает в запись, датированную моментом СЛЕДУЮЩЕГО + # отказа и подписанную ЕГО адресом — возможно, случайного соседа по NAT. + assert saturated[1]["payload"]["since_prev_s"] == pytest.approx(61.0, abs=1.0) + + # --------------------------------------------------------------------------- # POST /logout # --------------------------------------------------------------------------- From f0968c851374fe84f0dfc0775a3f5a1c1409bb9d Mon Sep 17 00:00:00 2001 From: bot-backend Date: Thu, 6 Aug 2026 14:35:32 +0000 Subject: [PATCH 3/6] =?UTF-8?q?test(tradein/auth):=20=D0=BF=D1=80=D0=B0?= =?UTF-8?q?=D0=B2=D0=B8=D0=BB=D0=BE=20=D0=BF=D1=80=D0=BE=20=D1=81=D0=B8?= =?UTF-8?q?=D0=BD=D1=85=D1=80=D0=BE=D0=BD=D0=BD=D1=83=D1=8E=20=D1=81=D0=B2?= =?UTF-8?q?=D0=B5=D1=80=D0=BA=D1=83=20=E2=80=94=20=D1=81=D1=82=D0=BE=D1=80?= =?UTF-8?q?=D0=BE=D0=B6=D0=B5=D0=BC,=20=D0=B0=20=D0=BD=D0=B5=20=D0=BA?= =?UTF-8?q?=D0=BE=D0=BC=D0=BC=D0=B5=D0=BD=D1=82=D0=B0=D1=80=D0=B8=D0=B5?= =?UTF-8?q?=D0=BC=20(#2715)=20(#2735)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../backend/tests/test_password_call_sites.py | 110 ++++++++++++++++++ 1 file changed, 110 insertions(+) create mode 100644 tradein-mvp/backend/tests/test_password_call_sites.py diff --git a/tradein-mvp/backend/tests/test_password_call_sites.py b/tradein-mvp/backend/tests/test_password_call_sites.py new file mode 100644 index 00000000..48e37a9d --- /dev/null +++ b/tradein-mvp/backend/tests/test_password_call_sites.py @@ -0,0 +1,110 @@ +"""Правило «из `async def` зови ТОЛЬКО ограниченную сверку» — проверяемое (#2715). + +Правило живёт в docstring `app/core/password.py`: синхронный `verify_password` +блокирует поток на ~282 мс (bcrypt cost 12), поэтому из кода приложения его +зовёт РОВНО ОДНА функция — `verify_password_bounded`, и она же единственная, +кто считает слоты (потолок темпа #2665 + доля на ключ #2714). + +Комментарий это правило не удерживает. Синхронная функция остаётся публичной и +импортируемой, и достаточно одной строчки `asyncio.to_thread(verify_password, +…)` в будущем коде, чтобы получить вынос в поток ВООБЩЕ БЕЗ учёта слотов: +внешне всё работает, вход отвечает быстро, а потолок перебора тихо исчезает. +Ревью такое ловит ровно до тех пор, пока помнит, что правило есть. + +Прецедент такого сторожа в репозитории: backend/tests/sql/test_auth_sql_migrations.py. + +ПОЧЕМУ AST, А НЕ GREP. `verify_password` упоминается в комментариях и docstring'ах +(app/api/v1/auth.py, app/core/config.py) — текстовый поиск краснел бы на них, и +сторож пришлось бы ослаблять исключениями до бессмысленности. AST видит только +ССЫЛКИ НА СИМВОЛ и ловит форму без скобок (`to_thread(verify_password, …)`), +которую `grep 'verify_password('` не поймал бы вовсе — то есть ровно ту, ради +которой сторож и написан. + +ЧЕГО СТОРОЖ НЕ ВИДИТ, и это записано тут, а не подразумевается: строкового +доступа (`getattr(mod, "verify_password")`) и обхода модуля целиком (прямой +`bcrypt.checkpw`). От НАМЕРЕННОГО обхода он не защищает и не может — только от +нечаянного, а нечаянный и есть частый случай. Обе непойманные формы закреплены +исполняемо (`test_detector_blind_spots_are_known`), чтобы «не ловим» было +проверенным фактом, а не обещанием в тексте. + +Без БД и без сети — только чтение файлов. +""" + +from __future__ import annotations + +import ast +from pathlib import Path + +_BACKEND_ROOT = Path(__file__).resolve().parents[1] +_APP_DIR = _BACKEND_ROOT / "app" +# Единственное место, которому синхронная сверка разрешена: там она и определена, +# и оттуда её забирает пул внутри `verify_password_bounded`. +_OWNER = _APP_DIR / "core" / "password.py" + + +def _references_verify_password(source: str) -> bool: + """Ссылается ли модуль на символ `verify_password` (в любой форме).""" + for node in ast.walk(ast.parse(source)): + if isinstance(node, ast.Name) and node.id == "verify_password": + return True + if isinstance(node, ast.Attribute) and node.attr == "verify_password": + return True + if isinstance(node, ast.ImportFrom) and any( + alias.name == "verify_password" for alias in node.names + ): + return True + return False + + +def test_detector_actually_detects() -> None: + """Сторож обязан уметь краснеть — иначе он зелен вхолостую. + + Проверка на самого себя: пустой детектор (`return False`) прошёл бы все + файлы приложения и выглядел бы работающим сторожем ровно до первого + настоящего нарушения. + """ + # Формы, которые обязан ловить. + assert _references_verify_password("from app.core.password import verify_password") + assert _references_verify_password("asyncio.to_thread(verify_password, plain, hashed)") + assert _references_verify_password("password.verify_password(plain, hashed)") + assert _references_verify_password("ok = verify_password(plain, hashed)") + + # Формы, на которые краснеть НЕЛЬЗЯ (иначе сторож потребуют выключить). + assert not _references_verify_password("await verify_password_bounded(p, h, key=ip)") + assert not _references_verify_password('"""Зови verify_password только из пула."""') + assert not _references_verify_password("# verify_password тут только в комментарии") + + +def test_detector_blind_spots_are_known() -> None: + """Слепые зоны — зафиксированы, а не забыты. + + Обе формы обходят сторож НАМЕРЕННЫМ усилием: строковый доступ к атрибуту и + обход модуля целиком. Ловить их AST'ом можно было бы только ценой ложняков + (любой `getattr` с любой строкой, любой вызов bcrypt), а цена ложняка — + требование выключить сторож. Тест держит это знание исполняемым: захочет + однажды детектор их ловить — покраснеет здесь и заставит осознанно + переписать и этот тест, и текст модуля. + """ + assert not _references_verify_password('fn = getattr(password_mod, "verify_password")') + assert not _references_verify_password("bcrypt.checkpw(plain.encode(), hashed.encode())") + + +def test_sync_verify_password_is_called_from_one_place_only() -> None: + """В `app/` синхронную сверку не поминает никто, кроме её собственного модуля.""" + # Область сканирования жива. `rglob` по несуществующему каталогу не падает — + # отдаёт пусто, нарушителей ноль, сторож зелен НАВСЕГДА. Достаточно + # переложить этот файл в подкаталог tests/ (их уже восемь, и прецедент + # такого сторожа лежит именно в подкаталоге), чтобы `parents[1]` уехал. + assert _OWNER.exists(), f"область сканирования съехала: {_APP_DIR}" + + offenders = [ + str(path.relative_to(_BACKEND_ROOT)) + for path in sorted(_APP_DIR.rglob("*.py")) + if path != _OWNER and _references_verify_password(path.read_text(encoding="utf-8")) + ] + + assert offenders == [], ( + f"{offenders}: синхронный verify_password блокирует поток на ~282 мс и НЕ считает " + "слоты. Из кода приложения зови verify_password_bounded (app/core/password.py) — " + "она единственная точка выноса в пул и единственная точка учёта потолка" + ) From 4aec49f7fb64e0253043cbdd8847afaaffba93b5 Mon Sep 17 00:00:00 2001 From: bot-backend Date: Thu, 6 Aug 2026 15:22:21 +0000 Subject: [PATCH 4/6] =?UTF-8?q?fix(tradein/yandex):=20=D0=B2=20=D0=BE?= =?UTF-8?q?=D1=87=D0=B5=D1=80=D0=B5=D0=B4=D1=8C=20=D0=BE=D0=B1=D0=BE=D0=B3?= =?UTF-8?q?=D0=B0=D1=89=D0=B5=D0=BD=D0=B8=D1=8F=20=D0=BD=D0=B5=20=D0=B1?= =?UTF-8?q?=D0=B5=D1=80=D1=91=D0=BC=20=D1=82=D0=BE,=20=D1=87=D1=82=D0=BE?= =?UTF-8?q?=20=D0=BF=D0=B0=D1=80=D1=81=D0=B5=D1=80=20=D0=BE=D1=82=D0=B2?= =?UTF-8?q?=D0=B5=D1=80=D0=B3=D0=B0=D0=B5=D1=82=20=D0=B4=D0=BE=20=D1=81?= =?UTF-8?q?=D0=B5=D1=82=D0=B8=20(#2674)=20(#2738)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../app/tasks/yandex_detail_backfill.py | 64 ++++++++++++++++++- .../tasks/test_yandex_detail_backfill.py | 63 +++++++++++++++++- 2 files changed, 123 insertions(+), 4 deletions(-) diff --git a/tradein-mvp/backend/app/tasks/yandex_detail_backfill.py b/tradein-mvp/backend/app/tasks/yandex_detail_backfill.py index 16873d03..6538c7c8 100644 --- a/tradein-mvp/backend/app/tasks/yandex_detail_backfill.py +++ b/tradein-mvp/backend/app/tasks/yandex_detail_backfill.py @@ -17,6 +17,14 @@ max_consecutive_blocks. Прогон с нулём обогащений тепе этот брейкер (attempted=5 failed=5) и все 31 назывались успешными. Остаток снапшота уедет в следующую ночь через NULL detail_enriched_at. +Почему брейкер срабатывал так часто (разобрано 2026-08-06, замеры в комментарии +у OFFER_URL_PATTERN): в очереди лежали карточки новостроек, у которых source_url +ведёт на сайт застройщика, а не на realty.yandex.ru/offer//. Парсер отвергает +такие URL регуляркой ДО сети — это не капча, а предрешённый parse→None. Идут они +пачками, поэтому «5 подряд» набиралось на первых же строках и обрывало прогон +целиком. Теперь снапшот-SELECT берёт только то, что парсер в принципе может +разобрать, а размер отброшенного видно в counters.unenrichable_pending. + Why curl_cffi and not YandexDetailScraper.fetch_detail: fetch_detail uses BaseScraper._http_get (plain httpx, no proxy, no TLS fingerprinting). On datacenter IPs Yandex returns captcha / shell-HTML @@ -43,10 +51,27 @@ from app.services import scrape_runs as runs_mod logger = logging.getLogger(__name__) __all__ = [ + "OFFER_URL_PATTERN", "YandexDetailBackfillResult", "run_yandex_detail_backfill", ] +# Условие, при котором обогащение этого объявления вообще возможно (#2723-класс). +# `YandexDetailScraper.parse` первым делом ищет в URL `/offer/<цифры>/` и без него +# возвращает None ЕЩЁ ДО обращения к HTML (providers/yandex/detail.py:150) — то есть +# отказ предрешён регуляркой, а не капчей. +# +# Замер прода 2026-08-06: из 15 511 необогащённых yandex-объявлений 3 535 имеют +# source_url на сайт застройщика (macroserver.ru, prospect-federation.ru, +# strana.com, …) — так карточки новостроек ведут с выдачи Яндекса. Обогащено из +# них за всю историю 0; все 1 210 обогащённых — вида realty.yandex.ru/offer//. +# +# Вред не в бесполезности, а в том, что они идут ПАЧКАМИ (один свип — один +# застройщик) и упираются в брейкер «5 parse-None подряд», обрывающий ВЕСЬ прогон: +# 32 прогона из 53 закончились ровно так — attempted=5, enriched=0, 23 секунды. +# Плюс каждая такая попытка — запрос на чужой сайт, который мы всё равно выбросим. +OFFER_URL_PATTERN = "/offer/[0-9]+" + @dataclass class YandexDetailBackfillResult: @@ -55,6 +80,7 @@ class YandexDetailBackfillResult: attempted: int = 0 enriched: int = 0 failed: int = 0 + unenrichable_pending: int = 0 duration_sec: float = field(default=0.0) def to_dict(self) -> dict[str, int]: @@ -62,6 +88,7 @@ class YandexDetailBackfillResult: "attempted": self.attempted, "enriched": self.enriched, "failed": self.failed, + "unenrichable_pending": self.unenrichable_pending, "duration_sec": int(self.duration_sec), } @@ -105,6 +132,9 @@ async def run_yandex_detail_backfill( # SNAPSHOT: single SELECT at start -- NOT re-selected in loop. # Priority: is_active DESC (active first), scraped_at DESC (newest first). + # Гейт по OFFER_URL_PATTERN — тот же признак, по которому парсер отказывает + # (см. комментарий у константы): в очередь не берём то, что заведомо + # непарсимо, иначе пачка карточек застройщика обрывает прогон брейкером. snapshot = ( db.execute( text( @@ -114,23 +144,53 @@ async def run_yandex_detail_backfill( WHERE source = 'yandex' AND detail_enriched_at IS NULL AND source_url IS NOT NULL + AND source_url ~ CAST(:offer_url_pattern AS text) ORDER BY is_active DESC NULLS LAST, scraped_at DESC NULLS LAST LIMIT CAST(:batch_size AS int) """ ), - {"batch_size": batch_size}, + {"batch_size": batch_size, "offer_url_pattern": OFFER_URL_PATTERN}, ) .mappings() .all() ) + # Отброшенное не должно исчезнуть из виду: без этого счётчика «обогащено + # 12 тыс. из 15,5 тыс.» снова стало бы необъяснимым нулём (#2674). + counters.unenrichable_pending = int( + db.execute( + text( + """ + SELECT count(*) + FROM listings + WHERE source = 'yandex' + AND detail_enriched_at IS NULL + AND source_url IS NOT NULL + AND source_url !~ CAST(:offer_url_pattern AS text) + """ + ), + {"offer_url_pattern": OFFER_URL_PATTERN}, + ).scalar_one() + ) + if counters.unenrichable_pending: + logger.info( + "yandex_detail_backfill: run_id=%d — %d объявлений вне очереди: " + "source_url ведёт не на карточку Яндекса (%s), парсер их отвергает " + "до сети", + run_id, + counters.unenrichable_pending, + OFFER_URL_PATTERN, + ) + if not snapshot: logger.info( "yandex_detail_backfill: run_id=%d -- no pending listings " "(detail_enriched_at IS NULL = 0), done", run_id, ) - runs_mod.mark_done(db, run_id, current_counters) + # to_dict(), а не current_counters: пустая очередь при непустом + # unenrichable_pending — самый важный случай этого счётчика. + runs_mod.mark_done(db, run_id, counters.to_dict()) return counters logger.info( diff --git a/tradein-mvp/backend/tests/tasks/test_yandex_detail_backfill.py b/tradein-mvp/backend/tests/tasks/test_yandex_detail_backfill.py index ccd3d2af..2d9f320a 100644 --- a/tradein-mvp/backend/tests/tasks/test_yandex_detail_backfill.py +++ b/tradein-mvp/backend/tests/tasks/test_yandex_detail_backfill.py @@ -13,6 +13,7 @@ from __future__ import annotations import json import os +import re import sys from unittest.mock import AsyncMock, MagicMock, patch @@ -50,11 +51,13 @@ def _make_snapshot(n: int) -> list[dict]: ] -def _mock_db(snapshot: list[dict]) -> MagicMock: - """Fake Session: first execute() returns snapshot via .mappings().all().""" +def _mock_db(snapshot: list[dict], unenrichable: int = 0) -> MagicMock: + """Fake Session: execute() отдаёт снапшот через .mappings().all(), а + .scalar_one() — размер отброшенной (непарсимой) части очереди.""" db = MagicMock() sel = MagicMock() sel.mappings.return_value.all.return_value = snapshot + sel.scalar_one.return_value = unenrichable db.execute.return_value = sel return db @@ -448,3 +451,59 @@ def test_save_detail_enrichment_rowcount_zero_returns_false() -> None: saved = save_detail_enrichment(db, listing_id=404, e=enrichment) assert saved is False + + +# --------------------------------------------------------------------------- +# Очередь не должна содержать того, что парсер отвергает до сети (2026-08-06) +# --------------------------------------------------------------------------- + +# Реальные source_url с прода (2026-08-06). Верх очереди на момент прогона 3300 +# состоял ровно из таких строк: 5 попыток, 5 parse-None, abort за 23 секунды. +_PROD_QUEUE_HEAD = [ + ("https://macroserver.ru/id/224566/", False), + ("https://prospect-federation.ru/flat/192", False), + ("https://macroserver.ru/id/7223953/", False), + ("https://strana.com/ekaterinburg/flat/1234", False), + ("https://realty.yandex.ru/offer/7416316701146842927/", True), + ("https://realty.yandex.ru/offer/7298311881327827251/", True), +] + + +@pytest.mark.asyncio +async def test_queue_gate_matches_parser_gate_and_counts_rest() -> None: + """Снапшот-SELECT судит по тому же признаку, что и парсер, — сторожем, а не на слово. + + `YandexDetailScraper.parse` возвращает None по регулярке в URL, ещё не + заглянув в HTML. Строки шире этого условия гарантированно дают parse-None и + пачкой выбивают брейкер «5 подряд», обрывая ВЕСЬ прогон (32 прогона из 53 на + проде). Проверяем на одних и тех же прод-URL обе стороны + что отброшенное + посчитано, а не молча исчезло. + """ + from scraper_kit.providers.yandex.detail import YandexDetailScraper + + db = _mock_db([], unenrichable=3535) + runs = MagicMock() + session_cls, _session = _make_session_ctx([]) + + with ( + patch(_ASYNC_SESSION, session_cls), + patch(_RUNS, runs), + patch(_SETTINGS, _mock_settings()), + ): + result = await run_yandex_detail_backfill( + db, run_id=42, params={"batch_size": 10, "budget_sec": 60} + ) + + snapshot_call = db.execute.call_args_list[0] + assert "source_url ~ CAST(:offer_url_pattern AS text)" in str(snapshot_call.args[0]) + pattern = snapshot_call.args[1]["offer_url_pattern"] + + scraper = YandexDetailScraper() + for url, enrichable in _PROD_QUEUE_HEAD: + assert (re.search(pattern, url) is not None) is enrichable, url + if not enrichable: + # HTML тут любой: отказ предрешён до его разбора. + assert scraper.parse("сайт застройщика", url) is None, url + + assert result.unenrichable_pending == 3535 + assert runs.mark_done.call_args.args[2]["unenrichable_pending"] == 3535 From 0dc6f126302c28f05c61c774900a3072f171540d Mon Sep 17 00:00:00 2001 From: bot-backend Date: Thu, 6 Aug 2026 15:29:48 +0000 Subject: [PATCH 5/6] =?UTF-8?q?fix(tradein/avito):=20=D1=81=D0=B5=D1=80?= =?UTF-8?q?=D0=B8=D1=8F=20=D0=BE=D1=82=D0=BA=D0=B0=D0=B7=D0=BE=D0=B2=20?= =?UTF-8?q?=D0=BE=D0=B1=D1=80=D1=8B=D0=B2=D0=B0=D0=B5=D1=82=D1=81=D1=8F=20?= =?UTF-8?q?=D0=B8=20=D0=BD=D0=B0=D0=B7=D1=8B=D0=B2=D0=B0=D0=B5=D1=82=20?= =?UTF-8?q?=D0=BF=D1=80=D0=B8=D1=87=D0=B8=D0=BD=D1=83,=20=D0=B0=20=D0=BD?= =?UTF-8?q?=D0=B5=20=D0=B2=D1=8B=D0=B5=D0=B4=D0=B0=D0=B5=D1=82=20=D0=B1?= =?UTF-8?q?=D1=8E=D0=B4=D0=B6=D0=B5=D1=82=20(#2674)=20(#2739)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../backend/app/services/scrape_runs.py | 13 ++- .../app/tasks/avito_detail_backfill.py | 81 +++++++++++++++++- .../tests/tasks/test_avito_detail_backfill.py | 85 +++++++++++++++++++ 3 files changed, 175 insertions(+), 4 deletions(-) diff --git a/tradein-mvp/backend/app/services/scrape_runs.py b/tradein-mvp/backend/app/services/scrape_runs.py index 789be992..dd7a56cf 100644 --- a/tradein-mvp/backend/app/services/scrape_runs.py +++ b/tradein-mvp/backend/app/services/scrape_runs.py @@ -578,6 +578,7 @@ def mark_backfill_finished( *, source: str, aborted_by_blocks: bool = False, + fail_hint: str | None = None, ) -> None: """Честный финал detail-backfill'а (#2674): нулевой прогон ≠ 'done'. @@ -601,11 +602,19 @@ def mark_backfill_finished( `gone` (404 у avito) считается результатом наравне с `enriched`: прогон, который подтвердил снятие объявлений, работу сделал. + + `fail_hint` — самая частая причина отказа этого прогона (задача считает её сама, + см. avito_detail_backfill._failure_signature). Дописывается в текст статуса, + потому что «blocked=5, обогащено 0» не отвечает на единственный вопрос, ради + которого статус и читают: отказала площадка или наш тракт (#2686, #2698). Логи + контейнера на этот вопрос отвечать не могут — они исчезают при пересоздании + контейнера, то есть на первом же деплое после ночного прогона. """ attempted = int(counters.get("attempted") or 0) enriched = int(counters.get("enriched") or 0) blocked = int(counters.get("blocked") or 0) produced = enriched + int(counters.get("gone") or 0) + hint = f"; причина: {fail_hint}" if fail_hint else "" if attempted == 0: mark_done(db, run_id, counters) @@ -614,7 +623,7 @@ def mark_backfill_finished( if blocked and (aborted_by_blocks or produced == 0): reason = ( f"backfill-honest-status: {source} остановлен блоками источника — " - f"blocked={blocked}, обогащено {enriched} из {attempted} попыток (#2674)" + f"blocked={blocked}, обогащено {enriched} из {attempted} попыток{hint} (#2674)" ) logger.error("%s run_id=%d", reason, run_id) mark_banned(db, run_id, reason, counters) @@ -624,7 +633,7 @@ def mark_backfill_finished( reason = ( f"backfill-honest-status: {source} без результата — 0 обогащено из " f"{attempted} попыток (failed={counters.get('failed', 0)}, " - f"blocked={blocked}) (#2674)" + f"blocked={blocked}){hint} (#2674)" ) logger.error("%s run_id=%d", reason, run_id) mark_failed(db, run_id, reason, counters) diff --git a/tradein-mvp/backend/app/tasks/avito_detail_backfill.py b/tradein-mvp/backend/app/tasks/avito_detail_backfill.py index 3805b8e0..fe4ed9c0 100644 --- a/tradein-mvp/backend/app/tasks/avito_detail_backfill.py +++ b/tradein-mvp/backend/app/tasks/avito_detail_backfill.py @@ -13,6 +13,13 @@ session path as the detail-phase of `run_avito_city_sweep` rotate IP on every block, abort after max_consecutive_blocks. Статус оборванного блоками прогона — 'banned' (#2674, runs.mark_backfill_finished): работу он не доделал, остаток снапшота уедет в следующую ночь через NULL detail_enriched_at. + +Отказы, не являющиеся блоками, до 2026-08-06 брейкера не имели вовсе: прогоны +3-5 августа делали ~1600 попыток, получали 1600 отказов, ноль обогащений и +выедали весь бюджет (9000 с) вместе с 1600 запросами через единственный прокси. +Теперь такая серия обрывается по max_consecutive_failures, а самая частая причина +отказа пишется в текст статуса прогона (_failure_signature) — иначе она живёт +только в логах контейнера, а те исчезают на первом же деплое. """ from __future__ import annotations @@ -20,7 +27,9 @@ from __future__ import annotations import asyncio import logging import random +import re import time +from collections import Counter from dataclasses import dataclass, field from urllib.parse import urlparse @@ -99,6 +108,38 @@ _OBLAST_AVITO_URL_PATTERNS = tuple( ) +# Причина отказа карточки без её URL: 1576 отказов одного прогона должны схлопнуться +# в ОДНУ строку, иначе перепись бесполезна. +_URL_IN_MESSAGE_RE = re.compile(r"https?://\S+") + + +def _failure_signature(exc: BaseException) -> str: + """Подпись причины отказа: тип исключения + текст без URL. + + Зачем (замер 2026-08-06): у прогонов 3 и 4 августа counters говорили + `attempted=1576, failed=1576, blocked=0` — и ничего больше. Кто отказал, + площадка или наш тракт, было видно ТОЛЬКО в логах контейнера, а тот + пересоздаётся на каждом деплое и уносит их с собой; в GlitchTip попадают + события уровня ERROR, а поштучные отказы — WARNING. Разница между этими + двумя диагнозами — разные владельцы задачи (#2686, #2698), поэтому она + обязана переживать перезапуск контейнера, то есть лежать в самом прогоне. + + Тип исключения — первый разряд диагноза (AvitoBlockedError = площадка + показала 403/firewall; сетевой класс curl_cffi = наш прокси-тракт; + ValueError = ответ пришёл, но не разобран), текст — второй. + """ + message = _URL_IN_MESSAGE_RE.sub("", str(exc)).strip() + return f"{type(exc).__name__}: {message}"[:160] if message else type(exc).__name__ + + +def _top_failure(census: Counter[str]) -> str | None: + """Самая частая причина отказа с её долей; None — отказов не было.""" + if not census: + return None + reason, hits = census.most_common(1)[0] + return f"{reason} ({hits} из {sum(census.values())})" + + @dataclass class AvitoDetailBackfillResult: """Counters for one backfill run.""" @@ -139,6 +180,8 @@ async def run_avito_detail_backfill( budget_sec: float -- wall-clock budget per run, default 3600s. request_delay_sec: float -- delay between listings, default 6.0s. max_consecutive_blocks: int -- abort threshold, default 5. + max_consecutive_failures: int -- порог обрыва по отказам-не-блокам, + default 25 (см. комментарий у чтения параметра ниже). Lifecycle: update_heartbeat -> snapshot -> loop with budget guard -> mark_backfill_finished (done / banned при блоках / failed при нуле, #2674); @@ -149,6 +192,13 @@ async def run_avito_detail_backfill( budget_sec = float(params.get("budget_sec", 3600)) request_delay_sec = float(params.get("request_delay_sec", 6.0)) max_consecutive_blocks = int(params.get("max_consecutive_blocks", 5)) + # Брейкер на отказы-НЕ-блоки. Блоки свой брейкер имели с самого начала, отказы — + # нет, и это стоило трёх ночей подряд: 3-5 августа прогон делал ~1600 попыток, + # получал 1600 отказов, ноль обогащений и выедал весь бюджет 9000 с (плюс 1600 + # запросов через единственный прокси, #2638). Порог заметно выше блочного: пачка + # мёртвых карточек (404 → ValueError в curl-режиме) не должна обрывать здоровый + # прогон, а 25 отказов подряд без единого успеха — уже не невезение. + max_consecutive_failures = int(params.get("max_consecutive_failures", 25)) warm_batch = int(params.get("warm_batch", 500)) research_every = int(params.get("research_every", 50)) block_cooldown_sec = float(params.get("block_cooldown_sec", 30.0)) @@ -308,9 +358,13 @@ async def run_avito_detail_backfill( ) consecutive_blocks = 0 + consecutive_failures = 0 aborted_by_blocks = False do_sleep = False items_since_warm = 0 + # Перепись причин (блоки + отказы) — переживает пересоздание контейнера, + # в отличие от логов; см. _failure_signature. + failure_census: Counter[str] = Counter() for idx, row in enumerate(snapshot): # Budget guard @@ -429,8 +483,9 @@ async def run_avito_detail_backfill( if use_curl: items_since_warm += 1 consecutive_blocks = 0 + consecutive_failures = 0 - except AvitoListingGoneError: + except AvitoListingGoneError as gone_exc: # #2034: мёртвый листинг (404 / removed) — НЕ блок, НЕ failed. # Координатные дыры в lat-null очереди в основном dead-листинги; # browser-mode рендерит их «Ошибка 404» без item-view → раньше это @@ -440,6 +495,10 @@ async def run_avito_detail_backfill( # и не сбрасываем). Метим is_active=FALSE → листинг уходит из scope # (snapshot SELECT фильтрует is_active = TRUE) и не тратит фетчи впредь. counters.gone += 1 + # 404 — честный ответ площадки, значит тракт цел: серия отказов + # прерывается (блочный брейкер 404 не трогает — см. #2034). + consecutive_failures = 0 + failure_census[_failure_signature(gone_exc)] += 1 try: with db.begin_nested(): db.execute( @@ -481,6 +540,7 @@ async def run_avito_detail_backfill( except (AvitoBlockedError, AvitoRateLimitedError) as e: consecutive_blocks += 1 counters.blocked += 1 + failure_census[_failure_signature(e)] += 1 do_sleep = False logger.warning( "avito_detail_backfill: run_id=%d BLOCKED #%d/%d (consecutive=%d): %s", @@ -538,12 +598,14 @@ async def run_avito_detail_backfill( exc_info=True, ) - except TimeoutError: + except TimeoutError as e: # asyncio.wait_for → TimeoutError (py3.12: asyncio.TimeoutError — alias). # Ловим ДО общего Exception (TimeoutError ⊂ OSError ⊂ Exception). Зависший # fetch отменён → листинг failed, переходим к следующему (loop не зависает, # run не zombie #1950). Не считаем soft-блоком: rotate не дёргаем. counters.failed += 1 + consecutive_failures += 1 + failure_census[_failure_signature(e)] += 1 logger.warning( "avito_detail_backfill: run_id=%d listing %s TIMEOUT (>%.0fs) -- skip", run_id, @@ -557,6 +619,8 @@ async def run_avito_detail_backfill( except Exception as e: counters.failed += 1 + consecutive_failures += 1 + failure_census[_failure_signature(e)] += 1 logger.warning( "avito_detail_backfill: run_id=%d listing %s failed: %s", run_id, @@ -568,6 +632,18 @@ async def run_avito_detail_backfill( except Exception: pass + if consecutive_failures >= max_consecutive_failures: + logger.error( + "avito_detail_backfill: run_id=%d ABORT -- %d отказов подряд без " + "единого успеха, частая причина: %s. enriched=%d attempted=%d", + run_id, + consecutive_failures, + _top_failure(failure_census) or "неизвестна", + counters.enriched, + counters.attempted, + ) + break + if counters.attempted % 25 == 0: current_counters = counters.to_dict() runs_mod.update_heartbeat(db, run_id, current_counters) @@ -580,6 +656,7 @@ async def run_avito_detail_backfill( current_counters, source="avito_detail_backfill", aborted_by_blocks=aborted_by_blocks, + fail_hint=_top_failure(failure_census), ) logger.info( "avito_detail_backfill: run_id=%d FINISHED -- attempted=%d enriched=%d " diff --git a/tradein-mvp/backend/tests/tasks/test_avito_detail_backfill.py b/tradein-mvp/backend/tests/tasks/test_avito_detail_backfill.py index a30a3760..4bc663d8 100644 --- a/tradein-mvp/backend/tests/tasks/test_avito_detail_backfill.py +++ b/tradein-mvp/backend/tests/tasks/test_avito_detail_backfill.py @@ -790,3 +790,88 @@ async def test_backfill_use_curl_block_cooldown_research_no_rebuild() -> None: mock_scraper.return_value._rotate_ip.assert_not_called() runs.mark_backfill_finished.assert_called_once() runs.mark_failed.assert_not_called() + + +# --------------------------------------------------------------------------- +# Отказы-не-блоки: брейкер + перепись причин (2026-08-06) +# --------------------------------------------------------------------------- + + +@pytest.mark.asyncio +async def test_backfill_aborts_on_consecutive_failures_and_names_the_reason() -> None: + """Серия отказов без единого успеха обрывается, а причина попадает в статус прогона. + + Прод 3-5 августа: attempted≈1600, failed≈1600, blocked=0, enriched=0, весь + бюджет 9000 с и 1600 запросов через единственный прокси — и ни слова о том, + ЧТО именно отказало (поштучные отказы логируются WARNING, а логи контейнера + пропадают на первом деплое). Брейкера на отказы-не-блоки не было вовсе. + """ + snapshot = _make_snapshot(200) + db = _mock_db(snapshot) + runs = MagicMock() + # Тот же класс отказа, что видели у соседнего свипа в тот же день. + mock_fetch = AsyncMock( + side_effect=OSError( + "Failed to perform, curl: (56) CONNECT tunnel failed, response 502. " + "See https://curl.se/libcurl/c/libcurl-errors.html" + ) + ) + fake_settings = MagicMock(scraper_fetch_mode="cffi", avito_detail_backfill_use_curl=True) + with ( + patch(_SETTINGS, fake_settings), + patch(_SESSION, return_value=AsyncMock()), + patch(_SCRAPER), + patch(_RUNS, runs), + patch(_FETCH, mock_fetch), + patch(_SLEEP, new_callable=AsyncMock), + ): + result = await run_avito_detail_backfill( + db, + run_id=77, + params={ + "batch_size": 200, + "budget_sec": 3600, + "max_consecutive_failures": 25, + }, + ) + + assert result.attempted == 25, "серия отказов обязана обрываться, а не выедать бюджет" + assert result.failed == 25 + assert result.blocked == 0 + + hint = runs.mark_backfill_finished.call_args.kwargs["fail_hint"] + assert hint is not None + assert "OSError" in hint # тип исключения = кому принадлежит отказ + assert "CONNECT tunnel failed" in hint + assert "25 из 25" in hint # доля, а не единичный пример + assert "https://curl.se" not in hint # URL вырезан, иначе 1600 «разных» причин + + +@pytest.mark.asyncio +async def test_backfill_success_resets_failure_streak() -> None: + """Успех между отказами обнуляет серию — здоровый прогон брейкер не трогает.""" + snapshot = _make_snapshot(5) + db = _mock_db(snapshot) + runs = MagicMock() + boom = ValueError("avito detail HTTP 500 for https://www.avito.ru/x") + # 2 отказа, успех, 2 отказа — при пороге 3 ни одна серия его не достигает. + mock_fetch = AsyncMock(side_effect=[boom, boom, MagicMock(), boom, boom]) + fake_settings = MagicMock(scraper_fetch_mode="cffi", avito_detail_backfill_use_curl=True) + with ( + patch(_SETTINGS, fake_settings), + patch(_SESSION, return_value=AsyncMock()), + patch(_SCRAPER), + patch(_RUNS, runs), + patch(_FETCH, mock_fetch), + patch(_SAVE, return_value=True), + patch(_SLEEP, new_callable=AsyncMock), + ): + result = await run_avito_detail_backfill( + db, + run_id=78, + params={"batch_size": 5, "budget_sec": 3600, "max_consecutive_failures": 3}, + ) + + assert result.attempted == 5 + assert result.enriched == 1 + assert result.failed == 4 From c86a5378efd695f3a952e2f1eda3304367217714 Mon Sep 17 00:00:00 2001 From: bot-backend Date: Thu, 6 Aug 2026 15:41:20 +0000 Subject: [PATCH 6/6] =?UTF-8?q?feat(tradein/houses):=20=D0=B6=D1=83=D1=80?= =?UTF-8?q?=D0=BD=D0=B0=D0=BB=20=D1=81=D0=BB=D0=B8=D1=8F=D0=BD=D0=B8=D0=B9?= =?UTF-8?q?=20=D0=B4=D0=BE=D0=BC=D0=BE=D0=B2=20=E2=80=94=20=D1=81=D0=BB?= =?UTF-8?q?=D0=B8=D1=8F=D0=BD=D0=B8=D0=B5=20=D1=81=D1=82=D0=B0=D0=BB=D0=BE?= =?UTF-8?q?=20=D0=BE=D0=B1=D1=80=D0=B0=D1=82=D0=B8=D0=BC=D1=8B=D0=BC=20(#2?= =?UTF-8?q?740)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../backend/app/services/house_dedup_merge.py | 272 ++++++++++++-- .../backend/data/sql/230_house_merge_log.sql | 262 +++++++++++++ .../backend/tests/test_house_dedup_merge.py | 355 ++++++++++++++++-- 3 files changed, 822 insertions(+), 67 deletions(-) create mode 100644 tradein-mvp/backend/data/sql/230_house_merge_log.sql diff --git a/tradein-mvp/backend/app/services/house_dedup_merge.py b/tradein-mvp/backend/app/services/house_dedup_merge.py index 330b66c0..0f244b97 100644 --- a/tradein-mvp/backend/app/services/house_dedup_merge.py +++ b/tradein-mvp/backend/app/services/house_dedup_merge.py @@ -92,6 +92,30 @@ BACKFILL (reduces recurrence): (same as 108) so the matching pipeline's Tier-1/Tier-2 finds the keeper next scrape and does not immediately re-split it. +MERGE JOURNAL — the merge is REVERSIBLE (#2690, migration 230): + Every loser gets a row in `house_merge_log` written in the SAME transaction as the merge: + the full jsonb snapshot of the deleted row, the keeper's snapshot BEFORE the identity + carry-over, the ids of every child row whose FK moved, the full snapshots of every child row + a UNIQUE collision destroyed, plus the grounds — which pass, which cluster-key VALUE fired, + whether the geo guard was on, and the keeper↔loser distance in metres. + + This exists because the merge used to leave no restorable trace: losers were hard-deleted + with their children and the only record of «what went into what» was a log line, in a + container whose logs rotate faster than a day. A day after a run nobody could even NAME the + pairs, and the only rollback was restoring the whole database. + + Undo: `SELECT * FROM house_merge_undo(batch_id)` inside a transaction — restores the loser + rows, points the children back, re-inserts the destroyed children, and un-does the identity + carry-over on the keeper, reporting per record what it could and could not restore. + + NOTE the journal is deliberately NEUTRAL to the merge rule: it changes no cluster key, no + keeper rule and no guard. It only makes whatever the pass decides reversible — which is the + precondition for revisiting those decisions at all (#2690, #1772). + + distance_m is recorded on BOTH passes, including the fias pass whose geo guard is off. That + asymmetry — merge allowed without a proximity check — was invisible in data before; now + «how many merges happened beyond N metres, on which key» is one query. + IDEMPOTENCY: Every UPDATE/DELETE keys off a temp mapping of (loser→keeper). On a clean table the mapping is empty → every statement touches 0 rows → no-op. Re-running is safe. @@ -105,8 +129,10 @@ psycopg v3: all SQL uses CAST(:x AS type), never the colon-colon bound-param cas from __future__ import annotations +import json import logging import time +import uuid from dataclasses import dataclass, field from typing import Any @@ -260,7 +286,16 @@ def _mapping_sql(cluster_key_case: str, *, apply_geo_guard: bool = True) -> str: -- DIFFERENT house_fias_id — provably different buildings the cluster key collapsed (canon -- slash-collapse «Сулимова, 32»/«Сулимова, 3/2»). No-op for the fias pass (one fias per -- cluster) and for canon clusters where at most one side carries a fias. - SELECT id AS loser_id, keeper_id, norm_address + -- + -- cluster_key / distance_m are carried out of the mapping for the MERGE JOURNAL (#2690): + -- cluster_key records WHICH key value fired, distance_m how far apart the two rows were. + -- distance_m is computed even when the geo guard is OFF for this pass — that is precisely + -- the case where nothing else records the distance, and #2690 had no way to ask + -- «how many merges happened at distances the guard would have blocked» from data. + SELECT id AS loser_id, keeper_id, norm_address, cluster_key, + CASE WHEN keeper_geom IS NOT NULL AND loser_geom IS NOT NULL + THEN ST_DistanceSphere(loser_geom, keeper_geom) + END AS distance_m FROM ranked WHERE rn > 1 AND id <> keeper_id{geo_guard} @@ -289,6 +324,7 @@ _STEPS: list[tuple[str, str]] = [ SET house_id_fk = m.keeper_id FROM _1772_dup_mapping m WHERE l.house_id_fk = m.loser_id + RETURNING m.loser_id, l.id AS child_id """, ), ( @@ -298,6 +334,7 @@ _STEPS: list[tuple[str, str]] = [ SET house_id = m.keeper_id FROM _1772_dup_mapping m WHERE hph.house_id = m.loser_id + RETURNING m.loser_id, hph.id AS child_id """, ), ( @@ -307,6 +344,7 @@ _STEPS: list[tuple[str, str]] = [ SET house_id = m.keeper_id FROM _1772_dup_mapping m WHERE hr.house_id = m.loser_id + RETURNING m.loser_id, hr.id AS child_id """, ), ( @@ -316,6 +354,7 @@ _STEPS: list[tuple[str, str]] = [ SET house_id = m.keeper_id FROM _1772_dup_mapping m WHERE hrc.house_id = m.loser_id + RETURNING m.loser_id, hrc.id AS child_id """, ), ( @@ -325,6 +364,7 @@ _STEPS: list[tuple[str, str]] = [ SET house_id = m.keeper_id FROM _1772_dup_mapping m WHERE ev.house_id = m.loser_id + RETURNING m.loser_id, ev.id AS child_id """, ), # ── UNIQUE(ext_source, ext_id): delete colliding losers, re-point rest ───── @@ -340,6 +380,7 @@ _STEPS: list[tuple[str, str]] = [ AND hs2.ext_source = hs.ext_source AND hs2.ext_id = hs.ext_id ) + RETURNING hs.house_id AS loser_id, to_jsonb(hs.*) AS row_snapshot """, ), ( @@ -349,6 +390,7 @@ _STEPS: list[tuple[str, str]] = [ SET house_id = m.keeper_id FROM _1772_dup_mapping m WHERE hs.house_id = m.loser_id + RETURNING m.loser_id, hs.id AS child_id """, ), # ── UNIQUE(normalized_address): delete colliding losers, re-point rest ───── @@ -363,6 +405,7 @@ _STEPS: list[tuple[str, str]] = [ WHERE haa2.house_id = m.keeper_id AND haa2.normalized_address = haa.normalized_address ) + RETURNING haa.house_id AS loser_id, to_jsonb(haa.*) AS row_snapshot """, ), ( @@ -372,6 +415,7 @@ _STEPS: list[tuple[str, str]] = [ SET house_id = m.keeper_id FROM _1772_dup_mapping m WHERE haa.house_id = m.loser_id + RETURNING m.loser_id, haa.id AS child_id """, ), # ── UNIQUE(house_id, source, room_count, prices_type, period, month_date) ── @@ -393,6 +437,7 @@ _STEPS: list[tuple[str, str]] = [ LEFT JOIN _1772_dup_mapping m ON m.loser_id = t2.house_id ) d WHERE t.id = d.id AND d.rn > 1 + RETURNING t.house_id AS loser_id, to_jsonb(t.*) AS row_snapshot """, ), ( @@ -402,6 +447,7 @@ _STEPS: list[tuple[str, str]] = [ SET house_id = m.keeper_id FROM _1772_dup_mapping m WHERE hpd.house_id = m.loser_id + RETURNING m.loser_id, hpd.id AS child_id """, ), # ── UNIQUE(house_id): one evaluation per keeper ─────────────────────────── @@ -419,6 +465,7 @@ _STEPS: list[tuple[str, str]] = [ LEFT JOIN _1772_dup_mapping m ON m.loser_id = t2.house_id ) d WHERE t.id = d.id AND d.rn > 1 + RETURNING t.house_id AS loser_id, to_jsonb(t.*) AS row_snapshot """, ), ( @@ -428,6 +475,7 @@ _STEPS: list[tuple[str, str]] = [ SET house_id = m.keeper_id FROM _1772_dup_mapping m WHERE hie.house_id = m.loser_id + RETURNING m.loser_id, hie.id AS child_id """, ), # ── UNIQUE(house_id, ext_item_id) ───────────────────────────────────────── @@ -445,6 +493,7 @@ _STEPS: list[tuple[str, str]] = [ LEFT JOIN _1772_dup_mapping m ON m.loser_id = t2.house_id ) d WHERE t.id = d.id AND d.rn > 1 + RETURNING t.house_id AS loser_id, to_jsonb(t.*) AS row_snapshot """, ), ( @@ -454,6 +503,7 @@ _STEPS: list[tuple[str, str]] = [ SET house_id = m.keeper_id FROM _1772_dup_mapping m WHERE hs.house_id = m.loser_id + RETURNING m.loser_id, hs.id AS child_id """, ), # ── UNIQUE(house_id, audit_batch) ───────────────────────────────────────── @@ -471,6 +521,7 @@ _STEPS: list[tuple[str, str]] = [ LEFT JOIN _1772_dup_mapping m ON m.loser_id = t2.house_id ) d WHERE t.id = d.id AND d.rn > 1 + RETURNING t.house_id AS loser_id, to_jsonb(t.*) AS row_snapshot """, ), ( @@ -480,10 +531,98 @@ _STEPS: list[tuple[str, str]] = [ SET house_id = m.keeper_id FROM _1772_dup_mapping m WHERE ama.house_id = m.loser_id + RETURNING m.loser_id, ama.id AS child_id """, ), ] +# ── MERGE JOURNAL (#2690) ───────────────────────────────────────────────────── +# +# Every child of houses(id) except `listings` references it through a column named house_id; +# listings uses house_id_fk. The undo function reads the column name back out of the journal +# key ("таблица.колонка"), so this mapping is what makes the reverse UPDATE possible. +_FK_COLUMN = {"listings": "house_id_fk"} + +# The (table, column) pairs the _STEPS pipeline actually handles, derived FROM the steps so the +# set cannot drift away from them. Compared against pg_catalog before every merge — see +# _assert_all_fk_children_handled. +_HANDLED_CHILDREN: frozenset[tuple[str, str]] = frozenset( + (tbl, _FK_COLUMN.get(tbl, "house_id")) for tbl in {label.split("(")[0] for label, _ in _STEPS} +) + +# Live FK children of houses(id), read from the catalog rather than trusted from a comment. +_FK_CHILDREN_SQL = text( + """ + SELECT CAST(CAST(c.conrelid AS regclass) AS text) AS child_table, + a.attname AS fk_column + FROM pg_constraint c + JOIN unnest(c.conkey) AS k(attnum) ON true + JOIN pg_attribute a ON a.attrelid = c.conrelid AND a.attnum = k.attnum + WHERE c.confrelid = CAST('houses' AS regclass) + AND c.contype = 'f' + """ +) + +# One journal row per loser, written from the mapping BEFORE anything is mutated — so loser_row +# is the row as it stood, and keeper_before precedes the identity carry-over. +_JOURNAL_INSERT_SQL = text( + """ + INSERT INTO house_merge_log ( + batch_id, run_id, initiator, merge_pass, cluster_key, geo_guard, distance_m, + norm_address, loser_id, keeper_id, loser_row, keeper_before + ) + SELECT + CAST(:batch_id AS uuid), + CAST(:run_id AS bigint), + CAST(:initiator AS text), + CAST(:merge_pass AS text), + m.cluster_key, + CAST(:geo_guard AS boolean), + m.distance_m, + m.norm_address, + m.loser_id, + m.keeper_id, + to_jsonb(l.*), + to_jsonb(k.*) + FROM _1772_dup_mapping m + JOIN houses l ON l.id = m.loser_id + JOIN houses k ON k.id = m.keeper_id + """ +) + +# Child bookkeeping lands after the steps ran — only then is it known which rows moved and which +# were destroyed by a UNIQUE collision. +_JOURNAL_CHILDREN_SQL = text( + """ + UPDATE house_merge_log + SET children_repointed = CAST(:children_repointed AS jsonb), + children_deleted = CAST(:children_deleted AS jsonb) + WHERE batch_id = CAST(:batch_id AS uuid) + AND loser_id = CAST(:loser_id AS bigint) + """ +) + + +def _assert_all_fk_children_handled(db: Session) -> None: + """Fail the merge if houses(id) gained an FK child the _STEPS pipeline does not handle. + + This is what makes the journal's promise true rather than merely documented. An unhandled + child is not a cosmetic gap: 9 of the 11 FKs are ON DELETE CASCADE, so `DELETE FROM houses` + would destroy its rows silently — no re-point step touches them, no RETURNING records them, + and the journal would claim a complete snapshot it does not have. Migration 133 already + broke on prod for exactly this (a missed child); there the failure was loud. Here it would + be silent, which is worse. Aborting the transaction costs one skipped merge cycle. + """ + live = {(r.child_table, r.fk_column) for r in db.execute(_FK_CHILDREN_SQL).all()} + unhandled = live - _HANDLED_CHILDREN + if unhandled: + raise RuntimeError( + "merge_duplicate_houses: houses(id) has FK children the merge does not handle: " + f"{sorted(unhandled)}. Their rows would be CASCADE-deleted without a journal entry. " + "Add a re-point step to _STEPS (and its RETURNING) before merging again." + ) + + # Delete the loser houses — all FK children are re-pointed or CASCADE by now. _DELETE_LOSERS_SQL = text( """ @@ -607,14 +746,20 @@ def _run_merge_pass( *, build_sql: Any, pass_label: str, + geo_guard: bool, + batch_id: str, + run_id: int | None, + initiator: str, result: DedupMergeResult, ) -> None: """Run ONE merge pass (fias- or canon-key) inside the caller's open transaction. - Builds a fresh loser→keeper mapping for this pass's cluster key, re-points every FK child - (UNIQUE-collision-safe), carries identity/enrichment onto the keeper, deletes the losers and - backfills sources/aliases. Accumulates counters onto `result`. NEVER commits/rolls back — the - caller owns the single transaction wrapping both passes. + Builds a fresh loser→keeper mapping for this pass's cluster key, writes the MERGE JOURNAL + (#2690), re-points every FK child (UNIQUE-collision-safe), carries identity/enrichment onto + the keeper, deletes the losers and backfills sources/aliases. Accumulates counters onto + `result`. NEVER commits/rolls back — the caller owns the single transaction wrapping both + passes, which is also what makes the journal atomic with the merge: there is no ordering in + which the rows vanish but the journal entry does not land (and dry_run rolls back both). """ # Fresh mapping for this pass. ON COMMIT DROP only fires at txn end, so drop the temp table # explicitly — the second pass must rebuild the same-named table within the one transaction. @@ -623,8 +768,8 @@ def _run_merge_pass( mapping = db.execute( text( - "SELECT loser_id, keeper_id, norm_address FROM _1772_dup_mapping " - "ORDER BY keeper_id, loser_id" + "SELECT loser_id, keeper_id, norm_address, cluster_key, distance_m " + "FROM _1772_dup_mapping ORDER BY keeper_id, loser_id" ) ).all() if not mapping: @@ -634,32 +779,73 @@ def _run_merge_pass( result.losers_deleted += len(mapping) result.clusters_merged += len({row.keeper_id for row in mapping}) - # Audit log: every loser→keeper move with its address, for traceability. + # JOURNAL, phase 1 — snapshot loser + keeper BEFORE any statement mutates them. + db.execute( + _JOURNAL_INSERT_SQL, + { + "batch_id": batch_id, + "run_id": run_id, + "initiator": initiator, + "merge_pass": pass_label, + "geo_guard": geo_guard, + }, + ) + + # Container logs rotate faster than a day (#2690), so this line is a convenience, not the + # record — house_merge_log is. Distance is logged too: it is the one number that says + # whether a merge would have survived the geo guard. for row in mapping: logger.info( - "merge_duplicate_houses: pass=%s merge loser_id=%d → keeper_id=%d address=%r", + "merge_duplicate_houses: pass=%s merge loser_id=%d → keeper_id=%d address=%r " + "distance_m=%s batch=%s", pass_label, row.loser_id, row.keeper_id, row.norm_address, + "n/a" if row.distance_m is None else f"{row.distance_m:.0f}", + batch_id, ) + # Per-loser child bookkeeping, collected from each step's RETURNING: survivors by id (the + # rows are intact, only their FK moved), destroyed rows by full snapshot (nothing else is + # left of them). + repointed: dict[int, dict[str, list[int]]] = {} + deleted: dict[int, dict[str, list[Any]]] = {} + for label, sql in _STEPS: - res = db.execute(text(sql)) - rowcount = res.rowcount or 0 - if label == "listings": - result.listings_repointed += rowcount - elif label.endswith("(collision-delete)") or label.endswith("(dedup)"): + rows = db.execute(text(sql)).all() + rowcount = len(rows) + table = label.split("(")[0] + if label.endswith("(collision-delete)") or label.endswith("(dedup)"): result.children_deleted += rowcount - elif label.endswith("(re-point)") or label in ( - "house_placement_history", - "house_reviews", - "house_reliability_checks", - "external_valuations", - ): - result.children_repointed += rowcount + for r in rows: + deleted.setdefault(r.loser_id, {}).setdefault(table, []).append(r.row_snapshot) + else: + key = f"{table}.{_FK_COLUMN.get(table, 'house_id')}" + for r in rows: + repointed.setdefault(r.loser_id, {}).setdefault(key, []).append(r.child_id) + if label == "listings": + result.listings_repointed += rowcount + else: + result.children_repointed += rowcount logger.debug("merge_duplicate_houses: pass=%s step=%s rows=%d", pass_label, label, rowcount) + # JOURNAL, phase 2 — attach the child bookkeeping to the rows written in phase 1. + touched = sorted(set(repointed) | set(deleted)) + if touched: + db.execute( + _JOURNAL_CHILDREN_SQL, + [ + { + "batch_id": batch_id, + "loser_id": loser_id, + "children_repointed": json.dumps(repointed.get(loser_id, {})), + "children_deleted": json.dumps(deleted.get(loser_id, {}), default=str), + } + for loser_id in touched + ], + ) + # Carry identity/enrichment onto the keeper BEFORE the losers vanish, then delete + backfill. db.execute(_CARRY_OVER_IDENTITY_SQL) db.execute(_DELETE_LOSERS_SQL) @@ -667,7 +853,13 @@ def _run_merge_pass( db.execute(_BACKFILL_ALIASES_SQL) -def merge_duplicate_houses(db: Session, *, dry_run: bool = False) -> dict[str, int]: +def merge_duplicate_houses( + db: Session, + *, + dry_run: bool = False, + run_id: int | None = None, + initiator: str = "manual", +) -> dict[str, int]: """Cluster houses by fias UUID, then by canonical address, merging dups onto one keeper. Re-implements migration 108's proven collision-safe pipeline as a RECURRING TWO-PASS job: @@ -680,16 +872,41 @@ def merge_duplicate_houses(db: Session, *, dry_run: bool = False) -> dict[str, i dry_run=True computes counts then ROLLS BACK (no writes). Idempotent: a clean table yields an empty mapping in each pass → every statement is a 0-row no-op. + Every deleted row is journaled to house_merge_log in the SAME transaction (#2690), so a + merge is reversible via house_merge_undo(batch_id); the batch_id is returned in the log line + and stored on every journal row of this call. + Returns the counter dict (DedupMergeResult.to_counters()). """ start = time.monotonic() result = DedupMergeResult(dry_run=dry_run) + batch_id = str(uuid.uuid4()) try: + # Refuse to merge at all if some FK child would be CASCADE-destroyed unjournaled. + _assert_all_fk_children_handled(db) # Pass 1: cluster by the ФИАС building UUID (runs first — most precise building identity). - _run_merge_pass(db, build_sql=_BUILD_MAPPING_SQL_FIAS, pass_label="fias", result=result) + _run_merge_pass( + db, + build_sql=_BUILD_MAPPING_SQL_FIAS, + pass_label="fias", + geo_guard=False, + batch_id=batch_id, + run_id=run_id, + initiator=initiator, + result=result, + ) # Pass 2: cluster by canonical address, with the cross-fias anti-over-merge guard. - _run_merge_pass(db, build_sql=_BUILD_MAPPING_SQL, pass_label="canon", result=result) + _run_merge_pass( + db, + build_sql=_BUILD_MAPPING_SQL, + pass_label="canon", + geo_guard=True, + batch_id=batch_id, + run_id=run_id, + initiator=initiator, + result=result, + ) if result.losers_deleted == 0: # Clean table — both passes empty. Roll back (we only opened temp tables). @@ -716,12 +933,15 @@ def merge_duplicate_houses(db: Session, *, dry_run: bool = False) -> dict[str, i db.commit() logger.info( "merge_duplicate_houses: COMMITTED clusters=%d losers=%d " - "listings_repointed=%d children_deleted=%d children_repointed=%d", + "listings_repointed=%d children_deleted=%d children_repointed=%d " + "batch_id=%s (undo: SELECT * FROM house_merge_undo('%s'))", result.clusters_merged, result.losers_deleted, result.listings_repointed, result.children_deleted, result.children_repointed, + batch_id, + batch_id, ) except Exception: logger.exception("merge_duplicate_houses: FAILED — rolling back") @@ -761,7 +981,7 @@ def run_house_dedup_merge(db: Session, *, run_id: int, params: dict) -> dict[str } try: runs_mod.update_heartbeat(db, run_id, counters) - counters = merge_duplicate_houses(db, dry_run=dry_run) + counters = merge_duplicate_houses(db, dry_run=dry_run, run_id=run_id, initiator="schedule") runs_mod.mark_done(db, run_id, counters) logger.info( "run_house_dedup_merge: run_id=%d DONE clusters=%d losers=%d dry_run=%s", diff --git a/tradein-mvp/backend/data/sql/230_house_merge_log.sql b/tradein-mvp/backend/data/sql/230_house_merge_log.sql new file mode 100644 index 00000000..bf55ec6b --- /dev/null +++ b/tradein-mvp/backend/data/sql/230_house_merge_log.sql @@ -0,0 +1,262 @@ +-- 230_house_merge_log.sql +-- Журнал слияний домов + обратная операция (#2690). +-- +-- WHY: +-- `house_dedup_merge` — НЕ спящая идея, а живой деструктивный проход: расписание +-- `house_dedup_merge` на проде enabled=true, dry_run=false, такт 7 дней. Шесть прогонов +-- с 2026-06-27 уже удалили 119 строк `houses` (счётчики losers_deleted в scrape_runs: +-- 2/39/31/9/6/32). Единственным следом «кто в кого» была строка `logger.info` в контейнере, +-- а логи ротируются быстрее суток. То есть **уже сегодня** нельзя назвать, какой дом в какой +-- свернули 1 августа, — не говоря о том, чтобы вернуть. +-- +-- Пока этого журнала нет, любой разговор о расширении ключа схлопывания (#2690, #1772) +-- ведётся без права на ошибку: единственный откат — restore всей БД на момент до прогона, +-- т.е. выброс недели сбора. Журнал снимает это условие: слияние становится обратимым, +-- и вопрос о ключе можно пересматривать, а не решать «навсегда». +-- +-- Правку НЕ следует читать как одобрение текущего ключа/победителя/гео-стража. Она к ним +-- НЕЙТРАЛЬНА: ни ключ, ни правило выбора победителя, ни гео-страж здесь не меняются. +-- Меняется только одно — теперь есть что откатить. +-- +-- WHAT (одна строка = один проигравший дом): +-- merge_pass / cluster_key / geo_guard / distance_m — ОСНОВАНИЕ слияния. Это не косметика: +-- ровно этих полей не хватило в #2690, чтобы ответить на вопрос «сколько слияний прошло +-- на расстояниях, которые гео-страж заблокировал бы» по ДАННЫМ, а не по ревью. distance_m +-- пишется всегда, даже когда страж для прохода выключен (fias-проход) — тогда он и есть +-- единственная запись о том, насколько далеко разъехались объединённые дома. +-- loser_row — ПОЛНЫЙ jsonb-снимок удаляемой строки (`to_jsonb(h.*)`, все 86 колонок). +-- Ссылка на удалённую строку бесполезна, поэтому хранится содержимое. Снимок целиком, +-- а не список полей: проверено, что `jsonb_populate_record(NULL::houses, loser_row)` +-- восстанавливает строку побайтово, включая PostGIS-geom (to_jsonb отдаёт её GeoJSON'ом, +-- populate_record разбирает обратно входной функцией типа). Побочная выгода: новая +-- колонка в `houses` попадает в снимок и в откат САМА, без правки этой миграции. +-- keeper_before — снимок ПОБЕДИТЕЛЯ до переноса метаданных. Нужен, потому что слияние не +-- только удаляет проигравшего: `_CARRY_OVER_IDENTITY_SQL` дозаполняет победителю NULL-поля +-- идентичности (fias/кадастр/ГАР/DaData) значениями проигравшего. Без этого снимка откат +-- вернул бы дом, но оставил бы его ФИАС на победителе — и следующий же fias-проход слил +-- бы их обратно. +-- children_repointed — {"таблица.колонка": [id, ...]}. Дочерние строки ПЕРЕЖИЛИ слияние, +-- у них сменилась только ссылка, поэтому хранятся id, а не содержимое (иначе одни +-- listings с их raw-payload'ом дали бы ~7 КБ на строку вместо ~8 байт на id). +-- children_deleted — {"таблица": [{строка целиком}, ...]}. Дочерние строки, которые проход +-- УДАЛИЛ из-за коллизии по UNIQUE. Их содержимое уничтожено, id недостаточно — только +-- полный снимок. Таких таблиц шесть (см. _STEPS), строки мелкие. +-- batch_id — один вызов merge_duplicate_houses() (оба прохода). Единица отката. +-- run_id / initiator — кто инициировал: scrape_runs.id для расписания, NULL для ручного. +-- +-- НАМЕРЕННО БЕЗ ВНЕШНИХ КЛЮЧЕЙ на houses(id) и scrape_runs(id): +-- журнал обязан ПЕРЕЖИВАТЬ строки, которые описывает. loser_id указывает на заведомо +-- удалённый дом. keeper_id — на дом, который сам может быть слит следующим прогоном; FK +-- с CASCADE стёр бы историю ровно тогда, когда она нужнее всего, а FK без CASCADE +-- заблокировал бы слияние. То же с run_id: чистка scrape_runs не должна трогать журнал. +-- +-- ОБЪЁМ (замерено на проде 2026-08-06): +-- 9 571 дом, средняя строка houses в jsonb 2 581 Б. Строка журнала ≈ loser_row 2.5 КБ + +-- keeper_before 2.5 КБ + списки id (в среднем 27.9 дочерних строк на дом × ~8 Б) ≈ 5.3 КБ. +-- Наблюдаемый темп — 20 слияний в неделю (119 за 6 прогонов) ≈ 106 КБ/нед ≈ 5.5 МБ/год. +-- Ближайший прогон (замер тем же выражением, что и код): 93 проигравших ≈ 0.5 МБ. +-- Абсолютный потолок, если схлопнуть вообще все дома: 9 571 × 5.3 КБ ≈ 50 МБ против 23 МБ +-- самой таблицы houses. +-- +-- RETENTION: НЕ НУЖЕН, сознательно. Потолок роста — двузначные мегабайты, то есть дешевле +-- любой процедуры чистки; а журнал слияний — это ровно то, что удалять не хочется: его +-- ценность в том, что он отвечает на вопрос «что было год назад», когда логов давно нет. +-- Если объём когда-нибудь станет проблемой, удалять надо не строки, а тяжёлые снимки +-- (loser_row/keeper_before → NULL) у записей старше N лет, сохранив соответствие +-- loser→keeper: оно весит байты и именно оно нужно дольше всего. +-- +-- Dependencies: 002_core_tables.sql (houses), 135_scrape_schedules_seed_house_dedup_merge.sql +-- Пишется в ТОЙ ЖЕ транзакции, что и слияние (см. house_dedup_merge._run_merge_pass) — +-- разрыв «слияние прошло, запись не легла» невозможен по построению; dry_run откатывает и то, +-- и другое вместе. + +BEGIN; + +CREATE TABLE IF NOT EXISTS house_merge_log ( + id bigserial PRIMARY KEY, + merged_at timestamptz NOT NULL DEFAULT now(), + batch_id uuid NOT NULL, + run_id bigint, + initiator text NOT NULL, + merge_pass text NOT NULL, + cluster_key text NOT NULL, + geo_guard boolean NOT NULL, + distance_m double precision, + norm_address text, + loser_id bigint NOT NULL, + keeper_id bigint NOT NULL, + loser_row jsonb NOT NULL, + keeper_before jsonb NOT NULL, + children_repointed jsonb NOT NULL DEFAULT '{}'::jsonb, + children_deleted jsonb NOT NULL DEFAULT '{}'::jsonb +); + +CREATE INDEX IF NOT EXISTS idx_house_merge_log_loser ON house_merge_log (loser_id); +CREATE INDEX IF NOT EXISTS idx_house_merge_log_keeper ON house_merge_log (keeper_id); +CREATE INDEX IF NOT EXISTS idx_house_merge_log_batch ON house_merge_log (batch_id); + +COMMENT ON TABLE house_merge_log IS + 'Журнал слияний домов (#2690): одна строка = один проигравший дом, удалённый проходом ' + 'house_dedup_merge. Пишется в ТОЙ ЖЕ транзакции, что и слияние. Содержит полный снимок ' + 'удалённой строки и перечень перенесённых/удалённых дочерних строк — достаточно, чтобы ' + 'назвать поимённо, что во что свернули, и вернуть обратно (house_merge_undo). Намеренно ' + 'БЕЗ FK на houses/scrape_runs: журнал переживает строки, которые описывает. Retention нет.'; + +COMMENT ON COLUMN house_merge_log.cluster_key IS + 'ЗНАЧЕНИЕ ключа, по которому дома попали в один кластер («addr:вайнера66» / «fias:»), ' + 'а не имя ключа — по нему видно, какое именно совпадение сработало.'; +COMMENT ON COLUMN house_merge_log.geo_guard IS + 'Был ли для этого прохода включён гео-страж 250 м. false = слияние разрешено БЕЗ проверки ' + 'близости; вместе с distance_m это и есть аудит основания (#2690).'; +COMMENT ON COLUMN house_merge_log.distance_m IS + 'ST_DistanceSphere между победителем и проигравшим на момент слияния; NULL = у одной из ' + 'сторон не было geom. Пишется ВСЕГДА, в том числе когда гео-страж выключен.'; +COMMENT ON COLUMN house_merge_log.loser_row IS + 'to_jsonb() удалённой строки houses целиком. Восстановление: ' + 'INSERT INTO houses SELECT r.* FROM jsonb_populate_record(NULL::houses, loser_row) r.'; +COMMENT ON COLUMN house_merge_log.keeper_before IS + 'Снимок победителя ДО переноса метаданных с проигравшего (COALESCE-дозаполнение полей ' + 'идентичности). Без него откат вернул бы дом, но оставил его ФИАС/кадастр на победителе.'; +COMMENT ON COLUMN house_merge_log.children_repointed IS + '{"таблица.колонка": [id, ...]} — дочерние строки, у которых слияние сменило ссылку ' + 'loser→keeper. Строки целы, поэтому хранятся id: откат возвращает ссылку обратно.'; +COMMENT ON COLUMN house_merge_log.children_deleted IS + '{"таблица": [{строка целиком}, ...]} — дочерние строки, УДАЛЁННЫЕ проходом из-за коллизии ' + 'по UNIQUE с победителем. Содержимое уничтожено, поэтому хранится снимок, а не id.'; + +-- ── Обратная операция ──────────────────────────────────────────────────────── +-- +-- Откат одного батча (или его части) по журналу. Транзакционен: вызывающий сам решает +-- COMMIT/ROLLBACK, увидев отчёт. Возвращает СТРОКУ НА КАЖДУЮ запись журнала со статусом — +-- в том числе «не смог», потому что молчаливо-успешный откат хуже отсутствующего. +-- +-- Порядок внутри одной записи важен: сначала воскресить дом (на него ссылаются дети), потом +-- вернуть ссылки детей, потом вернуть удалённых детей, потом снять перенос метаданных с +-- победителя. Записи батча обходятся в обратном порядке (id DESC) — если дом A слили в B, +-- а B потом в C, разматывать надо с конца. +-- +-- ИЗВЕСТНЫЕ ГРАНИЦЫ (сознательные, отражены в статусе): +-- * дочерняя строка, удалённая по коллизии, может не вернуться: место в UNIQUE-ключе занято +-- строкой победителя. ON CONFLICT DO NOTHING + счётчик в статусе, а не тихая потеря; +-- * backfill-строки house_sources/house_address_aliases, которые проход дописал победителю, +-- НЕ удаляются: они собраны из собственных полей победителя и остались бы верны и без +-- слияния; +-- * если id проигравшего уже занят — запись пропускается со статусом, откат не гадает. +CREATE OR REPLACE FUNCTION house_merge_undo( + p_batch uuid, + p_only_losers bigint[] DEFAULT NULL +) +RETURNS TABLE ( + out_log_id bigint, + out_loser_id bigint, + out_keeper_id bigint, + out_status text +) +LANGUAGE plpgsql +AS $$ +DECLARE + rec record; + v_table text; + v_column text; + v_ids bigint[]; + v_rows jsonb; + v_field text; + v_repointed int; + v_restored int; + v_lost int; + v_n int; + -- Список полей ДОЛЖЕН совпадать с SET в house_dedup_merge._CARRY_OVER_IDENTITY_SQL; + -- за расхождением следит тест test_undo_carryover_fields_match_merge_carryover. + c_carry_fields constant text[] := ARRAY[ + 'house_fias_id', 'cadastral_number', 'gar_house_guid', 'gar_flat_count', + 'gar_matched_at', 'gar_match_method', 'dadata_qc_geo', 'dadata_qc_house', + 'dadata_enriched_at' + ]; +BEGIN + FOR rec IN + SELECT * + FROM house_merge_log l + WHERE l.batch_id = p_batch + AND (p_only_losers IS NULL OR l.loser_id = ANY (p_only_losers)) + ORDER BY l.id DESC + LOOP + out_log_id := rec.id; + out_loser_id := rec.loser_id; + out_keeper_id := rec.keeper_id; + + IF EXISTS (SELECT 1 FROM houses h WHERE h.id = rec.loser_id) THEN + out_status := 'skipped: houses.id ' || rec.loser_id || ' занят — уже откачено?'; + RETURN NEXT; + CONTINUE; + END IF; + + -- 1. Воскресить проигравшего целиком из снимка (все колонки, включая geom). + INSERT INTO houses + SELECT r.* FROM jsonb_populate_record(NULL::houses, rec.loser_row) r; + + -- 2. Вернуть ссылки уцелевших детей. Условие «сейчас указывает на победителя» + -- защищает от затирания строк, которые после слияния перепривязали чем-то ещё. + v_repointed := 0; + FOR v_table, v_column, v_ids IN + SELECT split_part(e.key, '.', 1), + split_part(e.key, '.', 2), + ARRAY(SELECT jsonb_array_elements_text(e.value)::bigint) + FROM jsonb_each(rec.children_repointed) AS e + LOOP + EXECUTE format( + 'UPDATE %I SET %I = $1 WHERE id = ANY ($2) AND %I = $3', + v_table, v_column, v_column + ) USING rec.loser_id, v_ids, rec.keeper_id; + GET DIAGNOSTICS v_n = ROW_COUNT; + v_repointed := v_repointed + v_n; + END LOOP; + + -- 3. Вернуть детей, удалённых по коллизии UNIQUE. Место могло остаться занятым + -- строкой победителя — тогда DO NOTHING, и это попадёт в отчёт как «не вернулось». + v_restored := 0; + v_lost := 0; + FOR v_table, v_rows IN + SELECT e.key, e.value FROM jsonb_each(rec.children_deleted) AS e + LOOP + EXECUTE format( + 'INSERT INTO %I SELECT r.* FROM jsonb_array_elements($1) AS el, ' + 'LATERAL jsonb_populate_record(NULL::%I, el) r ON CONFLICT DO NOTHING', + v_table, v_table + ) USING v_rows; + GET DIAGNOSTICS v_n = ROW_COUNT; + v_restored := v_restored + v_n; + v_lost := v_lost + (jsonb_array_length(v_rows) - v_n); + END LOOP; + + -- 4. Снять перенос метаданных с победителя. Только там, где до слияния было NULL И + -- текущее значение всё ещё РОВНО то, что принёс этот проигравший: если поле успел + -- заполнить загрузчик (или донором был другой проигравший кластера) — не трогаем. + -- Сравнение в jsonb-пространстве, чтобы один цикл покрыл text/int/timestamptz. + FOREACH v_field IN ARRAY c_carry_fields LOOP + IF rec.keeper_before ->> v_field IS NULL THEN + EXECUTE format( + 'UPDATE houses SET %I = NULL WHERE id = $1 AND to_jsonb(%I) = $2', + v_field, v_field + ) USING rec.keeper_id, rec.loser_row -> v_field; + END IF; + END LOOP; + + out_status := format( + 'restored: дом %s вернулся, ссылок возвращено %s, дочерних строк восстановлено %s' + || CASE WHEN v_lost > 0 THEN ', НЕ ВЕРНУЛОСЬ ' || v_lost || ' (место занято)' + ELSE '' END, + rec.loser_id, v_repointed, v_restored + ); + RETURN NEXT; + END LOOP; +END; +$$; + +COMMENT ON FUNCTION house_merge_undo(uuid, bigint[]) IS + 'Откат слияния домов по журналу house_merge_log (#2690). Аргументы: batch_id (единица ' + 'отката = один вызов merge_duplicate_houses) и опциональный список loser_id для частичного ' + 'отката. Возвращает строку-статус на КАЖДУЮ запись журнала, включая неудачные. ' + 'Транзакции не открывает и не закрывает — вызывающий смотрит отчёт и решает COMMIT/ROLLBACK: ' + ' BEGIN; SELECT * FROM house_merge_undo(''''); -- прочитать статусы -- COMMIT;'; + +COMMIT; diff --git a/tradein-mvp/backend/tests/test_house_dedup_merge.py b/tradein-mvp/backend/tests/test_house_dedup_merge.py index ef6494e0..63db7822 100644 --- a/tradein-mvp/backend/tests/test_house_dedup_merge.py +++ b/tradein-mvp/backend/tests/test_house_dedup_merge.py @@ -284,9 +284,18 @@ def test_fias_pass_drops_geo_guard_canon_pass_keeps_it() -> None: assert "keeper_geom IS NOT NULL" in canon assert "loser_geom IS NOT NULL" in canon # fias pass drops the distance guard AND the NULL-geom exclusions entirely. - assert "ST_DistanceSphere" not in fias - assert "loser_geom IS NOT NULL" not in fias - assert "keeper_geom IS NOT NULL" not in fias + # + # Asserted on the guard PREDICATE, not on the bare function name: since #2690 the mapping also + # MEASURES the keeper↔loser distance into `distance_m` for the merge journal, on both passes. + # Measuring is the opposite of guarding — the fias pass is precisely where nothing else records + # how far apart the merged rows were — so the name alone can no longer stand in for the guard. + assert "ST_DistanceSphere(loser_geom, keeper_geom) <= 250" not in fias + guard = ( + "AND keeper_geom IS NOT NULL AND loser_geom IS NOT NULL " + "AND ST_DistanceSphere(loser_geom, keeper_geom) <= 250" + ) + assert guard in canon + assert guard not in fias # the cross-fias anti-over-merge guard is untouched in the canon pass. assert "lower(loser_fias) <> lower(keeper_fias)" in canon @@ -294,12 +303,15 @@ def test_fias_pass_drops_geo_guard_canon_pass_keeps_it() -> None: def test_mapping_sql_geo_guard_param_toggles_only_distance_filter() -> None: """_mapping_sql(apply_geo_guard=...) toggles ONLY the 250 m distance filter; the cross-fias guard is emitted regardless, and the default is True (canon-safe).""" + guard = "ST_DistanceSphere(loser_geom, keeper_geom) <= 250" with_guard = _flat(hdm._mapping_sql(hdm._CANON_KEY_EXPR, apply_geo_guard=True)) without_guard = _flat(hdm._mapping_sql(hdm._CANON_KEY_EXPR, apply_geo_guard=False)) - assert "ST_DistanceSphere" in with_guard - assert "ST_DistanceSphere" not in without_guard + assert guard in with_guard + assert guard not in without_guard # default = True (the canon pass must never lose its guard by omission). - assert "ST_DistanceSphere" in _flat(hdm._mapping_sql(hdm._CANON_KEY_EXPR)) + assert guard in _flat(hdm._mapping_sql(hdm._CANON_KEY_EXPR)) + # ...while the journal's distance MEASUREMENT is emitted either way (#2690). + assert "AS distance_m" in with_guard and "AS distance_m" in without_guard # cross-fias guard present in BOTH renderings (independent of the geo guard). assert "lower(loser_fias) <> lower(keeper_fias)" in with_guard assert "lower(loser_fias) <> lower(keeper_fias)" in without_guard @@ -327,7 +339,9 @@ def test_both_passes_share_one_pipeline_no_copy_paste() -> None: assert token in canon and token in fias # the 250 m distance guard is CANON-ONLY (#2187) — fias identity outranks proximity. assert "ST_DistanceSphere(loser_geom, keeper_geom) <= 250" in canon - assert "ST_DistanceSphere" not in fias + assert "ST_DistanceSphere(loser_geom, keeper_geom) <= 250" not in fias + # ...but the journal's distance MEASUREMENT is on both — measuring is not guarding. + assert "AS distance_m" in canon and "AS distance_m" in fias def test_cross_fias_guard_blocks_slash_collapse_over_merge() -> None: @@ -433,28 +447,62 @@ class _FakeResult: class _Row: - def __init__(self, loser_id: int, keeper_id: int, norm_address: str): + def __init__( + self, + loser_id: int, + keeper_id: int, + norm_address: str, + cluster_key: str = "addr:тест", + distance_m: float | None = 12.0, + ): self.loser_id = loser_id self.keeper_id = keeper_id self.norm_address = norm_address + # journal grounds (#2690): which key value fired, and how far apart the rows were. + self.cluster_key = cluster_key + self.distance_m = distance_m + + +class _ChildRow: + """What a step's RETURNING yields: an id for a survivor, a snapshot for a destroyed row.""" + + def __init__(self, loser_id: int, child_id: int = 1): + self.loser_id = loser_id + self.child_id = child_id + self.row_snapshot = {"id": child_id, "house_id": loser_id} + + +class _FKChild: + def __init__(self, child_table: str, fk_column: str): + self.child_table = child_table + self.fk_column = fk_column class _FakeDB: """Session stand-in: build-mapping + a scripted SELECT result, then per-step rowcounts.""" - def __init__(self, mapping_rows: list[_Row], step_rowcount: int = 1): + def __init__( + self, + mapping_rows: list[_Row], + step_rowcount: int = 1, + fk_children: dict[str, str] | None = None, + ): self._mapping_rows = mapping_rows self._step_rowcount = step_rowcount self._mapping_served = False + # The catalog the FK-child guard reads; defaults to the real live set. + self._fk_children = _FK_CHILDREN if fk_children is None else fk_children self.commits = 0 self.rollbacks = 0 self.executed: list[str] = [] - def execute(self, clause: Any, params: dict | None = None) -> _FakeResult: + def execute(self, clause: Any, params: Any = None) -> _FakeResult: sql = str(getattr(clause, "text", clause)) self.executed.append(sql) if "CREATE TEMP TABLE" in sql: return _FakeResult() + if "FROM pg_constraint" in sql: + return _FakeResult(rows=[_FKChild(t, c) for t, c in self._fk_children.items()]) if "SELECT loser_id, keeper_id, norm_address" in sql: # The service now runs TWO passes (fias, then canon). Model «fias pass found the # duplicates, canon pass is clean»: serve the scripted mapping once, empty afterwards. @@ -462,7 +510,13 @@ class _FakeDB: return _FakeResult(rows=[]) self._mapping_served = True return _FakeResult(rows=list(self._mapping_rows)) - # any UPDATE/DELETE/INSERT step (incl. DROP TABLE, carry-over, delete, backfill) + # Steps now RETURN the rows they touched (journal, #2690) — one per scripted rowcount, + # attributed to the first loser so the per-loser bookkeeping has something to bucket. + if "RETURNING" in sql: + loser = self._mapping_rows[0].loser_id if self._mapping_rows else 0 + rows = [_ChildRow(loser, child_id=i + 1) for i in range(self._step_rowcount)] + return _FakeResult(rowcount=self._step_rowcount, rows=rows) + # any other UPDATE/DELETE/INSERT (DROP TABLE, journal, carry-over, delete, backfill) return _FakeResult(rowcount=self._step_rowcount) def commit(self) -> None: @@ -524,7 +578,11 @@ def test_run_wrapper_marks_done_with_counters(monkeypatch: pytest.MonkeyPatch) - monkeypatch.setattr( hdm, "merge_duplicate_houses", - lambda _db, dry_run=False: {"clusters_merged": 3, "losers_deleted": 5, "dry_run": 0}, + lambda _db, dry_run=False, run_id=None, initiator="manual": { + "clusters_merged": 3, + "losers_deleted": 5, + "dry_run": 0, + }, ) out = hdm.run_house_dedup_merge(object(), run_id=42, params={"dry_run": False}) # type: ignore[arg-type] @@ -541,13 +599,20 @@ def test_run_wrapper_passes_dry_run_param(monkeypatch: pytest.MonkeyPatch) -> No monkeypatch.setattr(runs_mod, "mark_done", lambda *a, **k: None) monkeypatch.setattr(runs_mod, "mark_failed", lambda *a, **k: None) - def _fake_merge(_db: Any, dry_run: bool = False) -> dict[str, int]: + def _fake_merge( + _db: Any, dry_run: bool = False, run_id: int | None = None, initiator: str = "manual" + ) -> dict[str, int]: captured["dry_run"] = dry_run + captured["run_id"] = run_id + captured["initiator"] = initiator return {"dry_run": int(dry_run)} monkeypatch.setattr(hdm, "merge_duplicate_houses", _fake_merge) hdm.run_house_dedup_merge(object(), run_id=1, params={"dry_run": True}) # type: ignore[arg-type] assert captured["dry_run"] is True + # the journal must be able to say WHICH run did it, and that it was not a human (#2690) + assert captured["run_id"] == 1 + assert captured["initiator"] == "schedule" def test_run_wrapper_marks_failed_on_error(monkeypatch: pytest.MonkeyPatch) -> None: @@ -562,7 +627,9 @@ def test_run_wrapper_marks_failed_on_error(monkeypatch: pytest.MonkeyPatch) -> N lambda _db, run_id, err, counters: failed.update(run_id=run_id, err=err), ) - def _boom(_db: Any, dry_run: bool = False) -> dict[str, int]: + def _boom( + _db: Any, dry_run: bool = False, run_id: int | None = None, initiator: str = "manual" + ) -> dict[str, int]: raise RuntimeError("merge exploded") monkeypatch.setattr(hdm, "merge_duplicate_houses", _boom) @@ -642,12 +709,16 @@ def test_real_merge_repoints_dedups_deletes_and_is_idempotent() -> None: db = _live_session() assert db is not None try: - # Two houses at the SAME address. Keeper (geom present) should win. + # Two houses at the SAME address, ~10 m apart (the #2187 canon geo guard needs geom + # on BOTH sides). Keeper = min(id) once geom and listing counts tie. db.execute( _t( - "INSERT INTO houses (id, source, ext_house_id, address, lat, lon) VALUES " - "(900001, 'avito', 'EXT-KEEP', 'тестдом 1772, 1', 56.84, 60.60)," - "(900002, 'cian', 'EXT-LOSE', 'тестдом 1772, 1', NULL, NULL)" + # url is NOT NULL in houses (002_core_tables); nothing here asserts on it, + # so 'u' is a placeholder. These live-DB fixtures self-skip in CI, which is + # how they silently drifted out of sync with the schema in the first place. + "INSERT INTO houses (id, source, ext_house_id, url, address, lat, lon) VALUES " + "(900001, 'avito', 'EXT-KEEP','u', 'тестдом 1772, 1', 56.84, 60.60)," + "(900002, 'cian', 'EXT-LOSE','u', 'тестдом 1772, 1', 56.84009, 60.60)" ) ) # listings pointing at BOTH (the loser's must be re-pointed). source_url, dedup_hash, @@ -755,6 +826,9 @@ def test_real_merge_repoints_dedups_deletes_and_is_idempotent() -> None: db.execute( _t("DELETE FROM house_address_aliases WHERE normalized_address = 'тестдом 1772, 1'") ) + # journal rows have no FK and are never cascaded away — sweep them explicitly, + # or a re-run accumulates them (all live fixtures live in the 9000xx id range). + db.execute(_t("DELETE FROM house_merge_log WHERE loser_id BETWEEN 900000 AND 900299")) db.execute(_t("DELETE FROM houses WHERE id IN (900001,900002)")) db.commit() db.close() @@ -781,16 +855,16 @@ def test_real_canon_clusterkey_and_geo_guard_merge_semantics() -> None: try: db.execute( _t( - "INSERT INTO houses (id, source, ext_house_id, address, lat, lon) VALUES " + "INSERT INTO houses (id, source, ext_house_id, url, address, lat, lon) VALUES " # A — ул/улица spelling variants of the SAME building, ~10 m apart → MERGE - "(900010, 'avito', 'EXT-T-VK', 'улица Тестовая1772, 66', 56.84000, 60.60000)," - "(900011, 'cian', 'EXT-T-VL', 'ул. Тестовая1772, 66', 56.84009, 60.60000)," + "(900010, 'avito', 'EXT-T-VK','u', 'улица Тестовая1772, 66', 56.84000, 60.60000)," + "(900011, 'cian', 'EXT-T-VL','u', 'ул. Тестовая1772, 66', 56.84009, 60.60000)," # B — same canon (ленина-like) but ~5 km apart → geo guard BLOCKS the merge - "(900012, 'avito', 'EXT-T-L1', 'улица Тестовая1772, 5', 56.84000, 60.60000)," - "(900013, 'cian', 'EXT-T-L2', 'улица Тестовая1772, 5', 56.88500, 60.60000)," + "(900012, 'avito', 'EXT-T-L1','u', 'улица Тестовая1772, 5', 56.84000, 60.60000)," + "(900013, 'cian', 'EXT-T-L2','u', 'улица Тестовая1772, 5', 56.88500, 60.60000)," # C — different корпус → different canon, ~10 m apart → NOT merged - "(900014, 'avito', 'EXT-T-M2', 'Тестовая1772, 34к2', 56.84000, 60.60000)," - "(900015, 'cian', 'EXT-T-M4', 'Тестовая1772, 34к4', 56.84009, 60.60000)" + "(900014, 'avito', 'EXT-T-M2','u', 'Тестовая1772, 34к2', 56.84000, 60.60000)," + "(900015, 'cian', 'EXT-T-M4','u', 'Тестовая1772, 34к4', 56.84009, 60.60000)" ) ) db.execute( @@ -840,7 +914,7 @@ def test_real_canon_clusterkey_and_geo_guard_merge_semantics() -> None: db.execute( _t( "DELETE FROM house_sources WHERE ext_id IN " - "('EXT-T-VK','EXT-T-VL','EXT-T-L1','EXT-T-L2','EXT-T-M2','EXT-T-M4')" + "('EXT-T-VK','u','EXT-T-VL','u','EXT-T-L1','u','EXT-T-L2','u','EXT-T-M2','u','EXT-T-M4')" ) ) db.execute( @@ -850,6 +924,9 @@ def test_real_canon_clusterkey_and_geo_guard_merge_semantics() -> None: "'тестовая1772, 34к2','тестовая1772, 34к4')" ) ) + # journal rows have no FK and are never cascaded away — sweep them explicitly, + # or a re-run accumulates them (all live fixtures live in the 9000xx id range). + db.execute(_t("DELETE FROM house_merge_log WHERE loser_id BETWEEN 900000 AND 900299")) db.execute(_t("DELETE FROM houses WHERE id BETWEEN 900010 AND 900015")) db.commit() db.close() @@ -877,21 +954,21 @@ def test_real_fias_pass_cross_guard_and_identity_carryover() -> None: db.execute( _t( "INSERT INTO houses " - "(id, source, ext_house_id, address, lat, lon, house_fias_id, gar_house_guid, " + "(id, source, ext_house_id, url, address, lat, lon, house_fias_id, gar_house_guid, " " dadata_enriched_at) VALUES " # A — same fias, different canon (different streets), ~10 m apart → FIAS-pass merge - "(900020,'avito','EXT-F-K','ФиасОдин1772, 10', 56.84000,60.60000," + "(900020,'avito','EXT-F-K','u','ФиасОдин1772, 10', 56.84000,60.60000," " 'F-SAME-1772',NULL,NULL)," - "(900021,'cian', 'EXT-F-L','СовсемДругая1772, 77',56.84009,60.60000," + "(900021,'cian', 'EXT-F-L','u','СовсемДругая1772, 77',56.84009,60.60000," " 'F-SAME-1772',NULL,NULL)," # B — same canon (slash-collapse), DIFFERENT fias → cross-fias guard BLOCKS - "(900022,'avito','EXT-B-1','Клара1772, 32',56.84000,60.60000," + "(900022,'avito','EXT-B-1','u','Клара1772, 32',56.84000,60.60000," " 'F-B1-1772',NULL,NULL)," - "(900023,'cian', 'EXT-B-2','Клара1772, 3/2',56.84009,60.60000," + "(900023,'cian', 'EXT-B-2','u','Клара1772, 3/2',56.84009,60.60000," " 'F-B2-1772',NULL,NULL)," # C — same canon, fias only on the loser → canon-pass merge + carry-over - "(900024,'avito','EXT-C-K','Донбасс1772, 8',56.84000,60.60000,NULL,NULL,NULL)," - "(900025,'cian', 'EXT-C-L','Донбасс1772, 8',56.84009,60.60000," + "(900024,'avito','EXT-C-K','u','Донбасс1772, 8',56.84000,60.60000,NULL,NULL,NULL)," + "(900025,'cian', 'EXT-C-L','u','Донбасс1772, 8',56.84009,60.60000," " 'F-CARRY-1772','G-CARRY-1772',NOW())" ) ) @@ -944,7 +1021,7 @@ def test_real_fias_pass_cross_guard_and_identity_carryover() -> None: db.execute( _t( "DELETE FROM house_sources WHERE ext_id IN " - "('EXT-F-K','EXT-F-L','EXT-B-1','EXT-B-2','EXT-C-K','EXT-C-L')" + "('EXT-F-K','u','EXT-F-L','u','EXT-B-1','u','EXT-B-2','u','EXT-C-K','u','EXT-C-L')" ) ) db.execute( @@ -954,6 +1031,9 @@ def test_real_fias_pass_cross_guard_and_identity_carryover() -> None: "'донбасс1772, 8')" ) ) + # journal rows have no FK and are never cascaded away — sweep them explicitly, + # or a re-run accumulates them (all live fixtures live in the 9000xx id range). + db.execute(_t("DELETE FROM house_merge_log WHERE loser_id BETWEEN 900000 AND 900299")) db.execute(_t("DELETE FROM houses WHERE id BETWEEN 900020 AND 900025")) db.commit() db.close() @@ -982,16 +1062,16 @@ def test_real_fias_pass_ignores_geo_guard() -> None: db.execute( _t( "INSERT INTO houses " - "(id, source, ext_house_id, address, lat, lon, house_fias_id) VALUES " + "(id, source, ext_house_id, url, address, lat, lon, house_fias_id) VALUES " # A — same fias, loser NULL geom → fias pass merges despite the missing coordinate - "(900030,'avito','EXT-2187-A-K','ФиасГеоA2187, 1', 56.84000,60.60000,'F-A-2187')," - "(900031,'cian', 'EXT-2187-A-L','ФиасГеоAL2187, 2',NULL, NULL, 'F-A-2187')," + "(900030,'avito','EXT-2187-A-K','u','ФиасГеоA2187, 1',56.84,60.6,'F-A-2187')," + "(900031,'cian', 'EXT-2187-A-L','u','ФиасГеоAL2187, 2',NULL,NULL,'F-A-2187')," # B — same fias, ~5 km apart (>250 m) → fias pass merges despite the distance - "(900032,'avito','EXT-2187-B-K','ФиасГеоB2187, 3', 56.84000,60.60000,'F-B-2187')," - "(900033,'cian', 'EXT-2187-B-L','ФиасГеоBL2187, 4',56.88500,60.60000,'F-B-2187')," + "(900032,'avito','EXT-2187-B-K','u','ФиасГеоB2187, 3',56.84,60.6,'F-B-2187')," + "(900033,'cian', 'EXT-2187-B-L','u','ФиасГеоBL2187, 4',56.885,60.6,'F-B-2187')," # C — same canon, NO fias, ~5 km apart → canon pass STILL blocks (guard unchanged) - "(900034,'avito','EXT-2187-C-1','КанонГео2187, 5', 56.84000,60.60000,NULL)," - "(900035,'cian', 'EXT-2187-C-2','КанонГео2187, 5', 56.88500,60.60000,NULL)" + "(900034,'avito','EXT-2187-C-1','u','КанонГео2187, 5', 56.84000,60.60000,NULL)," + "(900035,'cian', 'EXT-2187-C-2','u','КанонГео2187, 5', 56.88500,60.60000,NULL)" ) ) # A loser gets a listing so we prove the re-point still fires with a NULL-geom loser. @@ -1028,6 +1108,199 @@ def test_real_fias_pass_ignores_geo_guard() -> None: db.execute(_t("DELETE FROM listings WHERE id = 910031")) db.execute(_t("DELETE FROM house_sources WHERE house_id BETWEEN 900030 AND 900035")) db.execute(_t("DELETE FROM house_address_aliases WHERE house_id BETWEEN 900030 AND 900035")) + # journal rows have no FK and are never cascaded away — sweep them explicitly, + # or a re-run accumulates them (all live fixtures live in the 9000xx id range). + db.execute(_t("DELETE FROM house_merge_log WHERE loser_id BETWEEN 900000 AND 900299")) db.execute(_t("DELETE FROM houses WHERE id BETWEEN 900030 AND 900035")) db.commit() db.close() + + +# ── Merge journal: reversibility (#2690) ────────────────────────────────────── + + +def test_undo_carryover_fields_match_merge_carryover() -> None: + """Static drift guard: migration 230's undo must un-set EXACTLY the fields the merge carries. + + The undo NULLs the keeper's identity fields that the merge COALESCE-filled from a loser. + If _CARRY_OVER_IDENTITY_SQL ever gains a field and the migration's array does not, the undo + silently leaves that field on the keeper — the restored loser and the keeper would then both + claim the same ФИАС, and the next fias pass would merge them straight back. + """ + migration = (_SQL_DIR / "230_house_merge_log.sql").read_text(encoding="utf-8") + carried = set(re.findall(r"^\s+(\w+)\s*=\s*COALESCE\(k\.", _CARRY_SQL, re.M)) + # slice the ARRAY[...] literal itself — the declaration's own `text[]` also holds a «]» + block = migration[migration.index("c_carry_fields") :] + undone = set(re.findall(r"'(\w+)'", block[block.index("ARRAY[") : block.index("];")])) + assert carried, "could not parse carried fields out of _CARRY_OVER_IDENTITY_SQL" + assert carried == undone, f"carry-over/undo field drift: merge={carried} undo={undone}" + + +def test_journal_written_in_the_same_transaction_as_the_merge() -> None: + """The journal INSERT must sit between mapping and delete, with no commit in between. + + Requirement from #2690: a merge that commits without its journal row is exactly the failure + the journal exists to prevent, so the two must share one transaction. + """ + src = inspect.getsource(hdm._run_merge_pass) + assert "_JOURNAL_INSERT_SQL" in src + assert "db.commit()" not in src, "the pass must not commit — the caller owns the txn" + # phase 1 (snapshots) strictly before the steps mutate anything, delete strictly after. + assert src.index("_JOURNAL_INSERT_SQL") < src.index("for label, sql in _STEPS") + assert src.index("for label, sql in _STEPS") < src.index("_DELETE_LOSERS_SQL") + + +def test_every_step_returns_what_it_touched() -> None: + """Each step must RETURN its rows: ids for survivors, full snapshots for destroyed rows.""" + for label, sql in hdm._STEPS: + assert "RETURNING" in sql, f"{label}: no RETURNING — its rows would go unjournaled" + if label.endswith("(collision-delete)") or label.endswith("(dedup)"): + assert "to_jsonb(" in sql, f"{label}: destroys rows, must snapshot them, not ids" + else: + assert "AS child_id" in sql, f"{label}: re-points rows, must return their ids" + + +@pytest.mark.skipif(_live_session() is None, reason="no reachable Postgres test DB") +def test_real_merge_is_reversible_via_journal() -> None: + """End-to-end on a real DB: merge → journal is sufficient → undo restores the ORIGINAL state. + + The comparison is over `to_jsonb(row.*)` for every row that existed before the merge — all + columns, not a chosen pair — for houses and for every FK child touched. + """ + from sqlalchemy import text as _t + + db = _live_session() + assert db is not None + ids = "(900201, 900202)" + try: + # Keeper 900201 and loser 900202: same canon address, ~12 m apart (inside the 250 m + # guard), keeper has the listings so the keeper rule picks it. + db.execute( + _t( + "INSERT INTO houses (id, source, ext_house_id, url, address, lat, lon, geom, " + "year_built, house_fias_id, gar_flat_count, raw_payload) VALUES " + "(900201,'avito','K-2690','http://t/2690/k','улица Журнальная, 7', " + " 56.8400, 60.6000, ST_SetSRID(ST_MakePoint(60.6000,56.8400),4326), " + " 1979, NULL, NULL, '{\"k\":[1,2]}'), " + "(900202,'cian','L-2690','http://t/2690/l','ул. Журнальная,7', " + " 56.8401, 60.6000, ST_SetSRID(ST_MakePoint(60.6000,56.8401),4326), " + # NB: no «:word» inside the literal — SQLAlchemy text() would read it as a bind. + " NULL, 'fias-2690-uuid', 144, '{\"l\":{\"deep\":[3,4]}}')" + ) + ) + db.execute( + _t( + "INSERT INTO listings (id, source, source_url, source_id, dedup_hash, price_rub, " + "house_id_fk) VALUES " + "(910201,'avito','http://t/2690/1','L1','dh-2690-1',5000000,900201)," + "(910202,'avito','http://t/2690/2','L2','dh-2690-2',5100000,900201)," + "(910203,'cian','http://t/2690/3','L3','dh-2690-3',6000000,900202)" + ) + ) + db.execute( + _t( + "INSERT INTO house_sources (house_id, ext_source, ext_id, confidence, " + "matched_method) VALUES (900201,'avito','S-2690-K',1.0,'t')," + "(900202,'cian','S-2690-L',1.0,'t')" + ) + ) + # Colliding child: identical 6-col UNIQUE key on both → the loser's row is DESTROYED by + # the dedup step. Only a full snapshot can bring it back. + db.execute( + _t( + "INSERT INTO houses_price_dynamics (house_id, month_date, source, room_count, " + "prices_type, period, price_per_sqm) VALUES " + "(900201, DATE '2026-02-01','cian','all','priceSqm','allTime',100000)," + "(900202, DATE '2026-02-01','cian','all','priceSqm','allTime',999999)" + ) + ) + db.commit() + + def snapshot() -> dict[tuple[str, int], Any]: + """to_jsonb of every seeded row, keyed by (table, id) — the full-fidelity state.""" + out: dict[tuple[str, int], Any] = {} + for tbl, col in ( + ("houses", "id"), + ("listings", "house_id_fk"), + ("house_sources", "house_id"), + ("houses_price_dynamics", "house_id"), + ): + where = f"id IN {ids}" if tbl == "houses" else f"{col} IN {ids}" + for r in db.execute( + _t(f"SELECT id, to_jsonb(t.*) AS j FROM {tbl} t WHERE {where}") + ): + out[(tbl, r.id)] = r.j + return out + + before = snapshot() + assert len(before) == 9, f"fixture should seed 9 rows, got {sorted(before)}" + + # ── merge ── + out = hdm.merge_duplicate_houses(db, dry_run=False, initiator="test") + assert out["losers_deleted"] == 1 + assert db.execute(_t(f"SELECT count(*) FROM houses WHERE id IN {ids}")).scalar() == 1 + + # ── the journal alone must be able to NAME what went into what ── + row = db.execute( + _t("SELECT * FROM house_merge_log WHERE loser_id = 900202 ORDER BY id DESC LIMIT 1") + ).one() + assert (row.loser_id, row.keeper_id) == (900202, 900201) + assert row.merge_pass == "canon" and row.geo_guard is True + assert row.cluster_key.startswith("addr:") + assert 0 < row.distance_m < 250, "distance to the keeper must be recorded, in metres" + assert row.initiator == "test" + # full snapshot of the deleted row, not a reference to it + assert row.loser_row == before[("houses", 900202)] + # keeper as it stood BEFORE the identity carry-over (fias still empty there, filled now) + assert row.keeper_before["house_fias_id"] is None + assert ( + db.execute(_t("SELECT house_fias_id FROM houses WHERE id = 900201")).scalar() + == "fias-2690-uuid" + ), "carry-over should have moved the loser's fias up" + # children: the loser's listing moved by id, the destroyed price row by content + assert row.children_repointed["listings.house_id_fk"] == [910203] + assert [r["price_per_sqm"] for r in row.children_deleted["houses_price_dynamics"]] == [ + 999999 + ] + + # ── undo ── + report = db.execute( + _t("SELECT * FROM house_merge_undo(CAST(:b AS uuid))"), {"b": str(row.batch_id)} + ).all() + assert len(report) == 1 and report[0].out_status.startswith("restored:"), report + db.commit() + + after = snapshot() + # every row that existed before is back, byte-identical, on every column + assert {k: v for k, v in after.items() if k in before} == before + # the ONLY residue is the house_sources row the merge backfilled for the keeper. + # migration 230 documents this: it is built from the keeper's OWN ext_house_id, so + # it would have been true without the merge too. Asserted, not assumed. + residue = [v for k, v in after.items() if k not in before] + assert all(v["matched_method"] == "backfill_dedup_merge" for v in residue), residue + finally: + db.rollback() + db.execute(_t(f"DELETE FROM listings WHERE house_id_fk IN {ids}")) + db.execute(_t("DELETE FROM listings WHERE id IN (910201,910202,910203)")) + db.execute(_t("DELETE FROM house_merge_log WHERE loser_id = 900202")) + db.execute(_t("DELETE FROM house_address_aliases WHERE house_id IN (900201,900202)")) + db.execute(_t(f"DELETE FROM houses WHERE id IN {ids}")) + db.commit() + db.close() + + +def test_merge_refuses_when_an_fk_child_is_unhandled() -> None: + """A new FK child on houses(id) must ABORT the merge, not be CASCADE-deleted unjournaled. + + 9 of the 11 FKs are ON DELETE CASCADE. A child the _STEPS pipeline does not know about is + therefore destroyed by `DELETE FROM houses` — no re-point step touches it, no RETURNING + records it, and the journal would claim a complete snapshot it does not have. Migration 133 + already broke on prod over a missed child; there it failed loudly, here it would be silent. + """ + db = _FakeDB( + mapping_rows=[_Row(2, 1, "ул. ленина, 5")], + fk_children={**_FK_CHILDREN, "house_brand_new_child": "house_id"}, + ) + with pytest.raises(RuntimeError, match="house_brand_new_child"): + hdm.merge_duplicate_houses(db, dry_run=False) # type: ignore[arg-type] + assert db.commits == 0, "an unhandled child must abort before anything is committed"