diff --git a/CHANGELOG.md b/CHANGELOG.md index 89479941..132c9eef 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,52 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/). ## [Unreleased] +### Fixed — the nightly cron could rebuild a repository the "Re-index repository" button never could + +`run_repo_index_task` is the repo-index pipeline, and two ARQ jobs call it with two +different ceilings: + +| Entry | ARQ job | Ceiling | +|---|---|---| +| nightly cron | `run_daily_project_knowledge_sync` | 7200 s | +| "Re-index repository", `POST /api/projects/{id}/index` | `run_repo_index` | **1800 s** | + +Both numbers measured against the same repository, from `indexing_runs`: + + 08-25 22:00 completed 42.4 min nightly + 08-27 09:30 TimeoutError 30.0 min manual + + 1800.02s ! run_repo_index failed, TimeoutError + pipeline_runner.py:1468 in _run_code_symbol_embed + +2 544 s of work fits under one ceiling and can never fit under the other. The repository +rebuilt itself unattended at 3 a.m. and failed every time a person asked — which is the +worse half, because the button is what an operator presses after shipping a fix. + +**It had been diagnosed once already.** AUD-0819-20 gave the job its own knob on +2026-08-19 for exactly this failure, then left the default at 1800 — the value just +measured as too small — with a note that a repository needing longer could "say so +without a code edit". Nothing in production said so. A knob whose default is the +known-bad value moves the defect, it does not close it. + +The same day's memory fix had made it worse and the connection was never drawn: +`EMBEDDING_UPSERT_BATCH_SIZE` went 200 → 8, buying ~552 MiB with ~17 % more wall clock, +spent inside the step the ceiling was cutting off. The old caution — that raising the +ceiling helps only a worker that is not swapping — was correct and its precondition is +now met and measured: Standard-2X, a full rebuild with zero R14 and zero R15 (CB-OPS1). + +`repo_index_job_timeout_seconds` now defaults to **3600**, and the invariant is a test +rather than a comment: it must clear the measured rebuild with 25 % headroom, and it must +stay below the daily sync's ceiling, which contains it plus a DB index plus a code↔DB +sync. A third test fails if any long job is ever registered without its own knob again — +the shape that produced AUD-0819-20. + +Not affected, checked rather than assumed: the checkpoint recorded all five completed +steps for the killed run (`indexing_checkpoint_step`), so a resume skips them. The empty +`completed_steps` column on the row is legacy and no longer written +(`checkpoint_service.py:10-15`). + + ### Fixed — `matched` was an opinion, and eleven tables that do not exist got it `sync_status` is the word a customer reads on the code↔DB screen. `matched` says *your diff --git a/CLAUDE.md b/CLAUDE.md index cbab69b4..97e47dd3 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -215,7 +215,7 @@ Worker functions (`backend/app/worker.py`): - `run_db_index` — schema indexing for a connection - `run_code_db_sync` — code↔DB cross-reference -- `run_repo_index` — Git repo knowledge pipeline +- `run_repo_index` — Git repo knowledge pipeline (per-function timeout `repo_index_job_timeout_seconds`, **3600 s since 2026-08-27**). The same pipeline also runs *inside* `run_daily_project_knowledge_sync`, which carries its own 7200 s ceiling — so until the raise, the nightly cron rebuilt a 9 981-file repository in 42.4 min while every press of "Re-index repository" died at exactly 1800 s inside `code_symbol_embed`. Keep this knob **below** `daily_knowledge_sync_job_timeout_seconds`, which contains it plus a DB index plus a code↔DB sync; the ordering is asserted in `tests/unit/services/test_repo_index_ceiling.py`, not just commented. - `run_batch` — batch query execution - `run_analytics_collect` — collect one analytics connection's reports into its fact tables (per-function timeout `analytics_collect_job_timeout_seconds`) diff --git a/backend/.env.example b/backend/.env.example index e0618774..6b0b24a9 100644 --- a/backend/.env.example +++ b/backend/.env.example @@ -403,9 +403,14 @@ CORS_ORIGINS=["http://localhost:3000","http://localhost:3100","https://checkmyda # ANALYTICS_COLLECT_JOB_TIMEOUT_SECONDS=1800 # Ceiling for one repo-index job, in seconds. The repo index is the longest job in # the system; before 2026-08-19 it was the only long one with no knob and inherited -# ARQ's hardcoded 1800 s. Raising this only helps a worker that is NOT swapping — -# on an over-quota dyno it buys a longer crawl, not a finished index (AUD-0819-20). -# REPO_INDEX_JOB_TIMEOUT_SECONDS=1800 +# ARQ's hardcoded 1800 s. Measured on a 9 981-file repository: a full rebuild takes +# 42.4 min, so 1800 s could never finish one and 3600 s finishes it with headroom. +# Keep this BELOW DAILY_KNOWLEDGE_SYNC_JOB_TIMEOUT_SECONDS, which grants the same +# pipeline its budget plus a DB index and a code↔DB sync — mismatching the two is +# how the nightly cron rebuilt a repository the manual button never could. +# Raising it only helps a worker that is NOT swapping: on an over-quota dyno it buys +# a longer crawl, not a finished index (AUD-0819-20). +# REPO_INDEX_JOB_TIMEOUT_SECONDS=3600 # How long a `running` batch may sit before another attempt may take its claim # (F-SCHED-07). `run_batch` inherits ARQ's class-level job_timeout of 1800 s, so past # that the previous attempt is provably dead — arq cancelled it. Matching the two is the diff --git a/backend/app/config.py b/backend/app/config.py index 10655bf2..a96bd399 100644 --- a/backend/app/config.py +++ b/backend/app/config.py @@ -517,10 +517,33 @@ def _fix_database_url(self) -> "Settings": # `job_timeout = 1800` while its two newer siblings read their own settings. # Production hit exactly that on 2026-08-19: `1800.09s ! run_repo_index failed, # TimeoutError` with `code_symbol_embed` still running after 29 minutes over - # 8,552 files. The default is unchanged; a repo that genuinely needs longer can - # now say so without a code edit. Note that raising this is only a fix when the - # worker is not swapping — on an over-quota dyno it buys a longer crawl. - repo_index_job_timeout_seconds: int = 1800 + # 8,552 files. It got a knob and the default was left at 1800 — the value that + # had just been measured as too small. + # + # Raised to 3600 on 2026-08-27, because leaving it produced the same failure + # eight days later and the reason to withhold the raise had gone. Two + # measurements, both from `indexing_runs` on the one real customer repository: + # + # 08-25 22:00 completed 42.4 min nightly cron, ceiling 7200 s + # 08-27 09:30 TimeoutError 30.0 min manual re-index, ceiling 1800 s + # + # The same pipeline, the same 2 544 s of work, two ceilings — because the cron + # runs it *inside* `run_daily_project_knowledge_sync`, which carries + # `daily_knowledge_sync_job_timeout_seconds`. So the repository rebuilt + # unattended at 3 a.m. and could never rebuild when a person pressed + # "Re-index repository", which is the path an operator reaches for after a fix. + # + # The old note said raising this only helps when the worker is not swapping. + # That precondition is now met and measured: the dyno is Standard-2X and a full + # rebuild logged zero R14 and zero R15 (CB-OPS1, 2026-08-27). What is left of + # that caution is the opposite lesson — the same day's memory fix cut + # `EMBEDDING_UPSERT_BATCH_SIZE` from 200 to 8 and bought ~552 MiB with ~17 % more + # wall clock, spent inside the very step this ceiling was cutting off. + # + # Invariant, asserted in `tests/unit/services/test_repo_index_ceiling.py`: this + # stays below `daily_knowledge_sync_job_timeout_seconds`, which contains it plus + # a DB index plus a code↔DB sync. + repo_index_job_timeout_seconds: int = 3600 # F-SCHED-07: how long a `running` batch may sit before another attempt may take # its claim. `run_batch` inherits ARQ's class-level `job_timeout` (1800 s), so past diff --git a/backend/tests/unit/services/test_repo_index_ceiling.py b/backend/tests/unit/services/test_repo_index_ceiling.py new file mode 100644 index 00000000..fed6b6e5 --- /dev/null +++ b/backend/tests/unit/services/test_repo_index_ceiling.py @@ -0,0 +1,139 @@ +"""One pipeline must not have two ceilings depending on which door it came through. + +`run_repo_index_task` is the repo-index pipeline. Two ARQ jobs call it, and each +carries its own timeout: + +| Entry | ARQ job | Setting carrying the ceiling | +|---|---|---| +| nightly cron | `run_daily_project_knowledge_sync` | `daily_knowledge_sync_job_timeout_seconds` | +| the button, `POST .../index` | `run_repo_index` | `repo_index_job_timeout_seconds` | + +Measured on the one real customer repository in production, `indexing_runs` for +`kind='index_repo'`: + + 08-25 22:00 completed 42.4 min <- nightly, ceiling 7200 s + 08-27 09:30 TimeoutError 30.0 min <- manual, ceiling 1800 s + + 1800.02s ! 33f44e65d24b48bd9795717bc21b0285:run_repo_index failed, TimeoutError + pipeline_runner.py:1468 in _run_code_symbol_embed + +The same 2 544 s of work fits under one ceiling and cannot fit under the other, so +the repository rebuilds unattended at 3 a.m. and never rebuilds when a person asks +for it. That is the worse half: the manual button is what an operator reaches for +after a fix, and it is the path that cannot finish. + +**This was diagnosed once already.** AUD-0819-20 gave the job its own knob on +2026-08-19 precisely because "production hit the hardcoded 1800 s with +`code_symbol_embed` still running after 29 minutes" — and left the default at the +value that had just been measured as too small, with a note that a repository +needing longer "can now say so without a code edit". Nobody said so; neither +`REPO_INDEX_JOB_TIMEOUT_SECONDS` nor its sibling is set in production. A knob whose +default is the known-bad value relocates the defect, it does not fix it. + +The same day's memory fix made it worse and the connection was not drawn: +`EMBEDDING_UPSERT_BATCH_SIZE` was cut from 200 to 8, trading ~17 % wall clock for +~552 MiB. That 17 % is spent inside the step the ceiling now cuts off. + +Two orderings are asserted below, and each fails differently. Losing the first +means the manual path cannot finish work the automatic path can. Losing the second +means the containing job would be cut off before the step it contains. +""" + +from __future__ import annotations + +import re +from pathlib import Path + +from app.config import Settings + +BACKEND = Path(__file__).resolve().parents[3] + +#: Longest full rebuild that ever *completed*, in seconds — `indexing_runs`, 42.4 min. +#: Runs longer than this on record all end `stale run reaped`, meaning their +#: heartbeat had stopped (the N1 defect, fixed 2026-08-25); their wall clock is +#: not evidence of work taking that long. +MEASURED_FULL_REBUILD_SECONDS = 2544 + +_DEFAULTS = Settings.model_fields + + +def _default(name: str) -> int: + return int(_DEFAULTS[name].default) + + +class TestTheManualPathCanFinishWhatTheNightlyPathCan: + def test_the_repo_index_ceiling_clears_the_measured_rebuild(self) -> None: + ceiling = _default("repo_index_job_timeout_seconds") + assert ceiling > MEASURED_FULL_REBUILD_SECONDS, ( + f"a full rebuild of the one real customer repository took " + f"{MEASURED_FULL_REBUILD_SECONDS} s and the manual ceiling is {ceiling} s — " + "the button cannot finish work the cron finishes" + ) + + def test_it_clears_it_with_headroom(self) -> None: + """A ceiling set to the last measurement is a ceiling that fails on the next + commit. The rebuild grows with the repository, and the memory fix already + spends ~17 % of it.""" + ceiling = _default("repo_index_job_timeout_seconds") + measured = MEASURED_FULL_REBUILD_SECONDS + assert ceiling >= measured * 1.25, ( + f"{ceiling} s leaves under 25 % headroom over a measured {measured} s" + ) + + +class TestTheContainingJobOutlivesWhatItContains: + """The daily sync runs the repo index, then the DB index, then the code↔DB sync, + in one job. Its ceiling must therefore be strictly the larger one — if it were + not, the cron would be cut off inside a step that was still within its own + budget, and the failure would be attributed to the step.""" + + def test_daily_sync_gets_the_larger_budget(self) -> None: + repo = _default("repo_index_job_timeout_seconds") + daily = _default("daily_knowledge_sync_job_timeout_seconds") + assert daily > repo, f"daily sync {daily} s must exceed the repo index {repo} s it contains" + + def test_the_daily_sync_really_does_contain_it(self) -> None: + """Asserted rather than assumed: the ordering above is only an invariant while + one job calls the other. If the call goes away, this test says so instead of + the ordering quietly becoming arbitrary.""" + service = (BACKEND / "app" / "services" / "daily_knowledge_sync_service.py").read_text( + encoding="utf-8" + ) + assert "run_repo_index_task" in service + + +class TestEveryLongJobHasAKnobAndNoneIsHardcoded: + """`run_repo_index` was the only long job reading the class-level `job_timeout`, + which is why it was the one that could not be raised without a deploy. The check + is that no *registered* function is left in that position again.""" + + def test_the_class_level_default_is_a_floor_not_a_ceiling_for_long_jobs(self) -> None: + worker = (BACKEND / "app" / "worker.py").read_text(encoding="utf-8") + block = worker[worker.index(" functions = [") :] + block = block[: block.index("]")] + for long_job in ( + "run_repo_index", + "run_daily_project_knowledge_sync", + "run_analytics_collect", + ): + line = next(ln for ln in block.splitlines() if long_job in ln) + idx = block.index(line) + window = block[max(0, idx - 120) : idx] + assert "_arq_func_with_timeout" in window, ( + f"{long_job} is registered without its own timeout and inherits the " + "hardcoded class-level job_timeout — the exact shape of AUD-0819-20" + ) + + def test_the_knob_is_reachable_from_the_environment(self) -> None: + """A default nobody can override in production is a code edit per repository.""" + example = (BACKEND / ".env.example").read_text(encoding="utf-8") + assert "REPO_INDEX_JOB_TIMEOUT_SECONDS" in example + + +def test_a_non_positive_ceiling_still_refuses_to_boot() -> None: + """Raising the default must not disturb the guard that makes `0` an error rather + than an accidental "no timeout".""" + config = (BACKEND / "app" / "config.py").read_text(encoding="utf-8") + assert re.search( + r"if self\.repo_index_job_timeout_seconds <= 0:\s*\n\s*raise ValueError", config + ) diff --git a/backend/tests/unit/test_task_queue.py b/backend/tests/unit/test_task_queue.py index 4aad1f4f..c749f01d 100644 --- a/backend/tests/unit/test_task_queue.py +++ b/backend/tests/unit/test_task_queue.py @@ -274,8 +274,15 @@ def test_repo_index_registered_with_its_own_configurable_timeout(monkeypatch): `analytics_collect_job_timeout_seconds`. Production hit that hardcoded ceiling on 2026-08-19: `1800.09s ! run_repo_index failed, TimeoutError` with `code_symbol_embed` still running after 29 minutes on a repo of 8,552 files. - The default stays 1800 — a knob, not a silent behaviour change — but a repo - that genuinely needs longer can now say so without a code edit. + This test used to pin the literal 1800, which is how a default measured as too + small came to look deliberate: the knob landed, the value did not move, and a + green test asserted the bad number. It hit production again on 2026-08-27 — + `1800.02s ! run_repo_index failed, TimeoutError` — while the nightly cron + rebuilt the same repository in 42.4 min under its own 7200 s ceiling. The + default is now 3600 and the assertion below compares the registration against + the setting, which is the wiring this test is named for; the value itself is + argued in `tests/unit/services/test_repo_index_ceiling.py`, where the + measurement lives. """ import types @@ -294,7 +301,9 @@ def fake_func(coroutine, **kwargs): "run_repo_index must be registered with an explicit timeout, not left on the " "class-level job_timeout" ) - assert names["run_repo_index"] == {"timeout": 1800} + from app.config import settings + + assert names["run_repo_index"] == {"timeout": settings.repo_index_job_timeout_seconds} # The raw coroutine must no longer be registered bare beside the wrapped one. bare = [f for f in w.WorkerSettings.functions if getattr(f, "__name__", "") == "run_repo_index"] assert bare == [] diff --git a/docs/qa-audit/issues.md b/docs/qa-audit/issues.md index 098247ba..8e4cc065 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 | 0 | +| 🟡 Medium | 1 | | 🟢 Low | 25 | -| ⚪ Info | 13 | +| ⚪ Info | 12 | -*Counted 2026-08-26, 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 **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.* *(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,7 +401,8 @@ 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 | ⚪ | **Worker peak memory is unverified at full load.** The Standard-1X → Standard-2X resize removed R14/R15 (170/2 in a 6.5 h window before; **0/0** since, including the 2026-08-26 02:00 CEST daily sync which completed all four runs). But the 1 143 MB peak came from `graph_build` / `generate_docs` over 25 421 symbols, and no run since has rebuilt the graph — the index has been incremental with no qualifying changes, and `clustering_enabled` is now off. The quota is 1 024 MB, so a full rebuild is still the open question. | Force one full re-index (`force_full`) on a quiet window and watch for `mem=` lines; the absence of any is the evidence, since Heroku emits them only over quota. | +| ~~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-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. | **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