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],
     )

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 "<html><body>карточка</body></html>"
+
+    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]