diff --git a/backend/app/knowledge/pipeline_runner.py b/backend/app/knowledge/pipeline_runner.py index 8e4831d8..8fccc543 100644 --- a/backend/app/knowledge/pipeline_runner.py +++ b/backend/app/knowledge/pipeline_runner.py @@ -594,7 +594,22 @@ async def _run_steps( # on) because that flag governs the broader "enhanced retrieval" # path; parsed_files is non-empty only when code_graph_enabled is # True, so this step is implicitly gated on both flags. - if settings.hybrid_retrieval_enabled and state.parsed_files: + # + # ...and on the checkpoint, since 2026-08-27. This step wrote + # `complete_step` and nothing read it, so every resume ran it again: + # measured at 2 300 s (38.3 min) on a 9 981-file repository, the most + # expensive step in the pipeline and expensive on purpose — + # EMBEDDING_UPSERT_BATCH_SIZE is 8 to hold the worker inside its memory + # quota. A full rebuild there needs ~2 h and the job's ceiling cut it off + # inside `generate_docs`; resuming re-entered this step and spent the 38 + # minutes over, so attempt N+1 reached no further than attempt N and no + # number of attempts could finish. Raising the ceiling alone only moves + # where that loop stalls. + if ( + settings.hybrid_retrieval_enabled + and state.parsed_files + and "code_symbol_embed" not in done + ): symbol_count = sum(len(pf.symbols) for pf in state.parsed_files.values()) async with tracker.step( wf_id, diff --git a/backend/tests/unit/knowledge/test_resume_skips_the_expensive_embed.py b/backend/tests/unit/knowledge/test_resume_skips_the_expensive_embed.py new file mode 100644 index 00000000..365844cd --- /dev/null +++ b/backend/tests/unit/knowledge/test_resume_skips_the_expensive_embed.py @@ -0,0 +1,100 @@ +"""A resume must not repay the most expensive step it already finished. + +`_run_steps` reads the completed-step set once (`pipeline_runner.py:168`) and gates +exactly four steps on it: `detect_changes` (:265), `cleanup_deleted` (:481), +`project_profile` (:510) and `cross_file_analysis` (:648). `code_symbol_embed` +writes `complete_step` and **nothing reads it**, so every resume runs it again. + +Measured in production on 2026-08-27, tracker timings from one full rebuild: + + 11:37:23 code_symbol_embed: started + 12:15:43 code_symbol_embed: completed 2 300 s (38.3 min) + +That is the single most expensive step in the pipeline, and it is expensive by +design: `EMBEDDING_UPSERT_BATCH_SIZE` was cut 200 → 8 to keep the worker inside its +memory quota, trading ~17 % wall clock for ~552 MiB. + +Consequence, observed the same day. A full rebuild of that repository needs about +two hours; the manual job's ceiling cut it off at 3 600 s inside `generate_docs`. +Resuming re-entered `code_symbol_embed` and spent the 38 minutes over again — so +attempt N+1 reached no further than attempt N, and no number of attempts could +finish the job. A ceiling raise alone cannot fix that; it only moves where the +loop stalls. + +The pattern to copy is already in the same file: `generate_docs` resumes at +*document* granularity through `processed_doc_paths` (:970, "N already done"). This +step needs the coarse version of that at minimum — skip when the checkpoint says it +finished. + +Deliberately NOT gated, and left alone: `ast_parse` re-runs because parsed files +live in memory rather than in the checkpoint (:555), and `graph_build` re-runs +because it merges into the stored graph so unchanged files survive. +""" + +from __future__ import annotations + +import re +from pathlib import Path + +PIPELINE = Path(__file__).resolve().parents[3] / "app" / "knowledge" / "pipeline_runner.py" +SOURCE = PIPELINE.read_text(encoding="utf-8") + + +def _block(step: str, width: int = 1400) -> str: + """The source around a step's `tracker.step(... "" ...)` call.""" + idx = SOURCE.index(f'"{step}",') + return SOURCE[max(0, idx - width) : idx + 400] + + +class TestTheExpensiveStepIsSkippedWhenAlreadyDone: + def test_code_symbol_embed_consults_the_completed_set(self) -> None: + block = _block("code_symbol_embed") + assert re.search(r'"code_symbol_embed"\s+not\s+in\s+done', block), ( + "code_symbol_embed records completion and no one reads it — a resume " + "repays 38 minutes and can never get past the step that cut it off" + ) + + def test_it_still_records_its_completion(self) -> None: + """The skip is only sound while the write is there to be read.""" + assert 'complete_step(db, cp_id, "code_symbol_embed")' in SOURCE + + def test_the_flag_gate_survives_the_resume_gate(self) -> None: + """`hybrid_retrieval_enabled` and a non-empty `parsed_files` still decide + whether the step runs at all; the resume check is an addition, not a + replacement.""" + block = _block("code_symbol_embed") + assert "settings.hybrid_retrieval_enabled" in block + assert "state.parsed_files" in block + + +class TestTheGatedSetIsExactlyWhatWasIntended: + """A list of gated steps is a claim about which work is safe to skip. Asserting + it means a future step that starts recording completion cannot quietly join or + leave the set without this file saying so.""" + + def test_every_step_that_should_be_skippable_is(self) -> None: + for step in ( + "detect_changes", + "cleanup_deleted", + "project_profile", + "cross_file_analysis", + "code_symbol_embed", + ): + assert re.search(rf'"{step}"\s+(not\s+)?in\s+done', SOURCE), step + + def test_the_two_deliberate_re_runs_stay_ungated(self) -> None: + """Skipping either would be a correctness bug, not a saving: `ast_parse` + rebuilds in-memory state nothing else can supply, and `graph_build` merges + into the stored graph.""" + for step in ("ast_parse", "graph_build"): + assert not re.search(rf'"{step}"\s+(not\s+)?in\s+done', SOURCE), ( + f"{step} is now gated on the checkpoint — it re-runs by design, and " + "skipping it leaves a later step reading empty state" + ) + + +def test_generate_docs_keeps_its_finer_grained_resume() -> None: + """The reason this file argues for a coarse skip rather than against fine-grained + resume: the fine-grained version already exists one step later, and is the shape + `code_symbol_embed` should eventually take.""" + assert "processed_doc_paths" in SOURCE or "processed_paths" in SOURCE diff --git a/docs/qa-audit/issues.md b/docs/qa-audit/issues.md index 8e4cc065..5d838498 100644 --- a/docs/qa-audit/issues.md +++ b/docs/qa-audit/issues.md @@ -93,11 +93,11 @@ frontend **A** (563 smells, 7 SOLID). |---|---| | 🔴 Critical | 0 | | 🟠 High | **0** | -| 🟡 Medium | 1 | +| 🟡 Medium | 3 | | 🟢 Low | 25 | | ⚪ Info | 12 | -*Counted 2026-08-27, not estimated: **33 open `F-` rows and 76 struck** by `grep -cE '^\| F-'` / `grep -cE '^\| ~~F-'` over this file, plus **5 open `CB-` rows** those two commands do not see. The severity table above counts all 38 open rows of both kinds, which is why it does not match the `F-` figure — the two measure different sets and each says which. Both are derived from the rows themselves.* +*Counted 2026-08-27, not estimated: **33 open `F-` rows and 76 struck** by `grep -cE '^\| F-'` / `grep -cE '^\| ~~F-'` over this file, plus **7 open `CB-` rows** those two commands do not see. The severity table above counts all 40 open rows of both kinds, which is why it does not match the `F-` figure — the two measure different sets and each says which. Both are derived from the rows themselves.* *(R1+R2 closed 4 High + 8 Medium + 3 Low. R3 (`fbf8112`) closed 2 High (F-SSH-08, F-RULE-01) + 5 Medium (F-RULE-05, F-DG-07/09, F-GRAPH-01, F-LEARN-07) + 1 Low (F-SSH-06). The 2026-07-19 UX @@ -401,8 +401,9 @@ maintainability / reliability risks. | ~~CB-SEN1~~ | ✅ | ~~**Sentry was reachable by two secrets neither scrubbing layer could see**~~ — the built-in `EventScrubber` matches key names and its 33-key default carries neither `dsn` nor `database_url`; `before_send` matched values but walked only `exception.values`, `logentry` and `breadcrumbs`. A key of either name in `extra` or `contexts` was caught by **neither**. Urgent rather than theoretical from the moment `SENTRY_DSN` was set in production. **Fixed 2026-08-26** (#230): layer 1 wired with the denylist extended 33 → 39, layer 2 walks `extra` and `contexts` recursively and depth-bounded, host preserved. Fifteen tests, one of them an assertion about *Sentry* — that layer 1 alone still leaks values — so the redundancy question re-opens from a red test rather than from memory. | | ~~CB-SEN2~~ | ✅ | ~~**The Sentry release would have been blank on the container stack**~~ — `HEROKU_SLUG_COMMIT`, the value every guide names, is populated only for slug (buildpack) deploys. This app is on the **container** stack, where the variable exists and is always **empty** (measured on v271 *after* `runtime-dyno-metadata` was enabled). Issues would attach to a release with no commits and suspect-commit attribution would silently do nothing. Enabling the labs feature was necessary and not sufficient, and nothing would have said so. **Fixed 2026-08-26** (#231): the commit is baked into the image via `--build-arg GIT_SHA` → `ENV RELEASE`; verified in production, `RELEASE == main` HEAD. The empty string is the trap — `os.getenv` returns `""` there, not `None`, so an `is None` check would have accepted it; a test catches that form. | | CB-UX1 | ⚪ | **102 UX scenarios carry a verification older than 30 days.** 110 of 127 were dated 2026-07-19 while 152 commits had landed since; five were re-audited 2026-08-26 and the ceiling now stands at 105, of which 102 still have a changed Coverage file under them. Ordered and computable: `python3 scripts/ux_verification_status.py --backlog 2026-07-19`. The ceiling in `tests/unit/docs/test_ux_scenarios.py` may fall but not rise. | Re-audit in batches, worst first; date each verdict and add an `SCN-NNN` anchor so a machine can check it (21 of 127 have one). | -| ~~CB-OPS1~~ | 🟢 | **CLOSED, measured 2026-08-27.** A forced full re-index of the 9 981-file customer repository ran on Standard-2X and logged **zero `R14` and zero `R15`**, with `mem=` absent from the whole window — Heroku emits those only over quota, so absence is the evidence. `graph_build` completed over the full symbol set, which is the case this row said no run had exercised. Before the resize: 170 × R14 and 2 × R15 in 6.5 h with a 1 143 MiB peak against a 512 MiB quota. | +| CB-OPS1 | 🟡 | **RE-OPENED 2026-08-27, and the earlier closure was the same mistake in a new form.** It was struck on "a full re-index logged zero `R14`/`R15`" — but every run measured for that claim died in or before `code_symbol_embed`, so nothing had yet reached the late steps where memory actually peaks. The first run that did reach them produced, at 12:32–12:34 inside `generate_docs`: `mem=1135M(100.1%)` with **4 × R14**, on Standard-2X. What the resize genuinely bought is still real and is now stated precisely: before it, 170 × R14 **and 2 × R15** in 6.5 h with a 1 143 MiB peak against a 512 MiB quota — a fatal overrun. Now: over quota, no `R15`, the process survives. Marginal, not clear. | Measure the peak across a rebuild that reaches `pipeline_end`, not one that is cut off; `generate_docs` is the step to watch, not `graph_build`. Decide from that whether the next size up is needed or whether `generate_docs` should hold less state. | | CB-OPS2 | 🟡 | **The nightly cron can rebuild a repository the "Re-index repository" button never can.** `run_repo_index_task` is called by two ARQ jobs carrying two ceilings: the cron's `run_daily_project_knowledge_sync` at 7200 s, and `run_repo_index` at 1800 s. Measured on the same repository from `indexing_runs`: nightly `completed` in **42.4 min** (08-25 22:00), manual `TimeoutError` at **exactly 1800.02 s** inside `_run_code_symbol_embed` (08-27 09:30). Diagnosed once already — AUD-0819-20 added the knob on 2026-08-19 for this failure and left the default at the value just measured as too small. **Fix written, not yet in production:** `repo_index_job_timeout_seconds` defaults to 3600 on branch `fix/repo-index-ceiling`, with both orderings asserted in `tests/unit/services/test_repo_index_ceiling.py`. | Deploy, then force one manual full re-index and require it to reach `pipeline_end`; strike this row on that evidence, not on the merge. | +| CB-OPS3 | 🟡 | **A worker restart during a repo index loses the run, and nothing retries it.** Measured 2026-08-27: release `v279` restarted the worker at 10:59:34 UTC, 37 min into an index. arq logged `shutdown on SIGTERM ◆ 0 jobs complete ◆ 2 failed ◆ 0 retries ◆ 1 ongoing to cancel`, exited 143, and the fresh worker started at 10:59:45 with **no job re-queued** — no `run_repo_index` or `run_daily_project_knowledge_sync` start appears in the next 30 min of worker log. `WorkerSettings` sets neither `retry_jobs` nor `max_tries`, so arq's defaults were in force and still did not retry. The reaper correctly flipped both rows to `failed / stale run reaped`, visible in `error_log` since N3. The restart was a deploy of our own, not an incident — the finding is that a routine deploy costs a whole index. | Decide the semantics before coding: re-enqueue on shutdown (risking a double run against `_indexing_locks` and the advisory locks), or leave it to the cron and make the loss explicit in the UI. Not a silent implementation choice. | **Verified-good in the codebase audit (no issue):** SQL identifier quoting (`connectors/base.py:262` doubles quotes correctly), credential exposure (`ConnectionResponse` returns no secrets; Fernet at