diff --git a/src/brainy.ts b/src/brainy.ts index 957920f5..81f3cc7e 100644 --- a/src/brainy.ts +++ b/src/brainy.ts @@ -1098,21 +1098,67 @@ export class Brainy implements BrainyInterface { configureLogger({ level: LogLevel.DEBUG }) // Enable verbose logging } - // OPEN-PATH NARRATION: lightweight phase timing across the five - // named stretches of init — storage init / generation-store open+fold / - // index init+gate / VFS bootstrap / embedding-warm-started. Each - // `markPhase()` call records elapsed ms SINCE THE PREVIOUS checkpoint, - // so the buckets always sum to the pre-integration/warmOnOpen total. - // Silent under 2s; one `prodLog.warn` line naming every phase's ms - // above it, so the operator's next restart storm names its own slow - // phase instead of re-deriving it from a stack of raw timestamps. + // OPEN-PATH NARRATION: phase timing across the five named stretches of + // init — storage init / generation-store open+fold / index init+gate / + // VFS bootstrap / embedding-warm-started. Each `markPhase()` call records + // elapsed ms SINCE THE PREVIOUS checkpoint, so the buckets always sum to + // the pre-integration/warmOnOpen total. + // + // THE LAW THIS ENFORCES: an open is never silent for more than + // OPEN_HEARTBEAT_MS. A production service opening a 16 GB store logged + // NOTHING for three minutes and then began work — the operator could not + // tell a slow open from a hung one, and restarted into the same wall. + // Two mechanisms, both on the always-visible narration channel (the old + // breakdown used `prodLog.warn`, which production clamps away — that is + // why the three minutes were silent): + // - a heartbeat that names the phase currently running and its elapsed + // wall, every OPEN_HEARTBEAT_MS, for as long as the open lasts; + // - one line per phase AS IT ENDS, naming its wall and its cause, for + // any phase over OPEN_PHASE_NARRATE_MS. + // The heartbeat is unref'd and cleared in the `finally` below, so it can + // neither hold the process open nor outlive a failed init. It cannot fire + // inside a phase that blocks the event loop synchronously; such a phase + // must narrate its own progress (the generation-log fold does). + const OPEN_HEARTBEAT_MS = 5_000 + const OPEN_PHASE_NARRATE_MS = 2_000 + /** Phase order + what each one is paying for, quoted in its narration. */ + const OPEN_PHASES: ReadonlyArray<{ name: string; cause: string }> = [ + { name: 'storage-init', cause: 'opening the store and loading its count ledger' }, + { + name: 'generation-store-open-fold', + cause: 'opening the generation store: crash-recovery replay/fold, derived-family registration, format handshake' + }, + { name: 'index-init-gate', cause: 'constructing the derived indexes and gating them for serving' }, + { name: 'vfs-bootstrap', cause: 'bootstrapping the virtual filesystem' }, + { name: 'embedding-warm-started', cause: 'starting the background embedding warm' } + ] const initStart = Date.now() let lastPhaseCheckpoint = initStart + let currentPhaseIndex = 0 const phaseTimingsMs: Record = {} + const openHeartbeat: ReturnType = setInterval(() => { + const phase = OPEN_PHASES[currentPhaseIndex] + if (!phase) return + prodLog.narrate( + `[Brainy] open: still in phase ${currentPhaseIndex + 1}/${OPEN_PHASES.length} ` + + `"${phase.name}" after ${Math.round((Date.now() - lastPhaseCheckpoint) / 1000)}s ` + + `(${Math.round((Date.now() - initStart) / 1000)}s into the open) — ${phase.cause}` + ) + }, OPEN_HEARTBEAT_MS) + if (typeof openHeartbeat.unref === 'function') openHeartbeat.unref() const markPhase = (name: string): void => { const now = Date.now() - phaseTimingsMs[name] = now - lastPhaseCheckpoint + const elapsed = now - lastPhaseCheckpoint + phaseTimingsMs[name] = elapsed lastPhaseCheckpoint = now + const finished = OPEN_PHASES[currentPhaseIndex] + if (elapsed >= OPEN_PHASE_NARRATE_MS && finished && finished.name === name) { + prodLog.narrate( + `[Brainy] open: phase ${currentPhaseIndex + 1}/${OPEN_PHASES.length} ` + + `"${name}" finished in ${elapsed}ms — ${finished.cause}` + ) + } + currentPhaseIndex++ } try { @@ -1777,7 +1823,7 @@ export class Brainy implements BrainyInterface { const phaseList = Object.entries(phaseTimingsMs) .map(([name, ms]) => `${name}=${ms}ms`) .join(', ') - prodLog.warn( + prodLog.narrate( `[Brainy] slow open: ${totalOpenMs}ms total (${phaseList}) — see the ` + `phase breakdown above to find which one to investigate first` ) @@ -1839,6 +1885,10 @@ export class Brainy implements BrainyInterface { // log — a plain string interpolation discards both stack and cause. const message = error instanceof Error ? error.message : String(error) throw new Error(`Failed to initialize Brainy: ${message}`, { cause: error }) + } finally { + // The open is over — succeeded or failed. Stop the heartbeat here so a + // failed init never leaves a timer narrating a phase nobody is running. + clearInterval(openHeartbeat) } } diff --git a/src/db/generationStore.ts b/src/db/generationStore.ts index 81bed338..d925c9e0 100644 --- a/src/db/generationStore.ts +++ b/src/db/generationStore.ts @@ -652,6 +652,7 @@ export class GenerationStore { : 'WHOLE-LOG fold' : 'above-manifest replay' let replayed = 0 + const foldStartedAt = Date.now() const replayFact = async (fact: CommitFact): Promise => { for (const op of fact.ops) { let image: { metadata: unknown | null; vector: unknown | null } @@ -697,9 +698,10 @@ export class GenerationStore { } replayed++ if (replayed % 1000 === 0) { - prodLog.warn( + prodLog.narrate( `[GenerationStore] recovery fold in progress — ${replayed} fact(s) folded ` + - `(at generation ${fact.generation}); do not restart, the fold is finite` + `in ${Date.now() - foldStartedAt}ms (at generation ${fact.generation}); ` + + `do not restart, the fold is finite` ) } if (fact.generation > this.committed) { @@ -714,7 +716,7 @@ export class GenerationStore { } } if (uncleanOpen) { - prodLog.warn( + prodLog.narrate( `[GenerationStore] log-authority recovery: ${foldKind} beginning ` + `(unclean shutdown detected) — streaming replay, bounded memory, ` + `progress every 1000 facts. Do not restart the process; a restart ` + @@ -737,9 +739,10 @@ export class GenerationStore { } await this.storage.writeRawObject(MANIFEST_PATH, manifest) await this.storage.syncRawObjects([MANIFEST_PATH]) - prodLog.warn( + prodLog.narrate( `[GenerationStore] log-authority recovery replayed ${replayed} fact(s) into ` + - `canonical (${foldKind}; committed at ${this.committed}) — an acked write is never lost` + `canonical in ${Date.now() - foldStartedAt}ms (${foldKind}; committed at ` + + `${this.committed}) — an acked write is never lost` ) } // A recovery fold re-applied (and the barrier below re-syncs) every diff --git a/src/utils/logger.ts b/src/utils/logger.ts index 5154d4fd..0d6b6594 100644 --- a/src/utils/logger.ts +++ b/src/utils/logger.ts @@ -266,6 +266,26 @@ export const prodLog = { console.error(message, ...args) }, + /** + * THE NARRATION CHANNEL — always visible, exactly like `error`. + * + * `warn`/`info`/`log` below are clamped to ERROR in any environment that + * looks like production (see isProductionEnvironment), which is the right + * default for chatter and the wrong one for the two things an operator is + * entitled to hear from a database no matter what: WHY IT IS SLOW and WHAT + * IT IS DOING ABOUT IT. A production service opening a 16 GB store spent + * three minutes emitting nothing at all — the phase timings that would have + * named the slow phase were written to `warn` and thrown away by the log + * level. Progress and cost narration goes here; it is never a per-record + * line, always a phase, a wall, or a bounded-cadence heartbeat. + * + * `silent: true` still silences it — that is the consumer's explicit + * request, not a cost default. + */ + narrate: (message?: any, ...args: any[]) => { + console.warn(message, ...args) + }, + // These are suppressed in production unless BRAINY_LOG_LEVEL is set warn: (message?: any, ...args: any[]) => smartConsole.warn(message, ...args), info: (message?: any, ...args: any[]) => smartConsole.info(message, ...args), diff --git a/tests/integration/open-narration.test.ts b/tests/integration/open-narration.test.ts new file mode 100644 index 00000000..95aba9f1 --- /dev/null +++ b/tests/integration/open-narration.test.ts @@ -0,0 +1,114 @@ +/** + * @module tests/integration/open-narration + * @description THE OPEN IS NEVER SILENT. + * + * A production service opened a 16 GB store and logged nothing at all for + * three minutes before its first line of work. Two defects made that possible + * and both are pinned here: + * + * 1. The phase breakdown was written to `prodLog.warn`, which every + * environment that looks like production clamps away. The narration + * channel (`prodLog.narrate`) is always visible, like `error`. + * 2. Nothing spoke DURING a phase — only after the whole open finished, if + * at all. A heartbeat now names the phase currently running and its + * elapsed wall while the open is still happening. + */ + +import { describe, it, expect, beforeEach, afterEach } 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' + +function makeTempDir(): string { + return mkdtempSync(join(tmpdir(), 'brainy-open-narration-')) +} + +/** Capture console.warn lines emitted while `fn` runs. */ +async function captureWarn(fn: () => Promise): Promise<{ result: T; lines: string[] }> { + const lines: string[] = [] + const orig = console.warn + console.warn = ((...args: unknown[]) => { + lines.push(args.map((a) => String(a)).join(' ')) + }) as typeof console.warn + try { + return { result: await fn(), lines } + } finally { + console.warn = orig + } +} + +describe('open narration', () => { + let dir: string + let brain: Brainy | null = null + + beforeEach(() => { dir = makeTempDir() }) + + afterEach(async () => { + if (brain) { + try { await brain.close() } catch { /* already closed */ } + brain = null + } + try { rmSync(dir, { recursive: true, force: true }) } catch { /* ignore */ } + }) + + it('narrate() survives the production log clamp that silences warn()', async () => { + // Exactly what isProductionEnvironment() does to the logger: level ERROR. + configureLogger({ level: LogLevel.ERROR }) + try { + const { lines } = await captureWarn(async () => { + prodLog.warn('[Brainy] this line is chatter and may be clamped') + prodLog.narrate('[Brainy] this line is why the database is slow') + }) + expect(lines.some((l) => /why the database is slow/.test(l))).toBe(true) + expect(lines.some((l) => /chatter/.test(l))).toBe(false) + } finally { + configureLogger({ level: LogLevel.INFO }) + } + }) + + it('names a slow phase as it ends, and heartbeats while it is still running', async () => { + // Seed a store, then reopen it with a deliberately slow storage init so + // the first phase crosses both the heartbeat and the narrate thresholds. + brain = new Brainy({ requireSubtype: false, storage: { type: 'filesystem', path: dir } }) + await brain.init() + await brain.add({ data: 'seed entity', type: NounType.Concept }) + await brain.flush() + await brain.close() + brain = null + + const realInit = FileSystemStorage.prototype.init + FileSystemStorage.prototype.init = async function slowInit(this: FileSystemStorage) { + await new Promise((r) => setTimeout(r, 6_500)) + return realInit.call(this) + } + // Clamped to ERROR for the whole open: the narration must survive it. + configureLogger({ level: LogLevel.ERROR }) + try { + const { result, lines } = await captureWarn(async () => { + const next = new Brainy({ requireSubtype: false, storage: { type: 'filesystem', path: dir } }) + await next.init() + return next + }) + brain = result + + // The heartbeat spoke DURING the phase, naming the phase and its cause. + const heartbeats = lines.filter((l) => /open: still in phase 1\/5 "storage-init"/.test(l)) + expect(heartbeats.length).toBeGreaterThanOrEqual(1) + expect(heartbeats[0]).toMatch(/loading its count ledger/) + + // And the phase named its own wall as it ended. + const ended = lines.filter((l) => /open: phase 1\/5 "storage-init" finished in \d+ms/.test(l)) + expect(ended.length).toBe(1) + + // The whole-open breakdown is on the same always-visible channel. + expect(lines.some((l) => /slow open: \d+ms total \(.*storage-init=/.test(l))).toBe(true) + } finally { + FileSystemStorage.prototype.init = realInit + configureLogger({ level: LogLevel.INFO }) + } + }, 120_000) +})