diff --git a/src/brainy.ts b/src/brainy.ts index 81f3cc7e..24407018 100644 --- a/src/brainy.ts +++ b/src/brainy.ts @@ -18199,17 +18199,89 @@ export class Brainy implements BrainyInterface { * 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 { await this.ensureInitialized() const startedAt = Date.now() const families: RepairFamilyReport[] = [] - const record = (family: string, entry: Omit): 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): 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) => void, + beginPhase: (name: string, cause: string) => void, + startedAt: number + ): Promise { + // 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 implements BrainyInterface { rebuildSubtypeCounts?: () => Promise } 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 implements BrainyInterface { : {}) }) 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 implements BrainyInterface { // 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 implements BrainyInterface { // 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 implements BrainyInterface { : {}) }) 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 implements BrainyInterface { 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 implements BrainyInterface { 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 implements BrainyInterface { 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 implements BrainyInterface { rebuild?: () => Promise } | 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 implements BrainyInterface { 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 implements BrainyInterface { 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 implements BrainyInterface { // 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 implements BrainyInterface { 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 } diff --git a/src/types/brainy.types.ts b/src/types/brainy.types.ts index d9934c3b..a0d55c1e 100644 --- a/src/types/brainy.types.ts +++ b/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(). */ diff --git a/tests/integration/repair-narration.test.ts b/tests/integration/repair-narration.test.ts new file mode 100644 index 00000000..1fbe15e4 --- /dev/null +++ b/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 { + 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 + > + 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) +})