feat(repair): repairIndex narrates every phase and its receipt carries the walls

On a production store (14,647 nouns / 73,070 verbs) a repairIndex() ran for
more than thirty minutes at roughly a full core with ZERO log lines between
its start and its end, while the read doors kept serving. The operator could
tell it was alive only from `top`, and could not tell which of its
single-threaded walks it was inside.

Same law as the open, applied to the repair:
- every phase announces itself BEFORE it works, naming what it is about to
  walk (each canonical walk, the VFS containment reconciliation, each
  provider's invariant pass);
- an unref'd heartbeat names the phase still running every 5s, for as long as
  it runs;
- every phase reports its own wall, and that wall is carried in the TYPED
  receipt as RepairFamilyReport.durationMs — a receipt that cannot say where
  the time went is not a receipt;
- the whole repair's narration moves to the always-visible channel, so a
  production log level cannot silence it.

The phases move into runRepairIndexPhases() so the heartbeat can live in a
finally around them; the public door and its report shape are unchanged apart
from the added durationMs.

Pins: tests/integration/repair-narration.test.ts — every checked family has a
start line, a finish line with its wall, and a numeric durationMs in the
receipt; a phase slowed to 6.5s produces a heartbeat naming it, with the
logger clamped to ERROR.

src/brainy.ts

@@ -18199,17 +18199,89 @@ export class Brainy<T = any> implements BrainyInterface<T> {
    * invariant-driven pass (it was already rebuilt unconditionally — a second,
    * report-driven pass over the same family would be redundant at best).
    *
+   * NARRATION IS PART OF THE CONTRACT. A repair on a production store ran for
+   * more than thirty minutes at a full core with NOT ONE log line between its
+   * start and its end while the doors kept serving; the operator could tell it
+   * was alive only from `top`. Every phase now announces itself before it
+   * works, a heartbeat names the phase still running every five seconds, and
+   * each phase reports its own wall — carried in the receipt as
+   * `durationMs` per family, so nobody has to infer progress from CPU.
+   *
    * @param options.rebuild - Family name(s) to unconditionally rebuild, or `'all'` for all three (`'metadata' | 'graph' | 'vector'`).
-   * @returns The full per-family receipt (see {@link RepairReport}); also narrated via `prodLog.warn`.
+   * @returns The full per-family receipt (see {@link RepairReport}); also narrated as it goes.
    */
   async repairIndex(options?: { rebuild?: Array<'metadata' | 'graph' | 'vector'> | 'all' }): Promise<RepairReport> {
     await this.ensureInitialized()
     const startedAt = Date.now()
     const families: RepairFamilyReport[] = []
-    const record = (family: string, entry: Omit<RepairFamilyReport, 'family'>): void => {
-      families.push({ family, ...entry })
+
+    // THE REPAIR HEARTBEAT — the same law the open obeys: no stretch of work
+    // may be silent for more than REPAIR_HEARTBEAT_MS. Unref'd (it never holds
+    // a process open) and cleared in the `finally` below.
+    const REPAIR_HEARTBEAT_MS = 5_000
+    let currentPhase = 'starting'
+    let currentPhaseCause = 'preparing the repair'
+    let phaseStartedAt = Date.now()
+    const heartbeat = setInterval(() => {
+      prodLog.narrate(
+        `[Brainy] repairIndex: still in "${currentPhase}" after ` +
+          `${Math.round((Date.now() - phaseStartedAt) / 1000)}s ` +
+          `(${Math.round((Date.now() - startedAt) / 1000)}s into the repair) — ${currentPhaseCause}`
+      )
+    }, REPAIR_HEARTBEAT_MS)
+    if (typeof heartbeat.unref === 'function') heartbeat.unref()
+
+    /** Announce a phase before it does any work, and start its clock. */
+    const beginPhase = (name: string, cause: string): void => {
+      currentPhase = name
+      currentPhaseCause = cause
+      phaseStartedAt = Date.now()
+      prodLog.narrate(`[Brainy] repairIndex: "${name}" started — ${cause}`)
     }
 
+    /**
+     * Close the current phase: stamp its wall into the receipt row and say
+     * what it did. Every family row carries its own `durationMs`.
+     */
+    const record = (family: string, entry: Omit<RepairFamilyReport, 'family' | 'durationMs'>): void => {
+      const durationMs = Date.now() - phaseStartedAt
+      families.push({ family, ...entry, durationMs })
+      prodLog.narrate(
+        `[Brainy] repairIndex: "${family}" finished in ${durationMs}ms — ` +
+          (entry.checked
+            ? `${entry.healed} heal(s)${entry.rebuilt ? ', rebuilt' : ''}` +
+              (entry.detail ? ` (${entry.detail})` : '')
+            : `skipped (${entry.skipped ?? entry.reason ?? 'no reason given'})`)
+      )
+      phaseStartedAt = Date.now()
+    }
+
+    try {
+      return await this.runRepairIndexPhases(options, families, record, beginPhase, startedAt)
+    } finally {
+      clearInterval(heartbeat)
+    }
+  }
+
+  /**
+   * @description The phases of {@link repairIndex}, separated so its heartbeat
+   * can live in a `finally` around them. Not a public door — see `repairIndex`
+   * for the contract.
+   * @param options - As `repairIndex`.
+   * @param families - The receipt rows being accumulated.
+   * @param record - Closes a phase: stamps its wall and narrates its outcome.
+   * @param beginPhase - Announces a phase before it works.
+   * @param startedAt - When the repair began, for the closing line.
+   * @returns The full receipt.
+   */
+  private async runRepairIndexPhases(
+    options: { rebuild?: Array<'metadata' | 'graph' | 'vector'> | 'all' } | undefined,
+    families: RepairFamilyReport[],
+    record: (family: string, entry: Omit<RepairFamilyReport, 'family' | 'durationMs'>) => void,
+    beginPhase: (name: string, cause: string) => void,
+    startedAt: number
+  ): Promise<RepairReport> {
+
     // Prune orphaned canonical containers left by the pre-8.3.1 partial-delete
     // defect: a delete that removed the metadata (content) leg but left the
     // vector leg + the entity directory (a "ghost"), or left an empty directory
@@ -18223,6 +18295,10 @@ export class Brainy<T = any> implements BrainyInterface<T> {
       rebuildSubtypeCounts?: () => Promise<void>
     }
     if (typeof pruner.pruneOrphanedEntities === 'function') {
+      beginPhase(
+        'orphaned-containers',
+        'walking every canonical id directory for ghost/scar containers left by a partial delete'
+      )
       const orphans = await pruner.pruneOrphanedEntities()
       const pruned = orphans.nouns.length + orphans.verbs.length
       record('orphaned-containers', {
@@ -18233,7 +18309,7 @@ export class Brainy<T = any> implements BrainyInterface<T> {
           : {})
       })
       if (pruned > 0) {
-        prodLog.warn(
+        prodLog.narrate(
           `[Brainy] repairIndex() pruned ${orphans.nouns.length} orphaned noun + ` +
             `${orphans.verbs.length} orphaned verb container(s) left by a pre-8.3.1 ` +
             `partial delete.`
@@ -18249,6 +18325,10 @@ export class Brainy<T = any> implements BrainyInterface<T> {
     // correct itself. rebuildTypeCounts() recomputes EVERY counter rollup
     // (scalar totals + per-type maps + type-statistics arrays) from one
     // canonical walk and persists them.
+    beginPhase(
+      'count-rollups',
+      'ONE canonical walk recomputing every counter rollup — scalar totals, per-type maps, type statistics'
+    )
     await pruner.rebuildTypeCounts?.()
     await pruner.rebuildSubtypeCounts?.()
     record('count-rollups', {
@@ -18271,6 +18351,10 @@ export class Brainy<T = any> implements BrainyInterface<T> {
     // concurrent writers. Canonical metadata.path is the truth; only VFS
     // containment edges are touched. Loud per repair.
     if (this._vfsInitialized && this._vfs) {
+      beginPhase(
+        'vfs-containment',
+        'reconciling VFS containment edges against canonical metadata.path'
+      )
       const containment = await this._vfs.repairContainment()
       record('vfs-containment', {
         checked: true,
@@ -18280,7 +18364,7 @@ export class Brainy<T = any> implements BrainyInterface<T> {
           : {})
       })
       if (containment.removed + containment.restored > 0) {
-        prodLog.warn(
+        prodLog.narrate(
           `[Brainy] repairIndex() reconciled VFS containment: removed ${containment.removed} ` +
             `stale/duplicate edge(s), restored ${containment.restored} missing edge(s).`
         )
@@ -18291,17 +18375,25 @@ export class Brainy<T = any> implements BrainyInterface<T> {
       record('vfs-containment', { checked: false, healed: 0, skipped: 'VFS not initialized' })
     }
 
+    beginPhase(
+      'metadata-corruption',
+      'detect-and-repair pass over the metadata index'
+    )
     await this.metadataIndex.detectAndRepairCorruption()
     record('metadata-corruption', { checked: true, healed: 0, detail: 'detect-and-repair pass ran (see its own narration for repairs)' })
     // Lift a failed-rollback write-quarantine: force a full rebuild so the
     // derived indexes are provably reconciled with canonical, then clear the
     // flag so writes resume.
     if (this.storeInconsistency) {
+      beginPhase(
+        'write-quarantine',
+        'full derived-index rebuild to lift the quarantine set by a failed transaction rollback'
+      )
       await this.rebuildIndexesIfNeeded(true)
       const cleared = this.storeInconsistency
       record('write-quarantine', { checked: true, healed: 1, detail: `lifted (${cleared.records.length} record(s) reconciled)` })
       this.storeInconsistency = null
-      prodLog.warn(
+      prodLog.narrate(
         `[Brainy] repairIndex() reconciled the store and LIFTED the write-quarantine ` +
         `set by a failed transaction rollback (${cleared.records.length} record(s) affected). ` +
         `Writes are re-enabled.`
@@ -18332,9 +18424,9 @@ export class Brainy<T = any> implements BrainyInterface<T> {
           record(`provider:${familyName}`, { checked: false, healed: 0, skipped: 'no rebuild() contract' })
           continue
         }
-        prodLog.warn(
-          `[Brainy] repairIndex(): explicit rebuild requested for '${familyName}' — ` +
-            `rebuilding unconditionally (no invariant consulted).`
+        beginPhase(
+          `provider:${familyName}`,
+          `explicit rebuild requested — rebuilding '${familyName}' unconditionally, no invariant consulted`
         )
         // The metadata family routes through the online build-beside
         // orchestrator (B3 D3) instead of the provider's own rebuild() —
@@ -18351,7 +18443,7 @@ export class Brainy<T = any> implements BrainyInterface<T> {
           rebuilt: true,
           reason: 'explicit rebuild requested'
         })
-        prodLog.warn(`[Brainy] repairIndex(): '${familyName}' rebuild complete.`)
+        prodLog.narrate(`[Brainy] repairIndex(): '${familyName}' rebuild complete.`)
         continue
       }
 
@@ -18360,11 +18452,16 @@ export class Brainy<T = any> implements BrainyInterface<T> {
         rebuild?: () => Promise<void>
       } | null
       if (!p || typeof p.validateInvariants !== 'function' || typeof p.rebuild !== 'function') {
+        beginPhase(`provider:${familyName}`, 'checking the provider contract')
         record(`provider:${familyName}`, {
           checked: false, healed: 0, skipped: 'no validateInvariants/rebuild contract'
         })
         continue
       }
+      beginPhase(
+        `provider:${familyName}`,
+        `reading the '${familyName}' provider's own invariant report, then healing only what it asks for`
+      )
       let report: ProviderInvariantReport
       try {
         report = await p.validateInvariants()
@@ -18381,7 +18478,7 @@ export class Brainy<T = any> implements BrainyInterface<T> {
           checked: true, healed: 1,
           detail: `rebuilt from canonical (failing: ${report.invariants.filter((i) => !i.holds).map((i) => i.name).join(', ')})`
         })
-        prodLog.warn(
+        prodLog.narrate(
           `[Brainy] repairIndex(): provider '${report.provider}' has a failing invariant ` +
             `requiring a rebuild — reconciling its derived state from canonical.`
         )
@@ -18405,7 +18502,7 @@ export class Brainy<T = any> implements BrainyInterface<T> {
         const failingRepairs = report.invariants
           .filter((i) => !i.holds && i.heal === 'repair')
           .map((i) => i.name)
-        prodLog.warn(
+        prodLog.narrate(
           `[Brainy] repairIndex(): provider '${report.provider}' asks for an incremental ` +
             `repair (${failingRepairs.join(', ')}) — running its own repair().`
         )
@@ -18444,6 +18541,7 @@ export class Brainy<T = any> implements BrainyInterface<T> {
     // rebuild failure are now reconciled — clear the queryable degraded state
     // and re-arm the read-path warning.
     if (this._indexDegradedIds.size > 0 || this._indexRebuildFailed) {
+      beginPhase('degraded-read-state', 'clearing degraded ids and re-arming the read-path warning')
       this._indexDegradedIds.clear()
       this._indexRebuildFailed = null
       this._degradedReadWarned = false
@@ -18452,11 +18550,13 @@ export class Brainy<T = any> implements BrainyInterface<T> {
 
     const healedTotal = families.reduce((n, f) => n + f.healed, 0)
     const report: RepairReport = { families, healedTotal, durationMs: Date.now() - startedAt }
-    prodLog.warn(
+    prodLog.narrate(
       `[Brainy] repairIndex complete in ${report.durationMs}ms — ` +
         `${families.filter((f) => f.checked).length}/${families.length} families checked, ` +
         `${healedTotal} heal(s): ` +
-        families.map((f) => `${f.family}=${f.checked ? f.healed : 'skipped'}`).join(', ')
+        families
+          .map((f) => `${f.family}=${f.checked ? f.healed : 'skipped'}@${f.durationMs ?? 0}ms`)
+          .join(', ')
     )
     return report
   }

src/types/brainy.types.ts

@@ -1217,6 +1217,13 @@ export interface RepairFamilyReport {
   skipped?: string
   /** Why the outcome is what it is when neither `detail` nor `skipped` says it. */
   reason?: string
+  /**
+   * The phase's own wall, in milliseconds. A repair on a production store ran
+   * for over thirty minutes without a single line of output; an operator had
+   * to read `top` to know it was alive. A receipt that cannot say WHERE the
+   * time went is not a receipt — every row carries its own.
+   */
+  durationMs?: number
 }
 
 /** The full receipt returned by repairIndex(). */

tests/integration/repair-narration.test.ts

@@ -0,0 +1,119 @@
+/**
+ * @module tests/integration/repair-narration
+ * @description A REPAIR NARRATES ITSELF, AND ITS RECEIPT SAYS WHERE THE TIME
+ * WENT.
+ *
+ * On a production store (14,647 nouns / 73,070 verbs) a `repairIndex()` ran
+ * for more than thirty minutes at roughly a full core with ZERO log lines
+ * between its start and its end, while the read doors kept serving. The
+ * operator could tell it was alive only from `top`, and could not tell which
+ * of its single-threaded walks it was inside. The law pinned here:
+ *
+ *   - every phase announces itself BEFORE it works, naming what it is about
+ *     to walk;
+ *   - a heartbeat names the phase still running, at a bounded cadence, for as
+ *     long as it runs;
+ *   - every phase reports its own wall, and that wall is carried in the typed
+ *     receipt (`RepairFamilyReport.durationMs`) — not only in a log line.
+ *
+ * All of it on the narration channel, which production's log clamp cannot
+ * silence (see tests/integration/open-narration.test.ts).
+ */
+
+import { describe, it, expect, afterEach, vi } from 'vitest'
+import { mkdtempSync, rmSync } from 'node:fs'
+import { tmpdir } from 'node:os'
+import { join } from 'node:path'
+import { Brainy } from '../../src/brainy.js'
+import { NounType } from '../../src/types/graphTypes.js'
+import { FileSystemStorage } from '../../src/storage/adapters/fileSystemStorage.js'
+import { prodLog, configureLogger, LogLevel } from '../../src/utils/logger.js'
+
+describe('repairIndex narration', () => {
+  const dirs: string[] = []
+  const brains: Brainy[] = []
+
+  afterEach(async () => {
+    for (const b of brains.splice(0)) {
+      try { await b.close() } catch { /* already closed */ }
+    }
+    for (const d of dirs.splice(0)) {
+      try { rmSync(d, { recursive: true, force: true }) } catch { /* ignore */ }
+    }
+    configureLogger({ level: LogLevel.INFO })
+  })
+
+  async function seededBrain(): Promise<Brainy> {
+    const dir = mkdtempSync(join(tmpdir(), 'brainy-repair-narration-'))
+    dirs.push(dir)
+    const brain = new Brainy({ requireSubtype: false, storage: { type: 'filesystem', path: dir } })
+    brains.push(brain)
+    await brain.init()
+    for (let i = 0; i < 5; i++) {
+      await brain.add({ data: `repair subject ${i}`, type: NounType.Concept })
+    }
+    await brain.flush()
+    return brain
+  }
+
+  it('announces every phase, reports its wall, and carries that wall in the receipt', async () => {
+    const brain = await seededBrain()
+    const narrateSpy = vi.spyOn(prodLog, 'narrate')
+
+    const report = await brain.repairIndex()
+
+    const lines = narrateSpy.mock.calls.map(([m]) => String(m))
+
+    // Every family that ran has BOTH a start line and a finish line naming it.
+    for (const family of report.families) {
+      const started = lines.filter((l) => l.includes(`"${family.family}" started —`))
+      const finished = lines.filter((l) =>
+        new RegExp(`"${family.family}" finished in \\d+ms`).test(l)
+      )
+      expect(finished.length, `no finish line for ${family.family}`).toBeGreaterThanOrEqual(1)
+      // A skipped family may be recorded without a start line only if it never
+      // began; every family that began must have announced itself.
+      if (family.checked) {
+        expect(started.length, `no start line for ${family.family}`).toBeGreaterThanOrEqual(1)
+      }
+      // THE RECEIPT CARRIES THE WALL — not only the log.
+      expect(typeof family.durationMs, `${family.family} has no durationMs`).toBe('number')
+      expect(family.durationMs).toBeGreaterThanOrEqual(0)
+    }
+
+    // The closing line accounts for the whole repair, per family.
+    const closing = lines.filter((l) => /repairIndex complete in \d+ms/.test(l))
+    expect(closing.length).toBe(1)
+    expect(closing[0]).toMatch(/@\d+ms/)
+  }, 180_000)
+
+  it('heartbeats while a single phase is still walking', async () => {
+    const brain = await seededBrain()
+
+    // Make one phase long enough to cross the heartbeat cadence, exactly as a
+    // multi-minute canonical walk does on a real store.
+    const proto = FileSystemStorage.prototype as unknown as Record<
+      string,
+      (...args: unknown[]) => Promise<unknown>
+    >
+    const realPrune = proto.pruneOrphanedEntities
+    proto.pruneOrphanedEntities = async function slow(this: unknown, ...args: unknown[]) {
+      await new Promise((r) => setTimeout(r, 6_500))
+      return realPrune.apply(this, args)
+    }
+    // Clamped as production clamps it: the narration must survive.
+    configureLogger({ level: LogLevel.ERROR })
+    const narrateSpy = vi.spyOn(prodLog, 'narrate')
+    try {
+      await brain.repairIndex()
+    } finally {
+      proto.pruneOrphanedEntities = realPrune
+    }
+
+    const beats = narrateSpy.mock.calls
+      .map(([m]) => String(m))
+      .filter((l) => /repairIndex: still in "orphaned-containers" after \d+s/.test(l))
+    expect(beats.length).toBeGreaterThanOrEqual(1)
+    expect(beats[0]).toMatch(/ghost\/scar containers/)
+  }, 180_000)
+})