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.
This commit is contained in:
parent
f4e2d34b4e
commit
3fffd9c6e6
3 changed files with 240 additions and 14 deletions
119
tests/integration/repair-narration.test.ts
Normal file
119
tests/integration/repair-narration.test.ts
Normal file
|
|
@ -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)
|
||||
})
|
||||
Loading…
Add table
Add a link
Reference in a new issue