/** * @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) })