bot-backend
1a773554db
All checks were successful
CI Trade-In / changes (pull_request) Successful in 17s
CI / changes (pull_request) Successful in 18s
CI Trade-In / frontend-checks (pull_request) Has been skipped
CI / backend-tests (pull_request) Has been skipped
CI / frontend-tests (pull_request) Has been skipped
CI / openapi-codegen-check (pull_request) Has been skipped
CI Trade-In / browser-tests (pull_request) Successful in 1m47s
CI Trade-In / backend-tests (pull_request) Successful in 5m54s
Порог 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 <noreply@anthropic.com>
156 lines
5.7 KiB
Python
156 lines
5.7 KiB
Python
"""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]
|