fix(lcm): structural FTS rebuilds log why + how long; undecryptable-row fixture (follow-up to #966)

plugins/context_engine/lcm/db_bootstrap.py

@@ -2392,13 +2392,21 @@ def quote_sql_identifier(identifier: str) -> str:
     return f'"{identifier}"'
 
 
-def _fts_needs_rebuild_structural(conn: sqlite3.Connection, spec: ExternalContentFtsSpec) -> bool:
+def _fts_structural_problem(conn: sqlite3.Connection, spec: ExternalContentFtsSpec) -> str:
+    """Why the FTS table needs a structural rebuild, or ``""`` when it is sound.
+
+    Returns a short reason so the caller can LOG it: a structural rebuild of a
+    2.5 M-row index is a 13-minute write transaction (measured 2026-09-24,
+    fleet DB, twice in one hour) and until then it ran silently — the only
+    trace was a ``PHASE=context_engine_load_slow`` line minutes later.
+    """
     shadow_tables = get_fts_shadow_table_names(spec.table_name)
     existing_tables = get_existing_table_names(conn, [spec.table_name, *shadow_tables])
     if spec.table_name not in existing_tables:
-        return True
-    if any(name not in existing_tables for name in shadow_tables):
-        return True
+        return "fts table missing"
+    missing_shadows = [name for name in shadow_tables if name not in existing_tables]
+    if missing_shadows:
+        return "shadow table(s) missing: " + ", ".join(missing_shadows)
 
     try:
         info = conn.execute(
@@ -2408,18 +2416,40 @@ def _fts_needs_rebuild_structural(conn: sqlite3.Connection, spec: ExternalConten
         sql = (info[0] if info else "") or ""
         normalized = sql.lower()
         if "virtual table" not in normalized or "using fts5" not in normalized:
-            return True
+            return f"not an fts5 virtual table: {sql[:120]!r}"
 
         columns = conn.execute(
             f"PRAGMA table_info({quote_sql_identifier(spec.table_name)})"
         ).fetchall()
         column_names = {row[1] for row in columns if len(row) > 1}
         if spec.indexed_column not in column_names:
-            return True
-    except sqlite3.DatabaseError:
-        return True
+            return (
+                f"indexed column {spec.indexed_column!r} not in table_info "
+                f"{sorted(column_names)!r}"
+            )
+    except sqlite3.DatabaseError as exc:
+        # NOTE: this also fires on a TRANSIENT error (SQLITE_BUSY on the
+        # schema read). Rebuilding on a transient error is a known hazard;
+        # the reason is logged by the caller so the next incident says so.
+        return f"schema probe raised {type(exc).__name__}: {exc}"
+
+    return ""
 
-    return False
+
+def _fts_needs_rebuild_structural(conn: sqlite3.Connection, spec: ExternalContentFtsSpec) -> bool:
+    return bool(_fts_structural_problem(conn, spec))
+
+
+def _fts_size_hint(conn: sqlite3.Connection, spec: ExternalContentFtsSpec) -> int:
+    """O(1) size hint for log lines (max rowid, never COUNT(*))."""
+    try:
+        row = conn.execute(
+            f"SELECT MAX({quote_sql_identifier(spec.content_rowid)}) "
+            f"FROM {quote_sql_identifier(spec.content_table)}"
+        ).fetchone()
+        return int(row[0] or 0) if row else 0
+    except sqlite3.DatabaseError:
+        return -1
 
 
 def _fts_count_parity_mismatch(conn: sqlite3.Connection, spec: ExternalContentFtsSpec) -> bool:
@@ -2928,7 +2958,18 @@ def _fts_needs_rebuild(
     now: float | None = None,
     throttle: bool = False,
 ) -> bool:
-    if _fts_needs_rebuild_structural(conn, spec):
+    problem = _fts_structural_problem(conn, spec)
+    if problem:
+        logger.warning(
+            "LCM FTS '%s' needs a structural rebuild: %s (content rows ~%d, "
+            "startup_path=%s). A rebuild is ONE write transaction over every "
+            "row — minutes on a large DB — and it holds the engine-load lock "
+            "when it runs on the startup path.",
+            spec.table_name,
+            problem,
+            _fts_size_hint(conn, spec),
+            throttle,
+        )
         return True
     if not throttle:
         # Explicit repair (``/lcm doctor repair apply``): full synchronous
@@ -3238,6 +3279,7 @@ def _repair_external_content_fts_body(
                 _clear_integrity_failed(conn, spec)
                 conn.commit()
                 return {"rebuilt": False, "degraded": True, "triggers_recreated": False}
+        rebuild_started = time.monotonic()
         _drop_fts_table(conn, spec.table_name)
         conn.execute(
             f"""
@@ -3251,6 +3293,9 @@ def _repair_external_content_fts_body(
         conn.execute(
             f"INSERT INTO {quote_sql_identifier(spec.table_name)}({quote_sql_identifier(spec.table_name)}) VALUES('rebuild')"
         )
+        logger.warning(
+            "LCM FTS '%s' rebuilt in %.1fs", spec.table_name, time.monotonic() - rebuild_started
+        )
         rebuilt = True
 
     triggers_were_missing = _fts_missing_triggers(conn, spec)

tests/context_engine/test_lcm_init_cost_regression.py

@@ -52,6 +52,7 @@
 from plugins.context_engine.lcm.config import LCMConfig
 from plugins.context_engine.lcm.engine import LCMEngine
 from plugins.context_engine.lcm.lifecycle_state import LifecycleStateStore
+from plugins.context_engine.lcm.storage_security import AEAD_PREFIX
 from plugins.context_engine.lcm.store import MessageStore, build_message_fts_spec
 
 # Any full traversal of one of these tables on a per-load / per-session-start
@@ -72,6 +73,12 @@ def _fill(db: Path, n: int) -> None:
         ("s%d" % (i % 50), "user", st._cipher.encrypt_text("m%d" % i, field="content"), float(i))
         for i in range(n)
     ]
+    # One row the profile cannot decrypt (an AEAD-prefixed payload with the
+    # cipher disabled — the fleet DB has three of these). Its search_content
+    # stays NULL forever, so the partial-index probe finds it on EVERY boot;
+    # the old backfill then wrote NULL over NULL, which fired the FTS5 update
+    # trigger and took the write lock on every load (4-57 s on the fleet index).
+    rows.append(("s0", "user", AEAD_PREFIX + "bm90LXJlYWxseS1lbmNyeXB0ZWQ=", float(n)))
     conn.executemany(
         "INSERT INTO messages (session_id, role, content, timestamp) VALUES (?,?,?,?)", rows
     )
@@ -284,6 +291,30 @@ def execute(self, sql, *args):
         writer.close()
 
 
+def test_structural_rebuild_logs_its_reason(tmp_path, caplog):
+    """A structural FTS rebuild must say WHY, before it runs.
+
+    On 2026-09-24 two rebuilds (13 min + 6.5 min, holding _LOAD_LOCK) left no
+    log line at all; the only trace was a load_slow WARNING minutes later.
+    """
+    import logging
+
+    db = tmp_path / "lcm.db"
+    _fill(db, 200)
+    conn = sqlite3.connect(str(db))
+    conn.execute("DROP TABLE messages_fts_docsize")
+    conn.commit()
+    with caplog.at_level(logging.WARNING, logger="plugins.context_engine.lcm.db_bootstrap"):
+        result = db_bootstrap.repair_external_content_fts(
+            conn, build_message_fts_spec(), throttle=True
+        )
+    conn.close()
+    assert result["rebuilt"] is True
+    text = "\n".join(r.getMessage() for r in caplog.records)
+    assert "needs a structural rebuild" in text and "messages_fts_docsize" in text, text
+    assert "rebuilt in" in text, text
+
+
 def test_init_time_does_not_scale_with_row_count(tmp_path):
     small = tmp_path / "small.db"
     big = tmp_path / "big.db"