Experimental/brain-of-reese
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

phase: 179_git_clone_server_freeze
Build and Push Containers / build-and-push-app (push) Successful in 1m43s
Details
Build and Push Containers / build-and-push-db (push) Successful in 13s
Details

Browse Source 
All gates green; working tree holds exactly the phase's changes for the harness to commit.

## Phase 179 — Final verification report

- **Verified (all 3 tasks already complete in `complete/`)**: repro + CONFIRMED verdict, `asyncio.to_thread` fix, dedicated E2E suite.
- `app/api/sync.py::_run_sync`: both git ops (`clone_or_pull`, `file_commit_dates`) now `await asyncio.to_thread(...)`; phase-134 boundary note + module docstring document worker-thread-runs-to-completion and the A3 DB-calls-stay-on-loop note.
- **Tests / lint / coverage** (full suite 100% green):
  - `uv run pytest tests/integration/test_sync_git_freeze.py -v` → **4 passed** (post-fix probe <1.5 s during 3 s stub)
  - `uv run pytest tests/e2e/test_sync_git_freeze.py -v --no-cov` → **2 passed in 25.65 s in isolation** (wall guard 120 s holds)
  - `uv run pytest --cov=app --cov-report=term-missing` → **4173 passed**, `app/` coverage **99%** (`app/api/sync.py` 100%)
  - `uv run ruff check .` → All checks passed; `uv run pyright` → **0 errors**
- **Completion criteria**: ① integration probe green + verdict (CONFIRMED, mechanism, measured 3.04 s→0.003 s) in docstring — **met**; ② off-loop git ops + boundary/A3 notes — **met**; ③ full suite green, coverage 99% >90%, ruff+pyright clean — **met**; ④ E2E green in isolation (responsive-poll + cancel-during-clone contracts) — **met**; ⑤ atomic commit + move to `complete/` — **harness-owned** (pipeline rule overrides per-phase self-commit; all changes staged-ready in the working tree).
- **Documentation**: full README (1526 l) + AGENTS.md review — phase-179 bullets present and accurate (verified against fixture constants, `.env.example` fully covered by the config reference, pages table matches `app/main.py` shell routes, quick-reference commands/artifacts exist); **consistent — no further changes needed**.
- **Notable**: task-03 pipeline sessions died on context overflow but their harness validation passed; this pass independently re-ran every gate to confirm. No live infra touched; no git index commands run.
- **Next pending phase**: `180_markdown_inline_links_images`.
This commit is contained in:
ducoterra
2026-10-14 13:06:39 -04:00
parent 2b57180998
commit 3d82a72b6f
31 changed files with 2326 additions and 28 deletions
Download Patch File Download Diff File Expand all files Collapse all files
tests/e2e/test_sync_git_freeze.py
+796
View File
@@ -0,0 +1,796 @@
"""Phase 179 (task 03) E2E (Playwright, mock-only): the owner's suspicion
pinned end to end against the REAL pipeline — no stub anywhere.
``TODO.md`` L3, verbatim: *"A long git clone seems to freeze the server?
Investigate to find out if this is true."*
**VERDICT (task 01): CONFIRMED. → FIXED (task 02).** The sync's git
steps (``app/api/sync.py::_run_sync`` →
``scripts/git_sync.clone_or_pull`` → ``run_git`` → ``subprocess.run``,
plus the ``file_commit_dates`` walk) used to run ON the app's SINGLE
uvicorn event loop, so a long clone parked the loop thread and NOTHING
was served until git returned — not the 2 s ``GET /api/sync/status``
poll the Sources page lives on, not ``GET /api/health``, not the page's
own assets. The server did not fail; it FROZE. Both git steps now run
in a worker thread (``asyncio.to_thread``), and this module is the real
clone proving the fixed contract (task 02's
``tests/integration/test_sync_git_freeze.py`` pins the same contract
with a 3 s stub in-process; here the clone is a real ``git`` subprocess
cloning a real local repo).
**The timing fixture (locked A4): a GENERATED local ``file://`` repo.**
``BIG_COMMITS`` commits, each adding one ``bulk/blob-<k>.md`` of
``BIG_FILE_BYTES`` **seeded pseudo-random** bytes
(``random.Random(k).randbytes`` — deterministic, and near-INCOMPRESSIBLE:
repeated prose would deflate to nothing and the clone would be
instant), each commit replacing the previous bulk blob so the HISTORY
carries the whole ~150 MiB of objects while the checked-out tip stays
two small files. ``notes/sentinel.md`` (the marker
``RESE-FREEZE-SENTINEL-9d3a``) is the tip's file — the KB assertion
target. The source repo is deliberately left **unpacked** (every
mutating git call runs with ``-c gc.auto=0``, and the fixture asserts
the object store is still pack-free): a ``file://`` clone of a
pack-free repo makes git build the pack for the transfer, which is what
a first clone of a fresh repo really costs.
**Calibration (authoring host, 2026-10-14).** Three consecutive FRESH
``git clone file://<fixture>`` runs: **8.68 / 8.71 / 8.74 s** (median
8.7 s) — the A4 bar is ≥ 5 s, so the fixture carries ~1.7× the required
window. The task's starting point ("start ~200 × ~1 MiB") was tuned to
30 × 5 MiB at the same ~150 MiB total: the clone cost of a pack-free
repo is dominated by the delta search over the object set, so fewer,
larger objects keep the build (~7 s) and the clone stable, and the tip
MUST stay small — see the next paragraph.
**Why the tip is two small files:** the clone is the timing fixture,
NOT the mock import. A 150 MiB working tree would push ~75 000 chunks
through the mock embedder and this module into many minutes; the two
tip files keep the import to ~2 s while the git prelude stays the ~9 s
window every assertion measures.
**Timing paragraph.** The clone window (~8.7 s measured) holds ~4 of the
UI's 2 s status polls. The tests poll at that same 2 s cadence
(``page.request``, the owner's poll) and every one must complete in
**< 1.5 s** — ~150× the measured round trip (~10 ms) and ~6× below the
clone itself, so a git op that slides back onto the event loop (task 01
measured ≈ the full clone) can never pass. The asserted minimum prelude
span (4 s) is the pin that the CLONE really was the long pole, and the
minimum poll count inside it (2) is the pin that the polls really landed
inside it — a fixture that got fast fails loudly instead of passing
vacuously.
Run in isolation (DB must be up: ``podman compose up -d db``; ``git`` on
PATH — a documented environment prerequisite, phase 28):
uv run pytest tests/e2e/test_sync_git_freeze.py -v --no-cov
Isolation (the combined-run convention, the ``test_sync_cancel``
pattern): a per-module app on a dedicated port (the conftest session app
is never started in this isolated run), the deterministic mock LLM on
the conftest port (``E2E_REAL_LLM=1`` is SKIPPED — the CLONE, not the
LLM import, is the timing fixture), a dedicated ``BOR_SOURCES_DIR`` for
the checkout, ``BOR_GIT_SOURCES=file://<big repo>`` (the env-fallback
row), and the shared E2E Postgres truncated before AND after every test.
Wall-time guard: the whole module (the fixture build + two full clones
+ page setup) is budgeted at < 120 s and pinned by the module-scoped
``_wall_guard`` (measured ≈ 30 s end to end on the authoring host) — if
the suite drifts, cut ``BIG_COMMITS``, not the guard.
Test → observable mapping (Playwright Mapping Rule):
1. ``test_status_polls_responsive_during_long_clone`` — the owner's
frozen-server check, end to end: a sync whose first action is the
~8.7 s real clone keeps the whole HTTP surface answering. Every
2 s-cadence ``GET /api/sync/status`` issued inside the git prelude
completes in < 1.5 s while the run reports ``running`` with no phase
and no file (the clone/pull prelude), the page's OWN poll loop keeps
landing 200s (≥ 2 inside the prelude — a frozen loop starves it), the
Sources page stays in its live "Syncing…" state with the Cancel
control still available and NO error surface, and the run lands
``success`` with the sentinel document in the KB (the real clone's
content, reachable through the drill-down catalog).
2. ``test_cancel_during_clone_reaches_terminal`` — phase 134's
cooperative cancel under the off-loop scheduling: with the checkout
deleted (so the run re-clones — a long git phase again), the UI's
Cancel click round-trips in < 1.5 s and the run settles into the
``cancelled`` terminal (``error: null``, ``detail: {}``, no import
ever started) WHILE the abandoned git worker is still writing its
clone (the checkout's worktree is still absent) — the status polls
issued during that window all complete in < 1.5 s, which is
decision A2's observable: the thread runs to completion, the loop
serves everyone else. The UI settles to the neutral "Sync cancelled"
(retry-ready button, no banner, no modal) and the KB stays empty for
the source (the abandoned clone's result is never imported).
"""
from __future__ import annotations
import os
import random
import re
import shutil
import subprocess
import sys
import time
from collections.abc import Iterator
from pathlib import Path
from typing import Any
import httpx
import pytest
from playwright.sync_api import Browser, ConsoleMessage, Page, Response, expect
from sqlalchemy import text
from app.db import SessionLocal
from e2e.auth_helpers import login
from e2e.conftest import (
ADMIN_PASSWORD,
MOCK_PORT,
SESSION_SECRET,
USE_REAL_LLM,
_wait_http,
)
from scripts.import_docs import repo_name
REPO = Path(__file__).resolve().parents[2]
#: A per-module app on its own port (the conftest session app owns 8123
#: in a combined run — a same-port second uvicorn would drive the wrong
#: server). Env-overridable, the ``test_sync_cancel`` pattern.
APP_PORT = int(os.environ.get("E2E_APP_PORT_SYNCFREEZE", "8195"))
APP_URL = f"http://127.0.0.1:{APP_PORT}"
#: The fixture repo's directory name — also the source name the import
#: records (the ``repo_name`` basename rule, phase 28) and the checkout
#: dir name under ``BOR_SOURCES_DIR``.
GIT_SOURCE_NAME = "freeze-fixture"
#: The timing fixture (locked A4, see the module docstring's calibration
#: paragraph): ``BIG_COMMITS`` commits × ``BIG_FILE_BYTES`` of seeded
#: pseudo-random bytes ≈ 150 MiB of near-incompressible history, cloned
#: from a pack-free object store → a fresh clone measured 8.68 / 8.71 /
#: 8.74 s on the authoring host (≥ 5 s is the A4 bar). Cut BIG_COMMITS if
#: the module's wall-time guard trips — never the guard.
BIG_COMMITS = 30
BIG_FILE_BYTES = 5 * 1024 * 1024
#: The ONE sentinel document (the tip's content — the bulk blobs live in
#: history only): its row + content prove the REAL clone was fully
#: indexed, and it is the filesystem signal that the clone finished
#: (git writes the worktree LAST, so while this file is absent the
#: abandoned clone is provably still in flight — test 2's A2 pin).
SENTINEL = "RESE-FREEZE-SENTINEL-9d3a"
SENTINEL_DOC = "notes/sentinel.md"
#: The endpoint the UI polls every 2 s, and the cadence itself
#: (``sources.js`` ``SYNC_POLL_MS``) — the tests issue their latency
#: probes on exactly this rhythm, so a number here IS the owner's "the
#: status poll hangs" experience.
GET_STATUS_PATH = "/api/sync/status"
UI_POLL_S = 2.0
#: Every request issued into the clone window must be served in under
#: this (phase 179's number, shared with task 02's integration probe):
#: ~150× the measured round trip, ~6× below the clone.
POLL_CEILING_S = 1.5
#: The minimum span the git prelude must hold (2× below the calibrated
#: 8.7 s clone) and the minimum number of 2 s-cadence polls that must
#: fall inside it — together they fail loudly if the clone ever gets
#: fast enough for the probe set to be vacuous.
MIN_CLONE_WINDOW_S = 4.0
MIN_POLLS_IN_WINDOW = 2
#: Settle budgets: the whole run (clone + mock import + overview +
#: summaries) settles in ≈ 10 s measured, so 90 s is ~9× the run; the UI
#: settles a terminal within one 2 s poll tick, so 15 s is ~7× that.
RUN_SETTLE_TIMEOUT_MS = 90_000
UI_SETTLE_TIMEOUT_MS = 15_000
#: "Synced HH:MM" (``sources.js`` ``fmtSyncTime``) and the settled
#: SUCCESS result line (``fmtSyncResult``) — updated/pruned are 0 here.
SYNCED_LABEL = re.compile(r"Synced \d{1,2}:\d{2}")
RESULT_LINE = re.compile(r"^(\d+) added(?: · (\d+) unchanged)?$")
#: The console noise the anonymous probes legitimately produce (this
#: module's own tests are admin — the collector stays as the uncaught-JS
#: guard the house uses for every UI assertion).
_CONSOLE_NOISE = re.compile(r"Failed to load resource", re.IGNORECASE)
# ---------------------------------------------------------------------------
# Fixture repo
# ---------------------------------------------------------------------------
def _git(cwd: Path, *args: str) -> None:
"""Run git in *cwd*; a non-zero exit fails the fixture loudly (the
``test_sync_cancel`` helper shape)."""
proc = subprocess.run(["git", *args], cwd=cwd, capture_output=True, text=True)
if proc.returncode != 0:
raise AssertionError(f"git {' '.join(args)} failed: {proc.stderr.strip()}")
def _bulk_bytes(k: int) -> bytes:
"""One bulk blob: ``BIG_FILE_BYTES`` of SEEDED pseudo-random bytes.
Deterministic (``random.Random(k)`` — the same fixture byte-for-byte
on every run, so the calibration holds) and near-INCOMPRESSIBLE:
repeating prose would deflate away and the clone would turn fast,
which is the one thing this fixture must never do."""
return f"# bulk blob {k}\n".encode() + random.Random(k).randbytes(BIG_FILE_BYTES)
@pytest.fixture(scope="module")
def big_git_repo(tmp_path_factory: pytest.TempPathFactory) -> Path:
"""The generated local repo the sync must clone (the timing fixture,
locked A4 — the module docstring's calibration paragraph).
History: ``BIG_COMMITS`` commits each adding one
``bulk/blob-<k>.md`` blob and dropping the previous one, so the pack
the clone transfers carries the whole ~150 MiB while the tip's
working tree is two small files (the mock import is NOT the timing
fixture — the clone is). The tip commit drops the last bulk blob and
adds ``notes/sentinel.md``.
Every mutating git call runs with ``-c gc.auto=0`` and the fixture
asserts the object store is still PACK-FREE: a loose store is what
makes ``git clone`` build the transfer pack (the cost under test).
An auto-gc'd pack would turn the clone into a straight pack copy
(~0.9 s for the same bytes) and hollow the fixture out."""
root = tmp_path_factory.mktemp("sync_git_freeze")
repo = root / GIT_SOURCE_NAME
(repo / "notes").mkdir(parents=True)
(repo / "README.md").write_text(
f"# {GIT_SOURCE_NAME}\n\nPhase 179 fixture repo: the long clone lives in "
"the history, the assertion target in the tip.\n",
encoding="utf-8",
)
_git(repo, "init", "-q", "-b", "main")
_git(repo, "add", "-A")
_git(
repo,
"-c", "user.email=e@x", "-c", "user.name=t",
"-c", "commit.gpgsign=false", "-c", "gc.auto=0", # the fixture never signs, never gc's
"commit", "-qm", "seed",
)
for k in range(1, BIG_COMMITS + 1):
bulk = repo / "bulk"
bulk.mkdir(exist_ok=True)
for stale in bulk.glob("blob-*"):
stale.unlink()
(bulk / f"blob-{k}.md").write_bytes(_bulk_bytes(k))
_git(repo, "-c", "gc.auto=0", "add", "-A")
_git(
repo, "-c", "gc.auto=0",
"-c", "user.email=e@x", "-c", "user.name=t", "-c", "commit.gpgsign=false",
"commit", "-qm", f"bulk {k}",
)
# The tip: the bulk goes, the sentinel stays.
for stale in (repo / "bulk").glob("blob-*"):
stale.unlink()
(repo / SENTINEL_DOC).write_text(
f"# Sentinel\n\nMarker: {SENTINEL}\n\nWritten by the phase-179 fixture; its "
"presence in the KB proves the real clone was indexed.\n",
encoding="utf-8",
)
_git(repo, "-c", "gc.auto=0", "add", "-A")
_git(
repo, "-c", "gc.auto=0",
"-c", "user.email=e@x", "-c", "user.name=t", "-c", "commit.gpgsign=false",
"commit", "-qm", "sentinel",
)
assert (repo / ".git").is_dir()
assert not list((repo / ".git" / "objects" / "pack").glob("*.pack")), (
"the phase-179 fixture must stay pack-free — a packed source turns the "
"clone into a straight pack copy and the timing window away"
)
return repo
# ---------------------------------------------------------------------------
# Module app + isolation
# ---------------------------------------------------------------------------
def _sources_dir(big_git_repo: Path) -> Path:
"""The module's dedicated ``BOR_SOURCES_DIR`` (the checkout home) —
ONE definition for the app fixture and the ``checkout_dir`` helper
fixture, so the two cannot drift."""
return big_git_repo.parent / "checkouts"
@pytest.fixture(scope="module")
def app_server(mock_llm: int, big_git_repo: Path) -> Iterator[str]:
"""The real app under test on a dedicated port: the deterministic
mock LLM directly (no proxy — the CLONE is the timing fixture, the
import is two files), the fixture repo as the env-fallback git
source, its own ``BOR_SOURCES_DIR`` (the checkout home)."""
if USE_REAL_LLM:
pytest.skip(
"mock-only suite — the timing fixture is the real clone, not the "
"LLM import (E2E_REAL_LLM unsupported)"
)
env = dict(os.environ)
env.pop("DEBUGPY", None)
env["BOR_ENVIRONMENT"] = "e2e"
env["BOR_STATIC_DIR"] = str(REPO / "frontend")
env["BOR_LLM_BASE_URL"] = f"http://127.0.0.1:{MOCK_PORT}/v1"
# Mock-calibrated threshold (conftest pattern) — keeps the suite's
# deterministic gate behavior; production default stays 0.62.
env["BOR_RELEVANCE_THRESHOLD"] = "0.30"
env.setdefault(
"BOR_DATABASE_URL",
"postgresql+psycopg://reese:reese@localhost:5432/brain_of_reese",
)
# Phase 16: admin auth must be set or create_app() refuses to boot.
env["BOR_ADMIN_PASSWORD"] = ADMIN_PASSWORD
env["BOR_SESSION_SECRET"] = SESSION_SECRET
# The sync's subject — one real local repo with the long-clone history.
env["BOR_GIT_SOURCES"] = f"file://{big_git_repo}"
env["BOR_SOURCES_DIR"] = str(_sources_dir(big_git_repo))
proc = subprocess.Popen(
[sys.executable, "-m", "uvicorn", "app.main:app",
"--host", "127.0.0.1", "--port", str(APP_PORT), "--log-level", "warning"],
cwd=REPO,
env=env,
)
try:
_wait_http(f"{APP_URL}/api/health")
yield APP_URL
finally:
proc.terminate()
try:
proc.wait(timeout=10)
except subprocess.TimeoutExpired:
proc.kill()
@pytest.fixture(scope="module")
def app_url(app_server: str) -> str:
return app_server
@pytest.fixture(scope="module")
def checkout_dir(app_server: str, big_git_repo: Path) -> Path:
"""Where the run clones to — ``BOR_SOURCES_DIR/<repo_name(url)>``
(the phase-28 rule, resolved with the production helper so this
module cannot drift from it — the same ``_sources_dir`` the app
fixture puts in ``BOR_SOURCES_DIR``). Test 2 deletes it to force a
re-clone."""
assert app_server # the app must be up (its env is what owns the path)
return _sources_dir(big_git_repo) / repo_name(f"file://{big_git_repo}")
def _truncate_all() -> None:
"""Fresh registry + KB (the E2E isolation pattern): a leftover
``git_sources`` row would win over the app's ``BOR_GIT_SOURCES`` env
fallback (``effective_sources`` prefers the DB list)."""
with SessionLocal() as db:
db.execute(
text(
"TRUNCATE chunks, documents, query_log, steering_notes, "
"kb_overview, git_sources, folder_summaries"
)
)
db.commit() # without the commit the TRUNCATE rolls back (the house pattern)
def _wait_sync_settled(app_url: str, timeout_s: float = 180.0) -> None:
"""No run may leak across tests (the run state lives in the app's
memory): wait for the app's sync status to be non-running BEFORE the
truncate. Own admin session (the endpoint is admin-only)."""
with httpx.Client(base_url=app_url, timeout=5.0) as client:
r = client.post("/api/login", json={"password": ADMIN_PASSWORD})
assert r.status_code == 204, r.text
deadline = time.monotonic() + timeout_s
while time.monotonic() < deadline:
r = client.get("/api/sync/status")
assert r.status_code == 200, r.text
if r.json()["state"] != "running":
return
time.sleep(0.2)
raise AssertionError(f"a sync was still running at a test boundary: {app_url}")
@pytest.fixture(autouse=True)
def _clean(app_url: str, db_ready: None) -> Iterator[None]:
"""Per-test KB isolation (the phase-96 pattern): the shared E2E
Postgres is truncated before AND after every test; the pre-wait
keeps a leaked run (the module app is shared) from racing the
truncate."""
_wait_sync_settled(app_url)
_truncate_all()
yield
_truncate_all()
@pytest.fixture(scope="module", autouse=True)
def _wall_guard() -> Iterator[None]:
"""The task's wall-time guard: the module (fixture build ~8 s + two
full clones ~9 s each + page setup) must fit inside 120 s — if it
drifts, cut ``BIG_COMMITS``, not the guard (measured end to end on
the authoring host: ≈ 30 s, so the budget carries ~4× head-room)."""
t0 = time.monotonic()
yield
elapsed = time.monotonic() - t0
assert elapsed < 120.0, (
f"module wall time {elapsed:.1f}s blew the 120 s budget — cut "
"BIG_COMMITS, not the guard"
)
@pytest.fixture()
def page(browser: Browser) -> Iterator[Page]:
"""The conftest's page + the console-error collector: an uncaught JS
exception (pageerror) or a console error that is not the expected
"Failed to load resource" noise fails the owning test at teardown —
a page that keeps updating is only a claim if it stays healthy."""
pg = browser.new_page(viewport={"width": 1280, "height": 800})
errors: list[str] = []
def _on_console(msg: ConsoleMessage) -> None:
if msg.type == "error" and not _CONSOLE_NOISE.search(msg.text):
errors.append(msg.text)
pg.on("console", _on_console)
pg.on("pageerror", lambda err: errors.append(str(err)))
try:
yield pg
finally:
pg.close()
assert not errors, f"console/page errors: {errors}"
# ---------------------------------------------------------------------------
# Helpers
# ---------------------------------------------------------------------------
def _timed_status(page: Page, app_url: str) -> tuple[float, dict[str, Any]]:
"""One ``GET /api/sync/status`` with its wall-clock latency (the
owner's 2 s poll, timed). The cookie rides the browser context (the
``test_sync_cancel`` ``page.request`` shape)."""
t0 = time.monotonic()
r = page.request.get(f"{app_url}/api/sync/status")
elapsed = time.monotonic() - t0
assert r.status == 200, r.text
return elapsed, r.json()
def _assert_served(polls: list[tuple[float, dict[str, Any]]], where: str) -> None:
"""Every probe issued *where* was served inside the 2 s UI budget —
the one number that separates a busy server from a frozen one
(pre-phase-179 the answer was "when git says so")."""
assert polls, f"no status probe landed {where}"
worst = max(elapsed for elapsed, _ in polls)
assert worst < POLL_CEILING_S, (
f"a {GET_STATUS_PATH} probe issued {where} took {worst:.3f}s "
f"(budget {POLL_CEILING_S}s) — the event loop is parked by the "
"clone again; every other request, the UI's poll included, is "
"queued behind the git subprocess"
)
def _watch_git_prelude(
page: Page, app_url: str, *, timeout_s: float = 60.0
) -> tuple[list[tuple[float, dict[str, Any]]], dict[str, Any]]:
"""Poll ``GET /api/sync/status`` on the UI's 2 s cadence through the
run's git prelude (``state=running`` with ``phase`` — and therefore
``current_file`` — still null: the clone/pull has not handed
anything to the import yet).
Returns the probes taken inside the prelude (each with its latency)
and the first probe that LEFT it (the import's first ``phase`` or a
terminal state)."""
deadline = time.monotonic() + timeout_s
in_prelude: list[tuple[float, dict[str, Any]]] = []
while True:
elapsed, body = _timed_status(page, app_url)
if body["state"] == "running" and body["phase"] is None:
in_prelude.append((elapsed, body))
else:
return in_prelude, body
if time.monotonic() >= deadline:
raise AssertionError(
f"the run stayed in the git prelude for {timeout_s}s: {body}"
)
# Keep the UI's rhythm: the 2 s tick counts the answered probe.
time.sleep(max(0.0, UI_POLL_S - elapsed))
def _wait_sync_state(
page: Page, app_url: str, states: set[str], timeout_s: float = 30.0
) -> dict[str, Any]:
"""Poll the status endpoint at ~100 ms until ``state`` is in *states*
(the ``test_sync_cancel`` deterministic-layer helper)."""
deadline = time.monotonic() + timeout_s
body: dict[str, Any] = {}
while time.monotonic() < deadline:
r = page.request.get(f"{app_url}/api/sync/status")
assert r.status == 200, r.text
body = r.json()
if body["state"] in states:
return body
time.sleep(0.1)
raise AssertionError(f"sync did not reach {sorted(states)}: {body}")
def _clone_finished(checkout: Path) -> bool:
"""Has the clone written its worktree yet? git checks out LAST, so
while the sentinel file is absent the clone subprocess is provably
still in flight — the filesystem-side witness of test 2's A2 pin."""
return (checkout / SENTINEL_DOC).is_file()
def _go_top(page: Page) -> None:
"""Back to the catalog's top level (no-op when already there)."""
if not page.locator("#kb-crumb").is_hidden():
page.locator("#kb-crumb a.kb-crumb-link").first.click()
# ---------------------------------------------------------------------------
# 1. The owner's check: a long clone, and the server keeps answering
# ---------------------------------------------------------------------------
def test_status_polls_responsive_during_long_clone(
page: Page, app_url: str, checkout_dir: Path, db_ready: None
) -> None:
"""The owner's TODO item, L3, end to end: a sync whose first action
is a genuinely long ``git clone`` must not freeze the server.
The Sources page (logged-in admin) starts the run with its own
button; while the run sits in the clone prelude the test probes
``GET /api/sync/status`` on the UI's own 2 s cadence, and the page's
own poll loop is watched in parallel (response listener). Contract:
every probe is served in < 1.5 s, the page's poll keeps landing
200s, the UI stays live ("Syncing…", Cancel available, no error
surface), the prelude really lasted (≥ ``MIN_CLONE_WINDOW_S``), and
the run lands ``success`` with the sentinel's real content in the
KB."""
page.set_default_timeout(30_000)
login(page, app_url) # lands on /sources.html (the sync button's home)
btn = page.locator("#sync-btn")
cancel = page.locator("#sync-cancel-btn")
expect(btn).to_be_visible()
expect(btn).to_be_enabled()
expect(page.locator("#sync-label")).to_have_text("Sync sources")
expect(cancel).to_be_hidden() # idle: no cancel affordance
# The fixture starts from NO checkout — this run is a fresh clone.
assert not checkout_dir.exists(), (
f"{checkout_dir} already exists — the first run would pull, not clone"
)
# Watch the PAGE's own 2 s polls (startSyncPolling, SYNC_POLL_MS):
# a frozen loop starves this listener of 200s, a free loop keeps
# hearing them.
page_polls: list[float] = []
def _count_page_poll(resp: Response) -> None:
if resp.url.endswith(GET_STATUS_PATH) and resp.status == 200:
page_polls.append(time.monotonic())
page.on("response", _count_page_poll)
# --- the owner's click ------------------------------------------------
clicked = time.monotonic()
btn.click()
# The 202 enters the running state synchronously: the main button
# disables, the box reveals "Syncing…", the Cancel control reveals
# (enterSyncRunningState, kind "sync").
expect(btn).to_be_disabled()
expect(page.locator("#sync-progress")).to_have_text("Syncing…")
expect(cancel).to_be_visible()
expect(cancel).to_be_enabled()
# --- the probes, inside the real clone --------------------------------
page_polls_at_start = len(page_polls)
prelude, left = _watch_git_prelude(page, app_url)
window = time.monotonic() - clicked
# The fixture pinned itself: the git prelude held the run long
# enough for the probe set to mean something.
assert window >= MIN_CLONE_WINDOW_S, (
f"the clone window was only {window:.1f}s (>= {MIN_CLONE_WINDOW_S}s "
"required) — the probe set proves nothing, retune BIG_COMMITS"
)
assert len(prelude) >= MIN_POLLS_IN_WINDOW, (
f"only {len(prelude)} status probes landed inside the clone window "
f"(>= {MIN_POLLS_IN_WINDOW} required at the UI's {UI_POLL_S}s cadence)"
)
_assert_served(prelude, "inside the real clone")
for _, body in prelude:
# The live run, mid-clone: running, no phase, no file — the
# clone/pull prelude reports nothing to show yet.
assert body["state"] == "running"
assert body["phase"] is None
assert body["current_file"] is None
assert body["files_done"] == 0 and body["files_total"] == 0
# The PAGE kept polling and kept getting answers through the clone.
assert len(page_polls) - page_polls_at_start >= MIN_POLLS_IN_WINDOW, (
f"the Sources page landed only {len(page_polls) - page_polls_at_start} "
"status 200s through the clone — its poll loop was starved"
)
# And it stayed in its live state: no error banner, no modal, the
# neutral running copy, the Cancel control still there.
expect(page.locator("#sync-progress-text")).to_have_text("Syncing…")
expect(btn).to_be_disabled()
expect(cancel).to_be_visible()
expect(page.locator("#sync-error-banner")).to_be_hidden()
assert page.locator(".sync-modal-backdrop").count() == 0
# The prelude ended where it must — the import's first phase, or the
# run's own terminal (the two-file mock import is ~1 s against a 2 s
# poll tick, so the ``import`` phase can be crossed between two
# probes). What may NEVER be the exit is a failure — a run that died
# in the clone is a broken fixture, not a responsive freeze.
assert left["state"] in {"running", "success"}, (
f"the run left the pipeline during the clone: {left}"
)
if left["state"] == "running":
assert left["phase"] == "import", left
assert _clone_finished(checkout_dir), (
"the prelude ended before the clone wrote its worktree — the "
"window the probes measured was not a clone"
)
# --- the success terminal ---------------------------------------------
body = _wait_sync_state(
page, app_url, {"success", "failed", "cancelled"},
timeout_s=RUN_SETTLE_TIMEOUT_MS / 1000,
)
assert body["state"] == "success", body
assert body["error"] is None
# The clone + the two tip files: the run reports a real import.
assert body["files_total"] >= 1 and body["files_done"] == body["files_total"]
assert body["phase"] is None and body["current_file"] is None
# The UI settles to the success shape within one poll tick.
expect(page.locator("#sync-label")).to_have_text(
SYNCED_LABEL, timeout=UI_SETTLE_TIMEOUT_MS
)
expect(btn).to_be_enabled()
expect(cancel).to_be_hidden()
expect(page.locator("#sync-error-banner")).to_be_hidden()
assert page.locator(".sync-modal-backdrop").count() == 0
line = page.locator("#sync-progress-text").inner_text()
assert RESULT_LINE.fullmatch(line), f"unexpected result line: {line!r}"
# The REAL clone's content is in the KB: the sentinel row, with the
# marker the fixture wrote.
with SessionLocal() as db:
sentinel_content = db.execute(
text(
"SELECT content FROM documents WHERE source = :s AND path = :p"
),
{"s": GIT_SOURCE_NAME, "p": SENTINEL_DOC},
).scalar_one()
assert SENTINEL in sentinel_content
# And the catalog shows it (drill source → notes → the sentinel row).
_go_top(page)
page.click(f'#folders-tbody a.folder-link:text-is("{GIT_SOURCE_NAME}")')
page.click('#folders-tbody a.folder-link:text-is("notes")')
expect(page.locator("#docs-tbody tr", has_text=SENTINEL_DOC)).to_have_count(1)
# ---------------------------------------------------------------------------
# 2. Phase 134 under asyncio.to_thread: cancel DURING the clone
# ---------------------------------------------------------------------------
def test_cancel_during_clone_reaches_terminal(
page: Page, app_url: str, checkout_dir: Path, db_ready: None
) -> None:
"""The cancel-during-clone contract under the off-loop scheduling
(decision A2's observable): with the checkout deleted the run
re-clones — a long git phase again — and the UI's Cancel click
round-trips in < 1.5 s. The run settles into the neutral
``cancelled`` terminal WITHOUT waiting for the git worker: the
sentinel worktree is still absent when the terminal lands and while
the abandoned clone keeps writing, every status probe is served in
< 1.5 s. The import never started (no documents for the source), and
the UI settles retry-ready with no error surface."""
page.set_default_timeout(30_000)
# Force a fresh clone for this run (the checkout is the previous
# test's completed one).
shutil.rmtree(checkout_dir, ignore_errors=True)
assert not checkout_dir.exists()
login(page, app_url)
btn = page.locator("#sync-btn")
cancel = page.locator("#sync-cancel-btn")
expect(btn).to_be_enabled()
expect(cancel).to_be_hidden()
btn.click()
expect(btn).to_be_disabled()
expect(cancel).to_be_visible()
# The deterministic layer: the run is IN the git prelude (running,
# no phase) — the cancel must land on the in-flight clone, not on
# the import.
body = _wait_sync_state(page, app_url, {"running"})
assert body["state"] == "running" and body["phase"] is None, body
# The owner's click, timed end to end: click → the browser's
# POST /api/sync/cancel → its response. Pre-phase-179 this request
# was queued behind the clone (task 01: ≈ the full clone).
clicked = time.monotonic()
with page.expect_response(
lambda resp: "/api/sync/cancel" in resp.url, timeout=UI_SETTLE_TIMEOUT_MS
):
cancel.click()
cancel_elapsed = time.monotonic() - clicked
assert cancel_elapsed < POLL_CEILING_S, (
f"the Cancel click round-tripped in {cancel_elapsed:.3f}s — the loop is "
"still parked by the clone, so the UI cannot even ask to stop a sync"
)
expect(cancel).to_be_disabled() # never stale: disabled on the first line
# Keep probing while the ABANDONED git worker is still running (the
# worktree appears only when clone finishes): the loop serves the
# whole HTTP surface while the thread runs to completion, and the
# run lands the cancelled terminal without waiting for it.
probes: list[tuple[float, dict[str, Any]]] = []
while_during_clone = 0
deadline = time.monotonic() + 60.0
terminal: dict[str, Any] | None = None
while time.monotonic() < deadline:
still_cloning = not _clone_finished(checkout_dir)
elapsed, body = _timed_status(page, app_url)
probes.append((elapsed, body))
if still_cloning:
while_during_clone += 1
if body["state"] != "running":
terminal = body
if not still_cloning:
break
time.sleep(0.5)
assert terminal is not None, "the cancelled terminal never landed"
assert terminal["state"] == "cancelled", terminal
# The phase-134 shape: intent, not failure.
assert terminal["error"] is None
assert terminal["detail"] == {}
assert terminal["started_at"] is not None and terminal["finished_at"] is not None
assert terminal["current_file"] is None and terminal["phase"] is None
assert terminal["current_summary"] is None
assert terminal["current_chunk"] == 0 and terminal["chunks_total"] == 0
# The cancel caught the run in the git prelude: no file was ever
# handed to the import, and the abandoned clone's result is never
# consumed (no half-cancelled index).
assert terminal["files_done"] == 0 and terminal["files_total"] == 0
with SessionLocal() as db:
n_docs = db.execute(
text("SELECT count(*) FROM documents WHERE source = :s"),
{"s": GIT_SOURCE_NAME},
).scalar_one()
assert n_docs == 0, n_docs
# A2's observable, pinned: enough probes to be meaningful, every one
# of them served — including the ones issued while the git thread
# was still copying the repo.
assert while_during_clone >= MIN_POLLS_IN_WINDOW, (
f"only {while_during_clone} probes landed while the abandoned clone was "
"still in flight — the cancelled terminal waited for the git worker "
"(or the clone finished before the cancel), so nothing pinned the "
"thread-runs-in-the-background contract"
)
_assert_served(probes, "during/after a cancelled clone")
# The neutral UI settle: "Sync cancelled", retry-ready, no error.
expect(page.locator("#sync-progress-text")).to_have_text(
"Sync cancelled", timeout=UI_SETTLE_TIMEOUT_MS
)
expect(page.locator("#sync-label")).to_have_text(
"Sync sources", timeout=UI_SETTLE_TIMEOUT_MS
)
expect(btn).to_be_enabled()
expect(btn).not_to_have_attribute("aria-busy")
expect(cancel).to_be_hidden()
expect(page.locator("#sync-error-banner")).to_be_hidden()
assert page.locator(".sync-modal-backdrop").count() == 0
tests/integration/test_sync_api.py
+35 -4
View File
@@ -280,6 +280,33 @@ def _poll(client: TestClient, want: str, timeout: float = 5.0) -> dict:
raise AssertionError(f"sync did not reach {want!r} within {timeout}s")
def _wait_phase(client: TestClient, want: str, timeout: float = 5.0) -> dict:
"""Poll ``GET /api/sync/status`` until ``phase == want`` (the phase
machine, phase 98 task 01), failing loudly if the run leaves
``running`` first.
Phase 179 (task 02) is why this exists: the sync's git ops now run
OFF the event loop (``asyncio.to_thread``), so how far the run has
progressed by the time the client issues its NEXT request is
genuinely concurrent — pre-fix the spawned task reached the import
span before the trigger's own response went out, and a test that
asserted a mid-run phase silently depended on that. Tests wait for
the phase instead."""
deadline = time.monotonic() + timeout
while True:
body = client.get("/api/sync/status").json()
assert body["state"] == "running", (
f"run left state {body['state']!r} before phase {want!r}: {body}"
)
if body["phase"] == want:
return body
if time.monotonic() >= deadline:
raise AssertionError(
f"sync did not report phase {want!r} within {timeout}s: {body}"
)
time.sleep(0.02)
class FakeImportSources:
"""Records every ``import_sources`` call; returns a canned summary."""
@@ -626,8 +653,10 @@ def test_double_trigger_while_running_returns_409(
monkeypatch.setattr(sync_api, "clone_or_pull", fake_clone)
_stub_probe(monkeypatch)
# The in-flight run takes a while (asyncio.sleep) so the second POST
# lands while it is still running.
fake_import = FakeImportSources(ImportSummary(files=1, added=1), delay=0.5)
# lands while it is still running (phase 179: 1.5 s, not 0.5 s — the
# run now yields the loop at its git ops, so the window the second
# POST and the phase wait fall into is wider on purpose).
fake_import = FakeImportSources(ImportSummary(files=1, added=1), delay=1.5)
monkeypatch.setattr(sync_api, "import_sources", fake_import)
monkeypatch.setattr(sync_api, "regenerate_overview", FakeOverview(ok=True))
monkeypatch.setattr(sync_api, "generate_folder_summaries", FakeFolderSummaries())
@@ -639,7 +668,10 @@ def test_double_trigger_while_running_returns_409(
assert r.status_code == 409
assert r.json() == {"detail": "a sync is already running"}
body = sync_client.get("/api/sync/status").json()
# Phase 179 (task 02): WAIT for the import phase — the run's
# progress is concurrent now that the git ops left the loop, so the
# next request no longer inherits a run that already ran past them.
body = _wait_phase(sync_client, "import")
assert body["state"] == "running"
assert body["started_at"] is not None
assert body["finished_at"] is None
@@ -647,7 +679,6 @@ def test_double_trigger_while_running_returns_409(
# Phase 98 (task 01): the in-flight run (parked in the fake
# import's delay) reports the import phase — the summary span has
# not started, so its counters are 0/0.
assert body["phase"] == "import"
assert body["current_summary"] is None
assert body["summaries_done"] == 0 and body["summaries_total"] == 0
tests/integration/test_sync_git_freeze.py
+630
View File
@@ -0,0 +1,630 @@
"""Integration: phase 179 — the owner's suspicion (``TODO.md`` L3,
verbatim): *"A long git clone seems to freeze the server? Investigate
to find out if this is true."*
**VERDICT (task 01): CONFIRMED. → FIXED (phase 179 task 02,
``asyncio.to_thread``).** A long ``git clone`` during a sync DID block
the app's event loop, and while it was blocked the ENTIRE HTTP surface
was stalled — including ``GET /api/sync/status``, the endpoint the UI
polls every 2 s, and even the dependency-free ``GET /api/health``. The
server did not fail; it FROZE — and the UI's status poll, the one
request that must stay live to watch a long sync, was among the
victims. Both git steps now run in a worker thread, and the probes
below are flipped to pin the server staying responsive.
**Mechanism (pre-fix, no ``to_thread`` anywhere).** ``POST /api/sync``
spawns the run with ``asyncio.create_task(_run_sync())``
(``app/api/sync.py``) — the coroutine runs on the app's SINGLE uvicorn
event loop. ``_run_sync`` called the per-source git steps as plain
synchronous calls — ``root = clone_or_pull(...)`` →
``scripts/git_sync.py::clone_or_pull`` → ``run_git`` →
``subprocess.run``. There was no ``asyncio.to_thread`` and no
``create_subprocess_exec`` anywhere in ``app/`` or ``scripts/``, so a
long clone parked the loop thread itself: no other coroutine —
including the ASGI dispatch of ANY incoming request, even sync-``def``
threadpool endpoints like ``/api/health`` — could be scheduled until
git returned.
**Measured PRE-fix (task 01, 3.0 s stubbed clone).** The
``GET /api/sync/status`` probe issued into the middle of the clone took
**≈3.0 s** (measured 3.04 s — the full remainder of the git op plus the
runner's yield-less tail); the ``GET /api/health`` probe in the same
window took **≈3.0 s** (measured 3.02 s — any endpoint on the loop
stalls); the trigger's own ``202`` was held ≈ 3.2 s. Idle, the same
endpoints answer in **milliseconds** (measured ≈ 0.001 s).
**Measured POST-fix (task 02, the same 3.0 s stubbed clone, the same
scenario).** The status probe issued into the middle of the clone took
**≈ 0.003 s** (0.0031 s), the second poll one second later the same
(0.0027 s), ``GET /api/health`` **≈ 0.003 s** (0.0033 s), the trigger's
``202`` **≈ 0.026 s**, and a ``POST /api/sync/cancel`` issued mid-clone
**≈ 0.004 s** with the ``cancelled`` terminal landing **≈ 0.006 s**
later — still INSIDE the abandoned clone's sleep, which is the proof
that the run no longer waits for the git worker while the worker itself
finishes on its own. The stub records the thread it ran on: pre-fix it
was the event-loop thread (identical idents), post-fix it is an
``asyncio`` worker thread (different ident) — asserted, so a git op that
slides back onto the loop fails this file even on a machine fast enough
to hide the latency.
**What phase 179 does NOT change:** the pipeline sequence, the run's
terminals (the stubbed run still lands ``success`` with the same
``detail``), and the phase-134 cooperative-cancel contract — a cancel
registered while a git op is in flight stops the run at the next
boundary (or right at the ``to_thread`` await, which is now the
common case), lands the ``cancelled`` terminal with ``error`` null and
``detail`` empty, and never resumes the pipeline with the abandoned
clone's result. Python threads are not interruptible: the git worker
runs its ``subprocess`` to completion, but the EVENT LOOP is free the
whole time.
**TestClient mechanics (why the trigger still rides a side thread).**
The shared app loop here is anyio's ``BlockingPortal`` thread. Firing
``POST /api/sync`` from the test thread would make the mid-clone probe
unfalsifiable — on a regressed (blocking) run the POST itself would be
held for the whole clone and only return once the git window had
CLOSED, so a later probe would be served instantly and pass on a frozen
server. With the trigger on its own thread the MAIN thread is a free
second client — the UI's 2 s poll — and the probe provably lands
mid-clone (the stub's ``finished_at is None`` pin). The trigger's own
latency is asserted too, in the post-fix direction (prompt, not held).
**The repro is deterministic and in-process:**
``app.api.sync.clone_or_pull`` / ``app.api.sync.file_commit_dates`` (the
module-level names imported in ``app/api/sync.py`` — patching the
``scripts.git_sync`` originals would NOT affect the runner) are
monkeypatched with stubs that record a ``time.monotonic()`` start/end,
the thread they ran on, and ``time.sleep(3.0)`` — the stub is a PLAIN
SYNC function, exactly like the real ``clone_or_pull``, because the
point under test is WHERE it runs. The git source rides the env fallback
(``BOR_GIT_SOURCES=file://<tmp repo>``, a fresh ``Settings`` on the
resolver's module — the dev ``.env`` never leaks in); the tmp repo is a
real one-commit git repo (the ``test_sync_cancel._git`` helper shape)
although the stub never actually clones it.
House patterns (``test_sync_api.py``): the ``sync_client`` fixture is a
**context-managed** ``TestClient`` — one app event loop across requests,
exactly how the app runs under uvicorn (without the context manager a
fresh loop per request would cancel the background task); the module
status/task/cancel-event reset + the ``git_sources`` / ``sources_meta``
/ ``folder_summaries`` global-state hygiene fixtures around every test;
the import / overview / folder-summary layers monkeypatched in
``app.api.sync`` so only the CLONE is the timing fixture.
"""
from __future__ import annotations
import asyncio
import subprocess
import threading
import time
from collections.abc import Callable, Iterator, Sequence
from datetime import datetime
from pathlib import Path
from typing import Any
import pytest
from fastapi.testclient import TestClient
from sqlalchemy import text
from sqlalchemy.orm import Session
from app.api import sync as sync_api
from app.config import Settings
from app.db import SessionLocal, db_available
from app.main import app as fastapi_app
from app.rag import git_sources as git_sources_resolver
from app.rag.importer import ImportSummary
from app.rag.llm import LLMClient
from tests.conftest import ADMIN_PASSWORD
# The timing fixture: a "long clone" of 3.0 s.
CLONE_SLEEP = 3.0
# POST-fix ceiling (phase 179 task 02): every request issued into the
# middle of the 3 s clone must be served in < 1.5 s — the phase's
# number, deliberately far above a warm-loop round trip (measured in
# milliseconds) and far below the clone itself, so a git op that slides
# back onto the event loop (task 01 measured >= 2.5 s of the same 3 s
# stub, 3.04 s actual) can never pass this pin.
PROBE_CEILING = 1.5
# The idle baseline ceiling: the host-slop canary — if the IDLE probe is
# slow, the host is too loaded to time anything and this suite's numbers
# mean nothing.
IDLE_CEILING = 1.0
@pytest.fixture(autouse=True)
def _fresh_sync_state() -> Iterator[None]:
"""House pattern (test_sync_api): the module-level status object +
task + cancel event are process-global — reset them around every
test (before AND after) so no terminal state / stale cancel bleeds."""
sync_api._status = sync_api.SyncStatus()
sync_api._task = None
sync_api._cancel_event = asyncio.Event()
yield
sync_api._status = sync_api.SyncStatus()
sync_api._task = None
sync_api._cancel_event = asyncio.Event()
@pytest.fixture(autouse=True)
def clean_git_sources(db: Session) -> Iterator[None]:
"""The env fallback only applies while the ``git_sources`` table is
EMPTY — truncate it around every test so ``BOR_GIT_SOURCES`` is
deterministically the origin of the run's single row."""
db.execute(text("TRUNCATE git_sources"))
db.commit()
yield
db.execute(text("TRUNCATE git_sources"))
db.commit()
@pytest.fixture(autouse=True)
def _reset_sources_version() -> Iterator[None]:
"""The fake import reports a CHANGED KB (added=1), so the runner's
phase-53 bump fires through its own short-lived ``SessionLocal`` —
pin the counter to the migration-0010 seed (0) around every test."""
if not db_available():
pytest.skip("Postgres not reachable — run `podman compose up -d db` first")
session = SessionLocal()
try:
session.execute(text("UPDATE sources_meta SET version = 0 WHERE id = 1"))
session.commit()
yield
finally:
session.execute(text("UPDATE sources_meta SET version = 0 WHERE id = 1"))
session.commit()
session.close()
@pytest.fixture(autouse=True)
def _clean_folder_summaries(db: Session) -> Iterator[None]:
"""``folder_summaries`` is global state the sync touches (the fake
generator never writes here, but the changed-KB branch runs through
the runner's own session) — truncate around every test."""
db.execute(text("TRUNCATE folder_summaries"))
db.commit()
yield
db.execute(text("TRUNCATE folder_summaries"))
db.commit()
@pytest.fixture()
def sync_client() -> Iterator[TestClient]:
"""Context-managed TestClient — one app event loop across requests
(the background task must survive between the POST and the probes;
this is precisely what makes the probes measure the loop's state —
starved pre-phase-179, free post-phase-179)."""
with TestClient(fastapi_app) as client:
yield client
def _settings(sources_dir: str) -> Settings:
"""Fresh settings (no .env file); the checkout root lands in tmp."""
return Settings(_env_file=None, sources_dir=sources_dir) # pyright: ignore[reportCallIssue]
def _stub_env(monkeypatch: pytest.MonkeyPatch, git_sources: str) -> None:
"""The resolver's env fallback, driven by a fresh ``Settings`` (the
dev ``.env`` never leaks in — the test_sync_api pattern)."""
monkeypatch.setattr(
git_sources_resolver,
"get_settings",
lambda: Settings(_env_file=None, git_sources=git_sources), # pyright: ignore[reportCallIssue]
)
def _login(client: TestClient) -> None:
r = client.post("/api/login", json={"password": ADMIN_PASSWORD})
assert r.status_code == 204, f"admin login failed: {r.status_code} {r.text}"
def _poll(client: TestClient, want: str, timeout: float = 15.0) -> dict:
"""Poll ``GET /api/sync/status`` until ``state == want`` (terminal).
Any other state before the deadline fails loudly. The default
timeout is generous so a wait never races the stub's tail; the
cancel test passes a SHORT one on purpose — the ``cancelled``
terminal must land while the abandoned clone is still sleeping
(phase 179: the run no longer waits for the git worker)."""
deadline = time.monotonic() + timeout
while time.monotonic() < deadline:
body = client.get("/api/sync/status").json()
if body["state"] == want:
return body
assert body["state"] == "running", (
f"unexpected state {body['state']!r} while waiting for {want!r}: {body}"
)
time.sleep(0.05)
raise AssertionError(f"sync did not reach {want!r} within {timeout}s")
def _git(cwd: Path, *args: str) -> None:
"""Run git in *cwd*; a non-zero exit fails the fixture loudly
(the ``tests/e2e/test_sync_cancel.py`` helper shape)."""
proc = subprocess.run(["git", *args], cwd=cwd, capture_output=True, text=True)
if proc.returncode != 0:
raise AssertionError(f"git {' '.join(args)} failed: {proc.stderr.strip()}")
def _make_repo(tmp_path: Path) -> Path:
"""A real one-commit git repo — the env-fallback source the runner
resolves. The stub NEVER clones it (content is irrelevant); it exists
so ``repo_name`` / ``clone_url_for`` resolve a real ``file://`` URL."""
repo = tmp_path / "freeze_repo.git"
(repo / "notes").mkdir(parents=True)
(repo / "notes" / "seed.md").write_text("# Seed\nfreeze-fixture content\n", encoding="utf-8")
_git(repo, "init", "-q")
_git(repo, "add", "-A")
_git(
repo,
"-c", "user.email=e@x", "-c", "user.name=t",
"-c", "commit.gpgsign=false", # the fixture commit never signs
"commit", "-qm", "init",
)
return repo
class _SlowClone:
"""The timing fixture: sync stubs for ``clone_or_pull`` /
``file_commit_dates`` (PLAIN SYNC functions — like the real ones,
so the only variable is WHERE the runner calls them: ON the loop
pre-phase-179, in a worker thread after the fix).
``clone_or_pull`` signals entry (``started``), records the
monotonic window, sleeps the simulated clone, and returns the tmp
repo's ``Path``; ``file_commit_dates`` answers ``{}``."""
def __init__(self, repo: Path, sleep: float = CLONE_SLEEP) -> None:
self.repo = repo
self.sleep = sleep
self.started = threading.Event()
self.started_at: float | None = None
self.finished_at: float | None = None
self.calls: list[tuple[str, Path, str | None]] = []
# Which thread the git op ran on, versus which thread awaited it
# (``loop_thread_ident``, filled by the fake ``check_models``
# that runs on the app's loop). PRE-fix the two were THE SAME
# thread — that identity IS the freeze; phase 179 makes them
# differ (the git op lands in a ``to_thread`` worker).
self.thread_ident: int | None = None
self.thread_name: str | None = None
self.loop_thread_ident: int | None = None
def clone_or_pull(self, url: str, dest: Path | str, branch: str | None = None) -> Path:
self.calls.append((url, Path(dest), branch))
self.thread_ident = threading.get_ident()
self.thread_name = threading.current_thread().name
self.started_at = time.monotonic()
self.started.set()
# THE (simulated) LONG CLONE: a blocking git op — exactly what
# ``run_git``'s ``subprocess.run`` does. PRE-fix it held the
# event loop thread and nothing else got scheduled until it
# returned; phase 179 runs it in a worker thread.
time.sleep(self.sleep)
self.finished_at = time.monotonic()
return self.repo
def file_commit_dates(self, root: Path | str) -> dict[str, datetime]:
return {}
class _FakeImport:
"""Canned changed-KB import (no files touched): records the runner's
wiring, returns ``added=1`` so the run takes the overview +
incremental-summaries branches and lands ``success``."""
def __init__(self) -> None:
self.sources: list[list[Path]] = []
self.doc_dates_maps: list[dict[str, dict[str, datetime]]] = []
self.prune_flags: list[bool] = []
async def __call__(
self,
sources: list[Path],
llm: LLMClient,
*,
prune: bool = False,
limit: int | None = None,
session: Session | None = None,
progress: Callable[[str, str, int, int], None] | None = None,
on_chunk_progress: Callable[[int, int], None] | None = None,
on_image_progress: Callable[[int, int], None] | None = None,
ignore_by_root: dict[str, list[str]] | None = None,
include_hidden_by_root: dict[str, bool] | None = None,
doc_dates_by_root: dict[str, dict[str, datetime]] | None = None,
) -> ImportSummary:
self.sources.append(list(sources))
self.prune_flags.append(prune)
self.doc_dates_maps.append(doc_dates_by_root or {})
return ImportSummary(files=1, added=1, updated=0, unchanged=0, pruned=0)
class _FakeOverview:
async def __call__(self, llm: LLMClient, session: Session | None = None) -> bool:
return True
class _FakeFolderSummaries:
async def __call__(
self,
db: Session,
llm: LLMClient,
*,
skip: bool = False,
only_missing: bool = False,
changed_docs: Sequence[tuple[str, str]] | None = None,
on_progress: Callable[[int, int, str, str], None] | None = None,
) -> dict[str, int]:
return {"generated": 0, "failed": 0, "pruned": 0}
def _install(
monkeypatch: pytest.MonkeyPatch, tmp_path: Path
) -> tuple[Path, _SlowClone, _FakeImport]:
"""Wire one stubbed sync run: env-fallback git source, tmp sources
root, stubbed probe + import + overview + summaries, and the
3 s-blocking clone stub on the ``app.api.sync`` module names."""
repo = _make_repo(tmp_path)
_stub_env(monkeypatch, f"file://{repo}")
monkeypatch.setattr(
sync_api, "get_settings", lambda: _settings(sources_dir=str(tmp_path / "bor"))
)
slow = _SlowClone(repo)
# Patch the module-level names imported at app/api/sync.py L233 —
# the runner calls THESE, not the scripts.git_sync originals.
monkeypatch.setattr(sync_api, "clone_or_pull", slow.clone_or_pull)
monkeypatch.setattr(sync_api, "file_commit_dates", slow.file_commit_dates)
async def fake_check_models(llm: LLMClient) -> None:
# No network — the clone is the only timing fixture. AND: this
# coroutine runs ON the app's event loop (``_run_sync`` awaits it
# there), so it is where the loop's OWN thread identity is
# recorded — the pin that the git op no longer shares it.
slow.loop_thread_ident = threading.get_ident()
monkeypatch.setattr(sync_api, "check_models", fake_check_models)
fake_import = _FakeImport()
monkeypatch.setattr(sync_api, "import_sources", fake_import)
monkeypatch.setattr(sync_api, "regenerate_overview", _FakeOverview())
monkeypatch.setattr(sync_api, "generate_folder_summaries", _FakeFolderSummaries())
return repo, slow, fake_import
def _trigger_from_side_thread(client: TestClient) -> tuple[threading.Thread, dict[str, Any]]:
"""Fire ``POST /api/sync`` from a SIDE thread and return immediately.
Why not POST from the test thread: it makes the mid-clone probe
unfalsifiable. If the git op ever slides back onto the event loop
(the regression this suite exists to catch), a test-thread POST is
held for the whole clone and only returns once the git window has
CLOSED — a probe issued after it would be served instantly and the
latency assertion would pass on a frozen server. With the trigger on
its own thread the MAIN thread is a free second client — the UI's 2 s
status poll — and the probe provably lands mid-clone (the stub's own
``finished_at is None`` pin below). The trigger's ``202`` is asserted
too, in the post-fix direction: phase 179 task 01 measured it held
for ≈ the full clone (its response dispatch rode the frozen loop);
it must now come back promptly."""
result: dict[str, Any] = {}
def _fire() -> None:
t0 = time.monotonic()
r = client.post("/api/sync")
result["status"] = r.status_code
result["elapsed"] = time.monotonic() - t0
thread = threading.Thread(target=_fire, name="sync-trigger", daemon=True)
thread.start()
return thread, result
# --- anonymous gating (house 403 pins) -------------------------------------
def test_anonymous_gets_403_on_sync_surface(client: TestClient) -> None:
"""The probes run as admin; the anonymous 403s on the two endpoints
they exercise stay pinned (router ``require_admin``)."""
assert client.get("/api/sync/status").status_code == 403
assert client.post("/api/sync").status_code == 403
# --- the mid-clone responsiveness probes (phase 179) ------------------------
def test_long_git_clone_no_longer_freezes_the_event_loop(
sync_client: TestClient, monkeypatch: pytest.MonkeyPatch, db: Session, tmp_path: Path
) -> None:
"""THE contract (phase 179 task 02 — the flip of task 01's repro).
With the git ops off the loop, the same scenario answers:
S0 (baseline) — idle, ``GET /api/sync/status`` answers in ms.
S1 (PRIMARY, the flip) — the status probe issued into the middle of
the 3 s stubbed clone — the exact request the UI's 2 s poll is —
is served in < 1.5 s (measured in ms) and reports the LIVE run
(``state=running``, ``phase``/``current_file`` null: the
clone/pull prelude). The stub's own recording proves the probe
landed INSIDE the clone window (``finished_at`` still None when
the response came back), so this is loop-freeness, not a clone
that finished early.
S2 — the git op ran on a DIFFERENT thread than the one that awaited
it (pre-fix: the same thread — that identity is the freeze).
S3 — a second poll ~1 s later (the UI's cadence) is answered just as
fast while the same clone is still running.
S4 — the trigger's own ``202`` is released promptly (task 01
measured it held for ≈ the whole clone; its response dispatch no
longer rides a parked loop).
The run still completes ``success`` with the same detail as before —
phase 179 changed scheduling, not behavior — and the fixture is left
clean for the next test."""
repo, slow, fake_import = _install(monkeypatch, tmp_path)
_login(sync_client)
# S0: idle, the status endpoint answers in milliseconds (this is
# the endpoint that must stay live to watch a sync — phase 32).
t0 = time.monotonic()
r = sync_client.get("/api/sync/status")
idle_elapsed = time.monotonic() - t0
assert r.status_code == 200 and r.json()["state"] == "idle"
assert idle_elapsed < IDLE_CEILING, f"idle status took {idle_elapsed:.3f}s — host too slow?"
thread, posted = _trigger_from_side_thread(sync_client)
# Give the trigger request a head start onto the loop, then wait
# (bounded) for the run to enter the blocking clone stub.
time.sleep(0.2)
assert slow.started.wait(10.0), "the run never reached the clone step"
# S1 — THE PROBE (PRIMARY): issued into the middle of the stubbed
# clone. PRE-fix (task 01) this request could not even be
# DISPATCHED — it returned only once the clone was done (≈ 3.0 s).
# Post-fix the clone occupies a to_thread worker, so the loop
# answers it in milliseconds.
t0 = time.monotonic()
probe = sync_client.get("/api/sync/status")
probe_elapsed = time.monotonic() - t0
assert probe.status_code == 200
body_live = probe.json()
assert body_live["state"] == "running"
# The clone/pull prelude reports no file and no phase (phase 64/98).
assert body_live["current_file"] is None
assert body_live["phase"] is None
assert probe_elapsed < PROBE_CEILING, (
f"status probe took {probe_elapsed:.3f}s during a {CLONE_SLEEP}s clone — "
f"the event loop is still being parked by the git op "
f"(expected < {PROBE_CEILING}s; pre-phase-179 it took >= 2.5s)"
)
# The probe landed INSIDE the git op, not after it: the stub had
# entered and had NOT exited when the response came back. Without
# this pin a too-fast fixture could fake the post-fix numbers.
assert slow.started_at is not None
assert slow.finished_at is None, (
"the status probe did not land inside the clone window — the "
"latency above measured an idle server, not a cloning one"
)
# S2: the git op does NOT run on the thread that awaited it. PRE-fix
# ``clone_or_pull`` executed on the event loop thread itself (the
# two idents matched) — that shared thread is exactly what froze.
assert slow.thread_ident is not None and slow.loop_thread_ident is not None
assert slow.thread_ident != slow.loop_thread_ident, (
f"the git op ran on the event loop thread ({slow.thread_name}) — "
"it must run in an asyncio.to_thread worker"
)
# S3: the UI's 2 s poll cadence keeps working THROUGH the clone —
# another poll ~1 s in, same fast answer, same live run.
time.sleep(1.0)
t0 = time.monotonic()
second = sync_client.get("/api/sync/status")
second_elapsed = time.monotonic() - t0
assert second.status_code == 200 and second.json()["state"] == "running"
assert second_elapsed < PROBE_CEILING, (
f"second status poll took {second_elapsed:.3f}s during the clone"
)
assert slow.finished_at is None, "the clone ended before the second poll"
# S4: the trigger's own 202 is released promptly now (task 01:
# held for ≈ the whole clone by the frozen loop).
thread.join(timeout=15.0)
assert not thread.is_alive(), "the trigger POST never returned"
assert posted["status"] == 202
assert posted["elapsed"] < PROBE_CEILING, (
f"trigger POST returned in {posted['elapsed']:.3f}s — its response "
f"dispatch is still queued behind the git op"
)
# Fixture cleanliness + the run's health: the stub returns, so the
# run completes success — the SAME terminal as before the fix
# (phase 179 moved scheduling only, it changed no behavior).
# (The terminal lands on whichever branch the stubbed root yields:
# the canned added=1 import → success with the overview + summary
# branches and the phase-53 bump.)
body = _poll(sync_client, "success")
assert body["error"] is None
assert body["detail"]["overview"] is True
assert body["detail"]["sources_version"] == 1
# The stub ran exactly once, on the env-resolved row (bare URL,
# branch None) into BOR_SOURCES_DIR/<repo-name>/.
assert slow.calls == [(f"file://{repo}", tmp_path / "bor" / "freeze_repo", None)]
assert fake_import.sources == [[repo]]
assert fake_import.prune_flags == [True]
# The runner fed the per-root date map from the stubbed git layer.
assert fake_import.doc_dates_maps == [{str(repo): {}}]
def test_health_stays_responsive_during_a_long_clone(
sync_client: TestClient, monkeypatch: pytest.MonkeyPatch, db: Session, tmp_path: Path
) -> None:
"""The blast radius, flipped (phase 179 task 02): task 01 found the
freeze covered the WHOLE HTTP surface — even ``GET /api/health``
(dependency-free, no admin, plain threadpool handler) took ≈ the
full clone. Post-fix that endpoint answers in < 1.5 s (measured in
ms) while the same 3 s clone is still in flight (the stub's
``finished_at`` pin), and the run still lands ``success``."""
_, slow, _ = _install(monkeypatch, tmp_path)
_login(sync_client)
thread, _posted = _trigger_from_side_thread(sync_client)
time.sleep(0.2)
# Enter the clone window through the stub's own signal (the probe
# below must be the request that lands inside the window, not a
# warm-up call).
assert slow.started.wait(10.0), "the run never reached the clone step"
t0 = time.monotonic()
r = sync_client.get("/api/health")
elapsed = time.monotonic() - t0
assert r.status_code == 200
assert elapsed < PROBE_CEILING, (
f"health probe took {elapsed:.3f}s during a {CLONE_SLEEP}s clone — "
f"the loop is still parked by the git op (expected < {PROBE_CEILING}s)"
)
assert slow.finished_at is None, "the health probe did not land inside the clone"
thread.join(timeout=15.0)
_poll(sync_client, "success")
def test_cancel_during_a_clone_lands_cancelled_with_a_free_loop(
sync_client: TestClient, monkeypatch: pytest.MonkeyPatch, db: Session, tmp_path: Path
) -> None:
"""Phase 134's cooperative cancel, re-pinned under ``to_thread``
(phase 179 task 02): a cancel registered mid-clone lands the
``cancelled`` TERMINAL without waiting for the git worker.
``POST /api/sync/cancel`` is answered promptly (202, < 1.5 s), the
run's await on the git worker is interrupted so the terminal lands
well BEFORE the abandoned clone's 3 s sleep would have ended (the
2 s poll deadline below is inside that sleep), and the terminal
keeps the phase-134 shape — ``error`` null, ``detail`` empty, no
error copy for the UI. What does NOT change: the git worker itself
is not interruptible, it finishes on its own — and the import that
would have consumed its result never runs (no half-cancelled
index)."""
_, slow, fake_import = _install(monkeypatch, tmp_path)
_login(sync_client)
thread, _posted = _trigger_from_side_thread(sync_client)
time.sleep(0.2)
assert slow.started.wait(10.0), "the run never reached the clone step"
t0 = time.monotonic()
r = sync_client.post("/api/sync/cancel")
cancel_elapsed = time.monotonic() - t0
assert r.status_code == 202, f"cancel not accepted: {r.status_code} {r.text}"
assert cancel_elapsed < PROBE_CEILING, (
f"the cancel request itself took {cancel_elapsed:.3f}s — the loop is "
"still parked by the git op, so the UI cannot even ask to stop a sync"
)
# The terminal lands inside the still-running clone sleep (< 3 s of
# it remains here): the loop is free and the run was unblocked at
# its await, it did not have to wait for the git worker.
body = _poll(sync_client, "cancelled", timeout=2.0)
assert body["error"] is None
assert body["detail"] == {}
assert slow.finished_at is None, (
"the cancelled terminal waited for the git worker — the run is "
"still parked behind the blocking subprocess"
)
# And the abandoned clone's import never ran: the run stopped at the
# cancel, it did not resume the pipeline with a late result.
assert fake_import.sources == []
thread.join(timeout=15.0)
tests/unit/test_sync_button.py
+41 -11
View File
@@ -2337,17 +2337,47 @@ def test_image_position_clears_at_phase_transitions_and_terminal(
# wake, which a parked loop never receives); the loop is drained
# afterwards so the runner's terminal step (the
# ``except CancelledError`` conversion) lands before the test reads
# the status.
# the status. Because the action owns the loop thread, waiting for
# run progress inside it goes through ``_pump_until`` — phase 179
# (task 02) moved the runner's git ops into ``asyncio.to_thread``, so
# the run no longer reaches the import gate inside the one loop
# iteration that created it and a blocking ``Event.wait()`` here
# deadlocks the loop the run needs to advance.
# * ``_start_run_via_api`` — the OLD house pattern (blocking threading
# gates; the loop thread may park inside a sync span — the
# clone/``file_commit_dates``) with the main thread orchestrating
# the event set / releases.
# gates, the loop turning on its own thread) with the main thread
# orchestrating the event set / releases — the actions run OUTSIDE the
# loop, so plain ``Event.wait()`` is fine there.
def _pump_until(
loop: asyncio.AbstractEventLoop,
event: threading.Event,
*,
why: str,
timeout: float = 5.0,
) -> None:
"""Wait for *event* while KEEPING the run's loop turning (phase 179,
task 02).
The loop-thread actions of :func:`_run_via_start_sync` need run
progress, and that progress is now produced by coroutines plus
``asyncio.to_thread`` completions this very thread has to service —
pre-fix the prelude (including the blocking git calls) ran to the
import gate before the action was ever reached, so a plain
``Event.wait()`` could not deadlock. Pump the loop instead: same
wait, same thread, no deadlock."""
deadline = time.monotonic() + timeout
while not event.is_set():
if time.monotonic() >= deadline:
raise AssertionError(why)
loop.run_until_complete(asyncio.sleep(0.01))
def _fast_clone(url: str, dest: Path | str, branch: str | None = None) -> Path:
"""A non-gated ``clone_or_pull`` — the loop thread must STAY FREE
for the loop-thread action, so nothing in the prelude may block it
(the import's gate is an ``asyncio.to_thread`` park — loop-safe).
for the loop-thread action, so nothing in the prelude blocks here
(the import's gate is an ``asyncio.to_thread`` park — loop-safe,
and since phase 179 so are the runner's git calls).
Phase 135: accepts the row's branch pin (the third argument —
``None`` for this file's rows)."""
dest = Path(dest)
@@ -2445,7 +2475,7 @@ def test_cancel_is_409_idle_and_after_a_terminal_run(
# A full (uncancelled) run to the success terminal ...
def act(loop: asyncio.AbstractEventLoop) -> None:
assert fake_import.started.wait(5.0), "the run never reached the import"
_pump_until(loop, fake_import.started, why="the run never reached the import")
fake_import.release.set()
task = sync_api._task
assert task is not None
@@ -2490,7 +2520,7 @@ def test_cancel_endpoint_stops_the_in_flight_run(
_patch_sync_seams(monkeypatch, tmp_path, fake_import, _fast_clone)
def act(loop: asyncio.AbstractEventLoop) -> dict[str, str]:
assert fake_import.started.wait(5.0), "the run never reached the import"
_pump_until(loop, fake_import.started, why="the run never reached the import")
# Phase 152 (task 04): the live image position in flight when
# the cancel converts was fired through the runner's OWN
# _image_hook closure (image_pairs[0] — the fake fired it
@@ -2559,7 +2589,7 @@ def test_unrequested_cancel_is_never_swallowed_and_never_converts(
_patch_sync_seams(monkeypatch, tmp_path, fake_import, _fast_clone)
def act(loop: asyncio.AbstractEventLoop) -> None:
assert fake_import.started.wait(5.0), "the run never reached the import"
_pump_until(loop, fake_import.started, why="the run never reached the import")
assert sync_api._cancel_event.is_set() is False
task = sync_api._task
assert task is not None
@@ -2615,7 +2645,7 @@ def test_fresh_run_clears_a_stale_cancel_event(
_patch_sync_seams(monkeypatch, tmp_path, first_import, _fast_clone)
def act1(loop: asyncio.AbstractEventLoop) -> dict[str, str]:
assert first_import.started.wait(5.0), "run 1 never reached the import"
_pump_until(loop, first_import.started, why="run 1 never reached the import")
return loop.run_until_complete(sync_api.cancel_sync())
try:
@@ -2640,7 +2670,7 @@ def test_fresh_run_clears_a_stale_cancel_event(
monkeypatch.setattr(sync_api, "import_sources", second_import)
def act2(loop: asyncio.AbstractEventLoop) -> None:
assert second_import.started.wait(5.0), "run 2 never reached the import"
_pump_until(loop, second_import.started, why="run 2 never reached the import")
# start_sync cleared the stale event before the task was
# created — by the import park it is definitely clear.
assert sync_api._cancel_event.is_set() is False