"""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]