diff --git a/tradein-mvp/backend/app/services/scheduler.py b/tradein-mvp/backend/app/services/scheduler.py index 7b42fd0e..5c483c1a 100644 --- a/tradein-mvp/backend/app/services/scheduler.py +++ b/tradein-mvp/backend/app/services/scheduler.py @@ -42,6 +42,7 @@ from scraper_kit.orchestration import runs as kit_runs # такта снова разъедется по одному из них. Re-export (а не правка импорта у вызывающих) # сохраняет `from app.services.scheduler import compute_next_run_at` в admin.py и тестах. from scraper_kit.orchestration.scheduler import compute_next_run_at +from scraper_kit.proxy_errors import caused_by_no_proxy from sqlalchemy import text from sqlalchemy.orm import Session @@ -126,8 +127,18 @@ async def _execute_cian_backfill( """Сигнал живости из середины батча. Best-effort: сбой heartbeat не должен ронять уже идущую работу — прогон в худшем случае вернётся к прежнему поведению (пометка 'zombie' на 6-м часу).""" + nonlocal counters + # #3384: снимок измеренного едет не только в БД, но и в `counters` — этот словарь + # уезжает в mark_failed из общего except ниже, а тот counters ЗАМЕНЯЕТ + # (scrape_runs.py:738 `counters = CAST(:counters AS jsonb)`; мерж `||` — только у + # kit-копии, которую этот путь не зовёт). Пока снимок сюда не доезжал, любой отказ + # ПОСЛЕ пройденной стадии (пул опустел между стадиями, упал SELECT домов) писал + # поверх измеренного предынициализированные нули, и SQL-разбор простоя + # (#3288/#3367) читал «к площадке не ходили» про прогон, который ходил. + # Присваивание ДО записи в БД: сбой heartbeat'а не должен стирать сам факт замера. + counters = _counters(progress) try: - runs_mod.update_heartbeat(db, run_id, _counters(progress)) + runs_mod.update_heartbeat(db, run_id, counters) except Exception: logger.warning( "scheduler: cian_history_backfill run_id=%d heartbeat failed (ignored)", @@ -135,6 +146,8 @@ async def _execute_cian_backfill( exc_info=True, ) + # Стартовые нули: прогон виден в админке до первого прогресса. Держатся здесь ровно + # до первого `_heartbeat` — дальше в `counters` лежит измеренное (см. выше). counters: dict[str, int] = { "listings_processed": 0, "listings_succeeded": 0, @@ -208,6 +221,17 @@ async def _execute_cian_backfill( ) except Exception as exc: logger.exception("scheduler: cian_history_backfill run_id=%d failed", run_id) + if caused_by_no_proxy(exc): + # #3384: пул был пуст ещё ДО первого объявления — lease берётся в + # BrowserFetcher.__aenter__, поэтому NoProxyAvailableError вылетает из + # самого `async with` (cian_history_backfill.py:218) мимо стоп-механики + # внутри цикла, которая и ставит no_proxy_stop. Без этого ключа прогон, + # который к площадке не ходил ВООБЩЕ, неотличим от любого другого падения: + # причина только в тексте, а разбор простоя идёт SQL'ём по + # counters.no_proxy_stop (#3288/#3367). Ключ тот же, что у ветки выше. + # Флаг ДОБАВЛЯЕТСЯ к последнему снимку `_heartbeat`, а не подменяет его: + # опустевший между стадиями пул — это отказ ПОСЛЕ реальной работы. + counters["no_proxy_stop"] = 1 runs_mod.mark_failed(db, run_id, str(exc)[:1000], counters) raise diff --git a/tradein-mvp/backend/app/tasks/avito_detail_backfill.py b/tradein-mvp/backend/app/tasks/avito_detail_backfill.py index cbd52c23..72f4ab24 100644 --- a/tradein-mvp/backend/app/tasks/avito_detail_backfill.py +++ b/tradein-mvp/backend/app/tasks/avito_detail_backfill.py @@ -1088,7 +1088,16 @@ async def run_avito_detail_backfill( run_id, counters.duration_sec, ) - runs_mod.mark_failed(db, run_id, str(exc)[:1000], counters.to_dict()) + current_counters = counters.to_dict() + if _caused_by_empty_pool(exc): + # #3384: пул был пуст ещё ДО первой карточки — lease берётся в + # BrowserFetcher.__aenter__ (строка 427), поэтому NoProxyAvailableError + # вылетает мимо стоп-механики цикла, которая и ставит no_proxy_stop. Без + # ключа такой прогон (attempted=0, к площадке не ходили) неотличим от + # любого другого падения: разбор простоя идёт SQL'ём по + # counters.no_proxy_stop (#3288/#3367), а не грепом текста ошибки. + current_counters["no_proxy_stop"] = 1 + runs_mod.mark_failed(db, run_id, str(exc)[:1000], current_counters) raise finally: diff --git a/tradein-mvp/backend/app/tasks/domclick_detail_backfill.py b/tradein-mvp/backend/app/tasks/domclick_detail_backfill.py index 4d35cd87..5f4c6963 100644 --- a/tradein-mvp/backend/app/tasks/domclick_detail_backfill.py +++ b/tradein-mvp/backend/app/tasks/domclick_detail_backfill.py @@ -642,5 +642,14 @@ async def run_domclick_detail_backfill( run_id, counters.duration_sec, ) - runs_mod.mark_failed(db, run_id, str(exc)[:1000], counters.to_dict()) + current_counters = counters.to_dict() + if _caused_by_empty_pool(exc): + # #3384: пул был пуст ещё ДО первой карточки — lease берётся в + # BrowserFetcher.__aenter__, поэтому NoProxyAvailableError вылетает из + # самого `async with` (строка 403) мимо стоп-механики цикла, которая и + # ставит no_proxy_stop. Без ключа такой прогон (attempted=0, к площадке не + # ходили) неотличим от любого другого падения: разбор простоя идёт SQL'ём + # по counters.no_proxy_stop (#3283/#3367), а не грепом текста ошибки. + current_counters["no_proxy_stop"] = 1 + runs_mod.mark_failed(db, run_id, str(exc)[:1000], current_counters) raise diff --git a/tradein-mvp/backend/tests/test_3384_no_proxy_at_batch_start.py b/tradein-mvp/backend/tests/test_3384_no_proxy_at_batch_start.py new file mode 100644 index 00000000..c0e36231 --- /dev/null +++ b/tradein-mvp/backend/tests/test_3384_no_proxy_at_batch_start.py @@ -0,0 +1,249 @@ +"""#3384 — пустой пул ДО первого объявления терял диагноз в записи прогона. + +Lease берётся ОДИН раз в `BrowserFetcher.__aenter__` (см. `_acquire_lease`), поэтому +на проде с пустым пулом `NoProxyAvailableError` вылетает из самого `async with`, +ДО первой карточки — то есть мимо стоп-механики внутри цикла (`no_proxy_stop = True; +break`), которая и пишет `counters.no_proxy_stop`. Общий `except Exception` ловил его и +писал `mark_failed` со стухшими нулевыми counters без ключа: прогон, который к площадке +не ходил ВООБЩЕ, в SQL-разборе простоя по `counters.no_proxy_stop` (#3288/#3367) не +находится и выглядит как произвольное падение задачи. + +Подделка ровно одна — провайдер прокси, чей `acquire()` возвращает `None` (ровно так +ведёт себя прод-`RealProxyProvider.acquire`, scraper_adapters.py:230, когда живых узлов +не осталось: он НЕ поднимает исключение). Отказ поэтому рождается там же, где в проде, — +в `BrowserFetcher._acquire_lease` (`lease is None and use_pool and production`), — и +проходит весь рабочий тракт до `mark_failed`. Счётчик POST'ов в сайдкар считается на +`httpx.AsyncClient.post` — «к площадке не ходили» проверяется, а не предполагается. + +Третий тест — про соседний случай: пул опустел МЕЖДУ стадиями, то есть уже ПОСЛЕ +реальной работы. Там проверяется, что в запись прогона не уезжают нули поверх +измеренного (`mark_failed` у `app.services.scrape_runs` counters ЗАМЕНЯЕТ, а не мержит). + +Сеть/БД замоканы; в сеть тест не ходит. +""" + +from __future__ import annotations + +import json +import os +import sys +from datetime import UTC, datetime, timedelta +from typing import Any +from unittest.mock import AsyncMock, MagicMock, patch + +os.environ.setdefault("DATABASE_URL", "postgresql+psycopg://test:test@localhost:5432/test") +sys.modules.setdefault("weasyprint", MagicMock()) + +import httpx # noqa: E402 +import pytest # noqa: E402 +from scraper_kit.proxy_errors import NoProxyAvailableError # noqa: E402 + +from app.core.config import settings # noqa: E402 +from app.services import scheduler as sched # noqa: E402 +from app.tasks import avito_detail_backfill as adb # noqa: E402 +from app.tasks import cian_history_backfill as chb # noqa: E402 +from app.tasks import domclick_detail_backfill as dcb # noqa: E402 + + +class _EmptyPoolProvider: + """Провайдер прокси, у которого не осталось живых узлов — как прод. + + `acquire` возвращает None, а не поднимает: `RealProxyProvider.acquire` + (scraper_adapters.py:222-234) отдаёт None, когда `proxy_pool.acquire` не нашёл + свободного узла. Разница не косметическая — исключение из провайдера + `_acquire_lease` глотает своим `except Exception` (browser_fetcher.py:696) и + приходит к тому же отказу другим путём, мимо ветки `lease is None`, которая и + работает на проде. + """ + + def __init__(self, *_a: Any, **_kw: Any) -> None: + pass + + def acquire(self, source: str) -> None: + return None + + def release(self, *_a: Any, **_kw: Any) -> None: + pass + + def mark_health(self, *_a: Any, **_kw: Any) -> None: + pass + + +def _mock_db(n_rows: int, url: str) -> MagicMock: + rows = [{"id": i + 1, "source_url": f"{url}{i + 1}"} for i in range(n_rows)] + db = MagicMock() + sel = MagicMock() + sel.mappings.return_value.all.return_value = rows + db.execute.return_value = sel + return db + + +def _prod_pool(monkeypatch: pytest.MonkeyPatch) -> None: + """Прод + включённый пул — единственная конфигурация, где отказ #2616 живой. + + Патчится ОДИН объект — `app.core.config.settings`: все три задачи и + `RealScraperConfig` (scraper_adapters.py:26) держат один и тот же синглтон, поэтому + `monkeypatch.setattr(chb.settings, ...)` выглядел как настройка одного циана, а на + деле настраивал и avito с домкликом. Assert ниже — чтобы зависимость не осталась + молчаливой: разъедется импорт — тест скажет об этом, а не начнёт тихо мерить не то. + """ + assert chb.settings is settings, "cian берёт другой settings — патч мимо" + assert adb.settings is settings, "avito берёт другой settings — патч мимо" + assert dcb.settings is settings, "domclick берёт другой settings — патч мимо" + monkeypatch.setattr(settings, "use_proxy_pool_browser", True) + monkeypatch.setattr(settings, "environment", "production") + monkeypatch.setattr(settings, "browser_http_endpoint", "http://browser:9000") + + +def _mock_session_svc() -> MagicMock: + svc = MagicMock() + svc.load_session.return_value = None + svc.COOKIE_EXPIRY_WARN_DAYS = 5 + svc.session_expires_at.return_value = datetime.now(tz=UTC) + timedelta(days=30) + return svc + + +@pytest.mark.asyncio +async def test_cian_empty_pool_at_start_marks_failed_with_no_proxy_stop( + monkeypatch: pytest.MonkeyPatch, +) -> None: + """Циан: пул пуст на старте → failed + no_proxy_stop=1, обработано 0 объявлений.""" + _prod_pool(monkeypatch) + db = _mock_db(5, "https://ekb.cian.ru/sale/flat/") + runs = MagicMock() + post = AsyncMock() + + with ( + patch.object(chb, "RealProxyProvider", _EmptyPoolProvider), + patch.object(sched, "runs_mod", runs), + patch.object(httpx.AsyncClient, "post", post), + pytest.raises(NoProxyAvailableError), + ): + await sched._execute_cian_backfill( + db, run_id=3384, params={"batch_size": 5, "do_houses": False} + ) + + runs.mark_done.assert_not_called() + runs.mark_banned.assert_not_called() + runs.mark_failed.assert_called_once() + counters = runs.mark_failed.call_args.args[3] + assert counters["no_proxy_stop"] == 1, f"counters={counters}: диагноз потерян" + assert counters["listings_processed"] == 0, "к площадке не ходили — 0 объявлений" + post.assert_not_called() + + +@pytest.mark.asyncio +async def test_domclick_empty_pool_at_start_marks_failed_with_no_proxy_stop( + monkeypatch: pytest.MonkeyPatch, +) -> None: + """Домклик: тот же контракт — failed + no_proxy_stop=1 + attempted=0.""" + _prod_pool(monkeypatch) + db = _mock_db(5, "https://ekaterinburg.domclick.ru/card/sale__flat__") + runs = MagicMock() + post = AsyncMock() + + with ( + patch.object(dcb, "RealProxyProvider", _EmptyPoolProvider), + patch.object(dcb, "domclick_session_svc", _mock_session_svc()), + patch.object(dcb, "runs_mod", runs), + patch.object(httpx.AsyncClient, "post", post), + pytest.raises(NoProxyAvailableError), + ): + await dcb.run_domclick_detail_backfill( + db, run_id=3384, params={"batch_size": 5, "budget_sec": 3600} + ) + + runs.mark_backfill_finished.assert_not_called() + runs.mark_failed.assert_called_once() + counters = runs.mark_failed.call_args.args[3] + assert counters["no_proxy_stop"] == 1, f"counters={counters}: диагноз потерян" + assert counters["attempted"] == 0, "к площадке не ходили — 0 попыток" + post.assert_not_called() + + +@pytest.mark.asyncio +async def test_avito_empty_pool_at_start_marks_failed_with_no_proxy_stop( + monkeypatch: pytest.MonkeyPatch, +) -> None: + """Avito: BrowserFetcher.__aenter__ вызывается напрямую — дыра та же, контракт тот же.""" + _prod_pool(monkeypatch) + monkeypatch.setattr(adb.settings, "scraper_fetch_mode", "browser") + monkeypatch.setattr(adb.settings, "avito_detail_backfill_use_curl", False) + db = _mock_db(5, "https://www.avito.ru/ekaterinburg/kvartiry/1-k._kvartira_") + runs = MagicMock() + post = AsyncMock() + + with ( + patch.object(adb, "RealProxyProvider", _EmptyPoolProvider), + patch.object(adb, "AvitoScraper", MagicMock()), + patch.object(adb, "runs_mod", runs), + patch.object(httpx.AsyncClient, "post", post), + pytest.raises(NoProxyAvailableError), + ): + await adb.run_avito_detail_backfill( + db, run_id=3384, params={"batch_size": 5, "budget_sec": 3600} + ) + + runs.mark_done.assert_not_called() + runs.mark_failed.assert_called_once() + counters = runs.mark_failed.call_args.args[3] + assert counters["no_proxy_stop"] == 1, f"counters={counters}: диагноз потерян" + assert counters["attempted"] == 0, "к площадке не ходили — 0 попыток" + post.assert_not_called() + + +@pytest.mark.asyncio +async def test_cian_empty_pool_between_stages_keeps_measured_counters() -> None: + """Циан: пул опустел ПОСЛЕ пройденной стадии — нули не должны лечь поверх замера. + + У циана (в отличие от avito/домклика с их живым `counters.to_dict()`) в общий + `except` приходит СТАРЫЙ словарь: реальные значения присваиваются уже после возврата + из `backfill_cian_history`, а отказ бывает и посреди неё — пул опустел между + стадиями, упал SELECT домов. `runs_mod` здесь настоящий + (`app.services.scrape_runs`), и его `mark_failed` counters ЗАМЕНЯЕТ + (`counters = CAST(:counters AS jsonb)`, scrape_runs.py:738) — то есть в записи + прогона остаётся ровно то, что уехало последним аргументом. + + Проверка по значению: смотрим jsonb-payload обоих UPDATE'ов (heartbeat и + mark_failed), а не факт вызова. + """ + measured = 5 + + async def _fake_backfill(_db: Any, **kw: Any) -> None: + """Стадия объявлений прошла (heartbeat записал замер) — потом пул опустел.""" + progress = chb.CianBackfillResult() + progress.listings_processed = measured + progress.listings_succeeded = measured + on_progress = kw["on_progress"] + assert on_progress is not None, "прогон без сигнала живости — мерить нечего" + on_progress(progress) + raise NoProxyAvailableError("cian") + + updates: list[dict[str, Any]] = [] + db = MagicMock() + + def _capture(_stmt: Any, params: Any = None, *_a: Any, **_kw: Any) -> MagicMock: + if isinstance(params, dict) and "counters" in params: + updates.append({**params, "counters": json.loads(params["counters"])}) + return MagicMock() + + db.execute.side_effect = _capture + + with ( + patch.object(chb, "backfill_cian_history", _fake_backfill), + pytest.raises(NoProxyAvailableError), + ): + await sched._execute_cian_backfill(db, run_id=3384, params={"batch_size": 5}) + + beats = [u["counters"] for u in updates if "error" not in u] + finals = [u["counters"] for u in updates if "error" in u] + assert beats and beats[-1]["listings_processed"] == measured, ( + f"heartbeat не записал замер — проверять нечего: {beats}" + ) + assert len(finals) == 1, f"ожидался ровно один mark_failed: {updates}" + final = finals[0] + assert final.get("no_proxy_stop") == 1, f"counters={final}: диагноз потерян" + assert final["listings_processed"] == measured, ( + f"counters={final}: нули поверх измеренных {measured} — SQL-разбор простоя " + "(#3288/#3367) прочитает «к площадке не ходили» про прогон, который ходил" + )