From 1a773554db26317cc0b909f1b1894a7d9bb0c4f8 Mon Sep 17 00:00:00 2001 From: bot-backend Date: Thu, 17 Sep 2026 13:00:23 +0500 Subject: [PATCH] =?UTF-8?q?=D0=A1=D0=B0=D0=B9=D0=B4=D0=BA=D0=B0=D1=80:=20?= =?UTF-8?q?=D0=B2=20=D0=BB=D0=BE=D0=B3=D0=B0=D1=85=20/fetch=20=D0=BF=D0=BE?= =?UTF-8?q?=D1=8F=D0=B2=D0=B8=D0=BB=D0=BE=D1=81=D1=8C=20=D0=B2=D1=80=D0=B5?= =?UTF-8?q?=D0=BC=D1=8F=20=D1=86=D0=B5=D0=BB=D0=B5=D0=B2=D0=BE=D0=B9=20?= =?UTF-8?q?=D0=BD=D0=B0=D0=B2=D0=B8=D0=B3=D0=B0=D1=86=D0=B8=D0=B8=20?= =?UTF-8?q?=E2=80=94=20=D0=B7=D0=B0=D0=BC=D0=B5=D1=80=20=D1=85=D0=B2=D0=BE?= =?UTF-8?q?=D1=81=D1=82=D0=B0=20=D0=A6=D0=B8=D0=B0=D0=BD=D0=B0=20(#3419)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Порог BROWSER_NAV_TIMEOUT_MS=60000 не с чем было сравнить: «fetch OK» писался на DEBUG и без длительности, «fetch error» — тоже без неё, а время из access-лога включает пейсинг (18 с у cian) и ожидание лока. За сутки до 17.09 у cian 54 TimeoutError на ~1350 страниц (90 recycle × 15), ~4 %. Теперь _fetch_once меряет только целевую page.goto (monotonic, в finally — и на таймауте), обе строки несут nav_ms, «fetch OK» переведён на INFO. nav_ms=None — до цели не дошли (упал прогрев origin), прошлое число не наследуется. Решение по порогу — после 48 ч данных, это отдельный шаг. Co-Authored-By: Claude Opus 5 --- tradein-mvp/browser/server.py | 24 ++- tradein-mvp/browser/test_server_nav_timing.py | 156 ++++++++++++++++++ 2 files changed, 176 insertions(+), 4 deletions(-) create mode 100644 tradein-mvp/browser/test_server_nav_timing.py diff --git a/tradein-mvp/browser/server.py b/tradein-mvp/browser/server.py index 42a3bb6b..4cbc3a8c 100644 --- a/tradein-mvp/browser/server.py +++ b/tradein-mvp/browser/server.py @@ -145,6 +145,7 @@ import logging import os import random import re +import time from collections.abc import Callable, Mapping from typing import NamedTuple from urllib.parse import quote, urlparse @@ -837,6 +838,12 @@ _last_goto_at: dict[str, float] = {} # provider → loop-time последн # _fetch_once (сбрасывается в None перед навигацией, чтобы не отдать чужой # протухший статус), читается fetch_handler'ом под тем же _locks[provider] — гонки нет. _last_response_status: dict[str, int | None] = {} +# #3419: provider → длительность ЦЕЛЕВОЙ page.goto последнего /fetch в мс (None — до неё не +# дошли: упал прогрев origin, fetch_mode не navigate). Пишется в _fetch_once и на успехе, +# и на исключении goto; читается fetch_handler'ом под тем же локом для строки «fetch error», +# а «fetch OK» печатает её сам. Нужна, чтобы порог BROWSER_NAV_TIMEOUT_MS сравнивать с +# распределением времени навигации, а не подбирать вслепую. +_last_nav_ms: dict[str, int | None] = {} # #2164 P4: proxy-url, с которым СЕЙЧАС запущен инстанс провайдера (env или динамический # из пула, переданный в теле /fetch). Нужен для политики «relaunch ТОЛЬКО при реальной # смене прокси» — camoufox берёт proxy на launch, релонч дорогой, поэтому не релончим, @@ -1465,8 +1472,9 @@ async def fetch_handler(request: web.Request) -> web.Response: status = _last_response_status.get(provider) except Exception as exc: logger.error( - "tradein-browser[%s]: fetch error url=%r: %s: %s", + "tradein-browser[%s]: fetch error nav_ms=%s url=%r: %s: %s", provider, + _last_nav_ms.get(provider), url, type(exc).__name__, exc, @@ -2360,6 +2368,7 @@ async def _fetch_once( # Гасим статус прошлой навигации ДО работы: если goto упадёт, наверх не должен # уехать статус предыдущей страницы этого же провайдера (#3196). _last_response_status[provider] = None + _last_nav_ms[provider] = None if reset_context: await _close_reusable_context(provider) @@ -2434,7 +2443,11 @@ async def _fetch_once( } if referer: goto_kwargs["referer"] = referer - response = await page.goto(url, **goto_kwargs) # type: ignore[attr-defined] + nav_started = time.monotonic() + try: + response = await page.goto(url, **goto_kwargs) # type: ignore[attr-defined] + finally: + _last_nav_ms[provider] = int((time.monotonic() - nav_started) * 1000) _last_response_status[provider] = _status_of(response) if BROWSER_WAIT_MS > 0: await page.wait_for_timeout(BROWSER_WAIT_MS) # type: ignore[attr-defined] @@ -2521,9 +2534,12 @@ async def _fetch_once( await page.close() # type: ignore[attr-defined] _page_counters[provider] = _page_counters.get(provider, 0) + 1 - logger.debug( - "tradein-browser[%s]: fetch OK url=%r pages_since_launch=%d", + # INFO, а не DEBUG (#3419): без строк успеха распределение времени навигации не + # снять, а сравнивать его с таймаутами и есть цель. + logger.info( + "tradein-browser[%s]: fetch OK nav_ms=%s url=%r pages_since_launch=%d", provider, + _last_nav_ms.get(provider), url, _page_counters[provider], ) diff --git a/tradein-mvp/browser/test_server_nav_timing.py b/tradein-mvp/browser/test_server_nav_timing.py new file mode 100644 index 00000000..68330b9e --- /dev/null +++ b/tradein-mvp/browser/test_server_nav_timing.py @@ -0,0 +1,156 @@ +"""test_server_nav_timing.py — длительность целевой навигации в логах /fetch (#3419). + +Порог BROWSER_NAV_TIMEOUT_MS=60000 не с чем было сравнить: «fetch OK» писался на DEBUG +и без длительности, «fetch error» — тоже без неё. Теперь обе строки несут nav_ms — +время ЦЕЛЕВОЙ page.goto (без прогрева origin, пейсинга и BROWSER_WAIT_MS). + +Часы подменяются только в модуле сервера (server.time), event loop их не видит. +camoufox НЕ запускается: browser/page поддельные. + +Запуск (из tradein-mvp/browser/):: + + python -m pytest test_server_nav_timing.py -q +""" + +from __future__ import annotations + +import asyncio +import importlib.util +import logging +import re +from pathlib import Path +from types import SimpleNamespace +from typing import Any + +import pytest +from aiohttp.test_utils import make_mocked_request + +_SERVER_PATH = Path(__file__).resolve().parent / "server.py" +_spec = importlib.util.spec_from_file_location("tradein_browser_server_nav_timing", _SERVER_PATH) +assert _spec is not None and _spec.loader is not None +server = importlib.util.module_from_spec(_spec) +_spec.loader.exec_module(server) + +_ORIGIN = "https://www.cian.ru/" +_CARD = "https://ekb.cian.ru/sale/flat/1/" + + +class _Clock: + def __init__(self) -> None: + self.now = 1000.0 + + def monotonic(self) -> float: + return self.now + + +class _Page: + """goto двигает поддельные часы на заданное время; на origin или по флагу — падает.""" + + def __init__(self, clock: _Clock, nav_s: float, *, fail_target: bool, fail_origin: bool): + self._clock = clock + self._nav_s = nav_s + self._fail_target = fail_target + self._fail_origin = fail_origin + + async def route(self, pattern: str, handler: Any) -> None: + return None + + async def goto(self, url: str, **kwargs: Any) -> None: + if url == _ORIGIN: + if self._fail_origin: + raise TimeoutError("origin goto timeout") + return None + self._clock.now += self._nav_s + if self._fail_target: + raise TimeoutError("Page.goto: Timeout 60000ms exceeded.") + return None + + async def wait_for_timeout(self, ms: int) -> None: + return None + + async def content(self) -> str: + return "карточка" + + async def close(self) -> None: + return None + + +class _Browser: + def __init__(self, page: _Page) -> None: + self._page = page + + async def new_page(self) -> _Page: + return self._page + + +@pytest.fixture(autouse=True) +def _reset_state(monkeypatch: pytest.MonkeyPatch) -> _Clock: + for name in ("_browsers", "_page_counters", "_locks", "_last_goto_at", + "_last_response_status", "_last_nav_ms", "_launched_proxy"): + monkeypatch.setattr(server, name, {}) + monkeypatch.setattr(server, "_locks_guard", asyncio.Lock()) + monkeypatch.setattr(server, "IS_PROD", False) + monkeypatch.setattr(server, "BROWSER_WAIT_MS", 0) + monkeypatch.setattr(server, "_MIN_PAGE_INTERVAL_BY_PROVIDER", {}) + monkeypatch.setattr(server, "BROWSER_MIN_PAGE_INTERVAL_S", 0.0) + monkeypatch.setattr(server, "_RECYCLE_PAGES_BY_PROVIDER", dict.fromkeys(server.PROVIDERS, 10_000)) + + async def _ensure(provider: str, proxy_override: str | None = None) -> bool: + return True + + monkeypatch.setattr(server, "_ensure_browser", _ensure) + clock = _Clock() + monkeypatch.setattr(server, "time", SimpleNamespace(monotonic=clock.monotonic)) + return clock + + +async def _coro(value: Any) -> Any: + return value + + +def _fetch(page: _Page, body: dict[str, Any]) -> int: + server._browsers["cian"] = _Browser(page) + request = make_mocked_request("POST", "/fetch") + request.json = lambda: _coro(body) # type: ignore[method-assign] + return asyncio.run(server.fetch_handler(request)).status + + +def _nav_ms(caplog: pytest.LogCaptureFixture, marker: str) -> list[int | None]: + """nav_ms из строк лога с маркером, по порядку: число или None.""" + values: list[int | None] = [] + for record in caplog.records: + message = record.getMessage() + if marker in message: + match = re.search(r"nav_ms=(\d+|None)\b", message) + assert match is not None, f"в строке нет nav_ms: {message}" + values.append(None if match.group(1) == "None" else int(match.group(1))) + return values + + +def test_success_logs_target_navigation_ms_at_info( + _reset_state: _Clock, caplog: pytest.LogCaptureFixture +) -> None: + page = _Page(_reset_state, 12.345, fail_target=False, fail_origin=False) + with caplog.at_level(logging.INFO, logger=server.logger.name): + status = _fetch(page, {"url": _CARD, "origin": _ORIGIN}) + + assert status == 200 + assert _nav_ms(caplog, "[cian]: fetch OK") == [12345] + + +def test_timeout_logs_navigation_ms_then_prenav_failure_logs_none( + _reset_state: _Clock, caplog: pytest.LogCaptureFixture +) -> None: + """Таймаут цели несёт своё время; следующий отказ ДО цели не наследует прошлое число.""" + with caplog.at_level(logging.INFO, logger=server.logger.name): + first = _fetch( + _Page(_reset_state, 60.0007, fail_target=True, fail_origin=False), + {"url": _CARD, "origin": _ORIGIN}, + ) + second = _fetch( + _Page(_reset_state, 5.0, fail_target=False, fail_origin=True), + {"url": _CARD, "origin": _ORIGIN}, + ) + + assert (first, second) == (500, 500) + assert _nav_ms(caplog, "[cian]: fetch error") == [60000, None]