David Snelling
afe08a1ff9
An operator watched a production service open a 16 GB store and print nothing for three minutes before its first line of work. Two defects, both fixed here. The narration was written to `prodLog.warn`, and every environment that looks like production clamps the logger to ERROR — so the phase breakdown that would have named the slow phase was composed and thrown away. `prodLog.narrate` is always visible, like `error`: it carries the two things an operator is entitled to hear from a database regardless of a cost setting — why it is slow and what it is doing about it. `silent: true` still silences it; that is a request, not a default. And nothing spoke DURING a phase, only after the whole open. init() now runs an unref'd heartbeat that every 5s names the phase currently running, its elapsed wall and what it is paying for, plus one line per phase as it ends for any phase over 2s. The generation-log fold's own progress and completion lines move to the same channel and now carry their wall — they were invisible in production, which is how an operator came to restart a converging fold three times. Pins: tests/integration/open-narration.test.ts — narrate() survives the clamp that silences warn(); a 6.5s storage-init produces a heartbeat naming the phase and a completion line naming its wall, with the logger clamped to ERROR.
114 lines
4.5 KiB
TypeScript
114 lines
4.5 KiB
TypeScript
/**
|
|
* @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<T>(fn: () => Promise<T>): 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)
|
|
})
|