Skip to content

fix(lcm): FTS parity COUNT(*) ran under _LOAD_LOCK on every engine load (freeze #3) - #966

Merged
Kyzcreig merged 2 commits into
mainfrom
fix/lcm-fts-parity-offload
Sep 24, 2026
Merged

Kyzcreig merged 2 commits into
mainfrom
fix/lcm-fts-parity-offload

Conversation

@Kyzcreig

@Kyzcreig Kyzcreig commented Sep 24, 2026 •

Copy link
Copy Markdown
Collaborator

Card: t_d3963974. Not merged. No deploy and no gateway restart; the operator owns both.

Root cause

_fts_needs_rebuild_structural (db_bootstrap.py:2420-2432 on main) ran SELECT COUNT(*) FROM messages (SCAN messages USING COVERING INDEX idx_msg_session_ts, 2.5M rows) and COUNT(*) FROM messages_fts_docsize on every MessageStore/SummaryDAG construction, under _LOAD_LOCK. Cold measurement on an APFS clone of the fleet DB: 13.4 s of a 17.9 s MessageStore() init. Live on 2026-09-24: 163x PHASE=context_engine_load_slow, held 49-64 s, waited up to 120 s. The two autocommit COUNTs could also straddle an ingest: 15/300 false mismatches, each followed by a full inline FTS rebuild (held 779.8 s, <=12 waiters, from py-spy samples).

Provenance

Fix

Fix:

  • The parity check moves to _fts_count_parity_mismatch. It never runs on
    the throttle=True (load) path. A metadata marker
    (fts_parity_checked_at:) throttles it to once per
    LCM_FTS_PARITY_CHECK_INTERVAL_HOURS (default 6 h). When due, it runs
    on the existing background integrity thread (own connection). A
    mismatch sets the /lcm doctor integrity flag instead of rebuilding
    inline. Both counts are read in one snapshot.
  • Explicit repair (throttle=False) and /lcm doctor still run parity
    synchronously.
  • A no-op load writes nothing:
    • _clear_integrity_failed runs only after a real repair. Before, it
      also erased the background corruption flag on every load.
    • The messages_dedup_v1 and schema_version upserts are marker-gated.
    • The integrity claim uses a 1 s busy timeout, not 30 s.
  • Lifecycle GC (on_session_start, every agent init):
    • no longer holds BEGIN IMMEDIATE across two SELECT DISTINCT
      session_id full scans;
    • uses indexed per-session probes;
    • runs at most once per 6 h per process.
  • _backfill_search_content no longer rewrites NULL over NULL for
    undecryptable rows. That rewrite fired msg_fts_update on every boot.

Evidence

RED (new test, unmodified plugins @ df43599):

E       AssertionError: engine load / session start full-scans a guarded table (the Apollo-freeze class):
E         SELECT COUNT(*) FROM "messages"  ->  SCAN messages USING COVERING INDEX idx_msg_session_ts
E         SELECT COUNT(*) FROM "messages_fts_docsize"  ->  SCAN messages_fts_docsize
E         SELECT DISTINCT session_id FROM messages  ->  SCAN messages USING COVERING INDEX idx_msg_session_ts
E         SELECT DISTINCT session_id FROM summary_nodes  ->  SCAN summary_nodes USING COVERING INDEX idx_nodes_session_node
E       sqlite3.OperationalError: database is locked
E               Failed: engine construction needed the write lock (issued a write on the load path): database is locked
E       AssertionError: an ordinary (no-op) open erased the background scan's corruption flag
E       assert (None is not None)
FAILED tests/context_engine/test_lcm_init_cost_regression.py::test_second_open_issues_no_full_scan_of_guarded_tables
FAILED tests/context_engine/test_lcm_init_cost_regression.py::test_engine_construction_needs_no_write_lock
FAILED tests/context_engine/test_lcm_init_cost_regression.py::test_ordinary_open_keeps_background_corruption_flag
3 failed, 1 passed in 4.21s

GREEN: 4 passed in 5.56s. Full tests/context_engine/: 393 passed in 50.15s. ruff: clean.

Deploy (operator)

After merge to main: ~/.hermes/fleet/deploy.sh (fast-forwards the runtime tree to fork/main, then restarts through safe-gateway-restart). --no-restart stages the deploy only. New knob: LCM_FTS_PARITY_CHECK_INTERVAL_HOURS (default 6).


View with [code]smith Autofix with [code]smith
Need help on this PR? Tag @codesmith-bot with what you need. Autofix is disabled.

Apollo added 2 commits September 24, 2026 05:39
…ad (freeze #3)

Card t_d3963974. Third Apollo boot-cost freeze. The cause:
_fts_needs_rebuild_structural ran `SELECT COUNT(*) FROM messages`
(SCAN messages USING COVERING INDEX, 2.5M rows) plus
`COUNT(*) FROM messages_fts_docsize` on EVERY MessageStore/SummaryDAG
construction, under plugins.context_engine._LOAD_LOCK. Measured on an APFS
clone of the fleet DB: 13.4 s of a 17.9 s cold MessageStore() init. The
two autocommit COUNTs could also straddle a concurrent ingest. They gave a
false mismatch 15/300 times, and each mismatch triggered a full inline
FTS drop+rebuild. That happened twice on 2026-09-24: held 779.8 s, 12
turns queued.

Provenance: the count came in with the original vendor import 8b86963
(2026-06-16) and was carried unchanged through re-vendor 27b6178.
#887/#902/#903 did not touch it. #903's plan check exempted
USING COVERING INDEX and skipped messages_fts*, so it passed on this code.

Fix:
- The parity check moves to _fts_count_parity_mismatch. It never runs on
  the throttle=True (load) path. A metadata marker
  (fts_parity_checked_at:<fts>) throttles it to once per
  LCM_FTS_PARITY_CHECK_INTERVAL_HOURS (default 6 h). When due, it runs
  on the existing background integrity thread (own connection). A
  mismatch sets the /lcm doctor integrity flag instead of rebuilding
  inline. Both counts are read in one snapshot.
- Explicit repair (throttle=False) and /lcm doctor still run parity
  synchronously.
- A no-op load writes nothing:
  - _clear_integrity_failed runs only after a real repair. Before, it
    also erased the background corruption flag on every load.
  - The messages_dedup_v1 and schema_version upserts are marker-gated.
  - The integrity claim uses a 1 s busy timeout, not 30 s.
- Lifecycle GC (on_session_start, every agent init):
  - no longer holds BEGIN IMMEDIATE across two SELECT DISTINCT
    session_id full scans;
  - uses indexed per-session probes;
  - runs at most once per 6 h per process.
- _backfill_search_content no longer rewrites NULL over NULL for
  undecryptable rows. That rewrite fired msg_fts_update on every boot.

Test: test_lcm_init_cost_regression now traces engine construction +
on_session_start on the loading thread. It fails on ANY SCAN of messages,
messages_fts*, summary_nodes and nodes_fts*, covering index included
(only LIMIT-bounded statements are exempt). It also asserts that a
steady-state load needs no write lock and preserves the corruption flag.
RED on df43599 (3 failed); GREEN with this change;
tests/context_engine: 393 passed.
@Kyzcreig

Copy link
Copy Markdown
Collaborator Author

🤖 merged-by: aegis · lane: incident-recovery · gate: BYPASS: No terminal FleetReview record for PR #966 yet; active Apollo outage, scoped Aegis review and all required CI green; retain merge-queue integration gate · why: Apollo production LCM freeze #3: 2.8M-row parity scan and false rebuild race; deterministic RED/GREEN, 394 context_engine tests green, required CI green; Ace explicitly requested merge/deploy ASAP

@Kyzcreig
Kyzcreig added this pull request to the merge queue Sep 24, 2026
Merged via the queue into main with commit dc228d5 Sep 24, 2026
55 checks passed
@Kyzcreig
Kyzcreig deleted the fix/lcm-fts-parity-offload branch September 24, 2026 13:18
@Kyzcreig Kyzcreig added the fleetreview:post-merge Ask FleetReview to review this MERGED pull (merge commit vs first parent) label Sep 24, 2026
Kyzcreig added a commit that referenced this pull request Sep 24, 2026
…ndex for the whole rebuild (t_d3963974 follow-up to #966)

Third defect of freeze #3, not covered by #966: repair_external_content_fts ran
DROP/CREATE VIRTUAL TABLE/'rebuild'/DROP+CREATE TRIGGER as separately autocommitted
statements (legacy isolation opens no implicit txn for DDL). For the 13-28 min rebuild
other connections saw messages_fts missing ('no such table', live 05:10) or empty
(docsize=0 vs 2.79M on disk). Now: BEGIN IMMEDIATE .. one COMMIT, rollback on error;
no-op loads still take no write lock.

test_lcm_fts_atomic_rebuild.py: RED on dc228d5 (engine-load structural path torn;
failed rebuild left index dropped). The explicit-repair path passed only because
#966's parity-marker write opens a txn first. tests/context_engine 397 passed.
github-merge-queue Bot pushed a commit that referenced this pull request Sep 24, 2026
…sed replays reported lost (t_43e058b7) (#961)

* fix: retain session prompt across route metadata writes (#958)

Verified targeted session-state, restore, accounting, and model-resume tests: 236 passed, 1 pre-existing dashboard-auth fixture warning deselected. Reproduced NULL from billing route before fix.

Co-authored-by: Kyzcreig <9063726+Kyzcreig@users.noreply.github.com>

* fix(gateway): restart follow-ups keep adapter-granted admission; refused replays reported lost (t_43e058b7)

Argus r8 N1 (t_e253d9d5): SessionSource.to_dict drops is_bot / role_authorized /
delivered_via_upstream_relay / profile_route_rejected, so a spooled follow-up
admitted only by ALLOW_BOTS, ALLOWED_ROLES or the relay was refused as
"Unauthorized user" on boot replay, its spool file acked, and
restart_followup_lost logged 0 lines.

Trust model: to_dict stays wire-safe (unchanged). The spool record carries the
flags in a separate `admission` block and the whole record is HMAC-SHA256'd
with a per-home 0600 key (<home>/gateway/restart_followups.key). On load the
flags are restored only if the MAC verifies; otherwise no trust flag is
restored (only fail-closed profile_route_rejected is honoured) and
PHASE=restart_followup_untrusted is logged. Live policy is still re-evaluated
by the normal intake. A replay the intake refuses (unauthorized /
profile_route_rejected) now logs PHASE=restart_followup_lost with reason.

MF (same review): AST contract that the post-turn draining site spools
pending_event itself, not None.

Verified: new real stop->boot e2e (human/bot/role/relay, forged, tampered,
gate-closed-during-restart, to_dict class guard) 8/8; on base 3 admission arms
fail, human control passes. Focused restart suites 49/49. Mutants: MAC
unchecked, refusal unreported, admission unrestored, MF pending_event=None all
KILLED. Argus probe_r8_source_authz_real_intake: B/R PRESERVED, CONTROL ok.
Session/authz/startup-restore suites 445 passed.

* fix(kanban): judge goal deliverables before completion; fail open for operator errors (#960)

* fix(kanban): grade goal deliverables before completion and isolate judge errors

Verified 81 targeted tests pass (one ACP-dependent test excluded). Mutating the completion rubric makes the first-completion regression fail as expected.

* refactor(kanban): one shared goal-mode handoff gate for CLI and tool surfaces

Argus r1 (t_c4e23682): _goal_mode_handoff_rejection was byte-identical in
tools/kanban_tools.py and hermes_cli/kanban.py; only the tool copy was
test-gated, so 4 CLI mutants survived (Issue NousResearch#38367 two-copies class).

- goals.kanban_handoff_rejection is now the single predicate (judge with
  completion_handoff=True; owned worker retries then blocks transient on
  judge error; operator fails open with a judge_error event; caller's conn).
- Both surfaces' complete + request-review delegate to it, injecting only
  their run-id resolver and judge-availability probe.
- CLI tests drive the real `kanban complete` / `request-review` argv path
  (build_parser -> kanban_command): completion_handoff reaches the judge and
  the card closes; real judge prompt accepts first completion; owned-worker
  500 -> 2 calls, blocked transient, error on stderr, rc!=0; review gated.
- AST contract: exactly one function in the tree calls the judge with
  completion_handoff, and both surface wrappers delegate to it.

Verified: 86 passed, 1 deselected (inherited ModuleNotFoundError: acp, also
red on ce0c9d3). Mutation matrix: baseline green precondition, 16/16 KILLED
by named failing tests (M01-M13 re-targeted at the shared helper + W1-W9
wiring/duplicate-predicate mutants).

---------

Co-authored-by: Kyzcreig <9063726+Kyzcreig@users.noreply.github.com>

* fix(kanban): resume dependency-wait PR and page stranded ready cards (#952)

* fix(kanban): respawn guard honors worker dependency_wait->promoted resume; add requeue_task + stuck-guard probe

t_7d7ff489. Rule 4 active_pr no longer strands a card whose own dependency block (kind=dependency) postdates the newest PR comment and whose promotion has not yet spawned. requeue_task emits operator-intent 'requeued' for READY cards. respawn_guard_stuck_tasks lists cards held by active_pr >= 30 min.

* fix(kanban): surface guarded ready cards and provide requeue verb

Verify dependency_wait promotion dispatches once and subsequent crash is guarded; CLI requeue and one-shot alert tests pass (168 passed, 1 skipped in focused suites). t_7d7ff489.

* test(kanban): keep corruption probe independent of watcher call count

Verified: corrupt-board regression 2 passed, 22 deselected; ruff and diff check pass. Original two failures reproduced on clean fork base.

* fix(kanban): keep PR continuation through status comments and unobserved ticks

Verified 213 passed, 2 skipped across focused DB/CLI/watcher suites; subprocess stdin guard passed.

* fix(kanban): consume event-ordered PR requeue intent

Verified 183 passed, 1 skipped across DB/CLI/watcher; ruff and subprocess stdin guard pass. Same-second event-order mutant fails the regression test.

* docs(kanban): state one-shot PR intent ordering

* fix(kanban): bind PR comments to events and consume dependency intent

Verified real dispatcher regressions RED before fix, then 210 passed, 2 skipped in focused DB/CLI/watcher suite; ruff and subprocess guard passed.

* fix(kanban): pin READY requeue to PR comment identity

Legacy same-second inline audit comments can share author and length; requeue snapshots the PR row id and remains one-shot. Verified 211 passed, 2 skipped; ruff clean.

* fix(kanban): snapshot comment identity for every resume intent

Verified focused DB/CLI/watcher/core suite: 217 passed, 2 skipped. Legacy equal-second strict mutant fails the intended arm.

* fix(kanban): guard-stuck age ignores data events; board-scoped recovery command

- respawn_guard_stuck_tasks: only kinds that can change the active_pr answer
  (_RESPAWN_GUARD_FAILURE_RESET_KINDS + dependency_wait + spawned, or a guard
  decline for another reason) restart the continuous-guard age; comments,
  heartbeats, attachments are data.
- render_operator_command(board, verb, *args): single renderer, always emits
  --board <slug>; clear_verb uses it; watcher passes the probed board.
- test_triage_resolve_records_who_and_why: expect after_comment_id ==
  max(task_comments.id) at emit time (CI slice 15/16 red).

Verified: new tests RED on 581299d (4 failed), GREEN here; recovery
command executed via real CLI on default and secondary boards (rc0);
no-board renderer mutant fails; 244 passed/1 skipped on db/triage/
watchers/cli/boards; ruff clean.

---------

Co-authored-by: Kyzcreig <9063726+Kyzcreig@users.noreply.github.com>

* fix(lcm): FTS parity COUNT(*) ran under _LOAD_LOCK on every engine load (freeze #3) (#966)

* fix(lcm): FTS parity COUNT(*) ran under _LOAD_LOCK on every engine load (freeze #3)

Card t_d3963974. Third Apollo boot-cost freeze. The cause:
_fts_needs_rebuild_structural ran `SELECT COUNT(*) FROM messages`
(SCAN messages USING COVERING INDEX, 2.5M rows) plus
`COUNT(*) FROM messages_fts_docsize` on EVERY MessageStore/SummaryDAG
construction, under plugins.context_engine._LOAD_LOCK. Measured on an APFS
clone of the fleet DB: 13.4 s of a 17.9 s cold MessageStore() init. The
two autocommit COUNTs could also straddle a concurrent ingest. They gave a
false mismatch 15/300 times, and each mismatch triggered a full inline
FTS drop+rebuild. That happened twice on 2026-09-24: held 779.8 s, 12
turns queued.

Provenance: the count came in with the original vendor import 8b86963
(2026-06-16) and was carried unchanged through re-vendor 27b6178.
#887/#902/#903 did not touch it. #903's plan check exempted
USING COVERING INDEX and skipped messages_fts*, so it passed on this code.

Fix:
- The parity check moves to _fts_count_parity_mismatch. It never runs on
  the throttle=True (load) path. A metadata marker
  (fts_parity_checked_at:<fts>) throttles it to once per
  LCM_FTS_PARITY_CHECK_INTERVAL_HOURS (default 6 h). When due, it runs
  on the existing background integrity thread (own connection). A
  mismatch sets the /lcm doctor integrity flag instead of rebuilding
  inline. Both counts are read in one snapshot.
- Explicit repair (throttle=False) and /lcm doctor still run parity
  synchronously.
- A no-op load writes nothing:
  - _clear_integrity_failed runs only after a real repair. Before, it
    also erased the background corruption flag on every load.
  - The messages_dedup_v1 and schema_version upserts are marker-gated.
  - The integrity claim uses a 1 s busy timeout, not 30 s.
- Lifecycle GC (on_session_start, every agent init):
  - no longer holds BEGIN IMMEDIATE across two SELECT DISTINCT
    session_id full scans;
  - uses indexed per-session probes;
  - runs at most once per 6 h per process.
- _backfill_search_content no longer rewrites NULL over NULL for
  undecryptable rows. That rewrite fired msg_fts_update on every boot.

Test: test_lcm_init_cost_regression now traces engine construction +
on_session_start on the loading thread. It fails on ANY SCAN of messages,
messages_fts*, summary_nodes and nodes_fts*, covering index included
(only LIMIT-bounded statements are exempt). It also asserts that a
steady-state load needs no write lock and preserves the corruption flag.
RED on df43599 (3 failed); GREEN with this change;
tests/context_engine: 393 passed.

* test(lcm): lock parity-race repro and document restart meltdown

---------

Co-authored-by: Apollo <apollo@angventures.io>

* fix(gateway): restart follow-ups keep adapter-granted admission; refused replays reported lost (t_43e058b7)

Argus r8 N1 (t_e253d9d5): SessionSource.to_dict drops is_bot / role_authorized /
delivered_via_upstream_relay / profile_route_rejected, so a spooled follow-up
admitted only by ALLOW_BOTS, ALLOWED_ROLES or the relay was refused as
"Unauthorized user" on boot replay, its spool file acked, and
restart_followup_lost logged 0 lines.

Trust model: to_dict stays wire-safe (unchanged). The spool record carries the
flags in a separate `admission` block and the whole record is HMAC-SHA256'd
with a per-home 0600 key (<home>/gateway/restart_followups.key). On load the
flags are restored only if the MAC verifies; otherwise no trust flag is
restored (only fail-closed profile_route_rejected is honoured) and
PHASE=restart_followup_untrusted is logged. Live policy is still re-evaluated
by the normal intake. A replay the intake refuses (unauthorized /
profile_route_rejected) now logs PHASE=restart_followup_lost with reason.

MF (same review): AST contract that the post-turn draining site spools
pending_event itself, not None.

Verified: new real stop->boot e2e (human/bot/role/relay, forged, tampered,
gate-closed-during-restart, to_dict class guard) 8/8; on base 3 admission arms
fail, human control passes. Focused restart suites 49/49. Mutants: MAC
unchecked, refusal unreported, admission unrestored, MF pending_event=None all
KILLED. Argus probe_r8_source_authz_real_intake: B/R PRESERVED, CONTROL ok.
Session/authz/startup-restore suites 445 passed.

* fix(gateway): reject torn spool keys and gate replay refusals

Verified: 57 focused restart tests passed; forged invalid-key, tampered-admission, and two refusal-site arms exercised via real restart.

---------

Co-authored-by: Kyzcreig <9063726+Kyzcreig@users.noreply.github.com>
Co-authored-by: Apollo <apollo@angventures.io>
Kyzcreig added a commit that referenced this pull request Sep 25, 2026
…ble-row fixture

Follow-up to #966 (card t_d3963974). Today's two structural rebuilds
(13 min + 6.5 min under _LOAD_LOCK) left no log line; the only trace was
a PHASE=context_engine_load_slow WARNING minutes later. Now the decision
site logs the reason (missing table / missing shadow / wrong column /
schema-probe exception incl. transient SQLITE_BUSY) and an O(1) size
hint before the rebuild, and the duration after it.

Test fixture: one AEAD-prefixed row the (disabled) cipher cannot
decrypt, so the write-lock test also gates the per-boot NULL-over-NULL
FTS trigger write that #966 removed.
Kyzcreig added a commit that referenced this pull request Sep 25, 2026
LCMConfig.from_env resolved ~12 config-file knobs, each through a helper
that re-read and re-parsed config.yaml with pure-Python yaml.safe_load.
All of it runs under plugins/context_engine/__init__.py::_LOAD_LOCK:
2.75 s per from_env measured on 2026-09-24, 5-10 s holds live after #966
(PHASE=context_engine_load_slow, card t_90850d58).

- Knob helpers read through _hermes_config_yaml(), which re-reads the file
  but parses only when its text changed (keyed on path + exact text, so an
  edit is seen on the next read with no mtime-granularity staleness).
  Returns a deepcopy so callers cannot poison the cache.
- _load_hermes_config_yaml() is the raw parser; uses yaml.CSafeLoader when
  libyaml is available, SafeLoader otherwise.
- docs/lcm-init-boot-cost-contract.md rule 7 + incident 4.

Verified:
- tests/context_engine/test_lcm_config_parse_once.py: RED on fork/main
  9f857c4 ("one engine load parsed config.yaml 12x"), 4/4 green here.
- Related config tests green: test_lcm_calibration_config,
  test_config_knob_arrival_sweep, test_lcm_fresh_tail_token_budget,
  test_warm_cache_maintenance_gate, test_lcm_compression_config_keys (89).
- Live ~/.hermes/config.yaml, runtime venv, load1 ~21: from_env 201-205 ms
  with 12 parses (base) -> 6.0 ms first / 3.1 ms repeat, 1 then 0 parses.
  dataclasses.asdict(LCMConfig.from_env()) byte-identical base vs fix.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

fleetreview:post-merge Ask FleetReview to review this MERGED pull (merge commit vs first parent)

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant