open-brainy/tests/integration/open-narration.test.ts

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