feat(open): the open narrates itself, on a channel production cannot clamp

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.

src/brainy.ts

@@ -1098,21 +1098,67 @@ export class Brainy<T = any> implements BrainyInterface<T> {
       configureLogger({ level: LogLevel.DEBUG })  // Enable verbose logging
     }
 
-    // OPEN-PATH NARRATION: lightweight phase timing across the five
+    // OPEN-PATH NARRATION: phase timing across the five named stretches of
-    // named stretches of init — storage init / generation-store open+fold /
+    // init — storage init / generation-store open+fold / index init+gate /
-    // index init+gate / VFS bootstrap / embedding-warm-started. Each
+    // VFS bootstrap / embedding-warm-started. Each `markPhase()` call records
-    // `markPhase()` call records elapsed ms SINCE THE PREVIOUS checkpoint,
+    // elapsed ms SINCE THE PREVIOUS checkpoint, so the buckets always sum to
-    // so the buckets always sum to the pre-integration/warmOnOpen total.
+    // 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
+    // THE LAW THIS ENFORCES: an open is never silent for more than
-    // phase instead of re-deriving it from a stack of raw timestamps.
+    // 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<string, number> = {}
+    const openHeartbeat: ReturnType<typeof setInterval> = 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<T = any> implements BrainyInterface<T> {
           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<T = any> implements BrainyInterface<T> {
       // 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)
     }
   }
 

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<void> => {
           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

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),

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<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)
+})