open-brainy/tests/integration/idle-costs-nothing.test.ts

/**
 * @module tests/integration/idle-costs-nothing
 * @description AN IDLE BRAIN DOES NO WORK.
 *
 * A flush used to re-persist state identical to what was already on disk —
 * the provider flushes, the watermark stamps, the generation counter, the
 * entity-tree stamp, roughly 28 writes — because `flush()` never asked whether
 * anything had changed.
 *
 * The field observation that started this: a production process holding 21
 * brains printed "All indexes flushed to disk in 216–601ms" per brain every
 * ~35 seconds and idled at 1.26 cores, with no writes for ten minutes. This
 * engine's cadence is WRITE-DRIVEN, so that observation is NOT explained by
 * the cadence and is not claimed to be fixed here — what is fixed is that such
 * a call now costs nothing. Who was calling flush() remains open.
 *
 * The laws pinned here:
 *   (a) the persistence cadence arms only on a write — a brain nobody writes
 *       to flushes zero times, however long it is left open;
 *   (b) a flush on a clean brain is O(1): no provider is called, nothing is
 *       written, and nothing is printed;
 *   (c) one write earns exactly one flush's worth of work, and no more.
 */

import { describe, it, expect, afterEach, vi } 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'

/** Wait for any in-flight background flush, then let the idle timer settle. */
async function drainCadence(brain: Brainy): Promise<void> {
  const inner = brain as unknown as { _persistBackgroundFlight: Promise<void> | null }
  await new Promise((r) => setTimeout(r, 3_000))
  await (inner._persistBackgroundFlight ?? Promise.resolve())
  await new Promise((r) => setTimeout(r, 500))
}

/** How long an idle brain is watched. Longer than the 30s flush interval. */
const IDLE_WATCH_MS = 90_000

describe('an idle brain costs nothing', () => {
  const dirs: string[] = []
  const brains: Brainy[] = []

  afterEach(async () => {
    for (const b of brains.splice(0)) {
      try { await b.close() } catch { /* already closed */ }
    }
    for (const d of dirs.splice(0)) {
      try { rmSync(d, { recursive: true, force: true }) } catch { /* ignore */ }
    }
    vi.restoreAllMocks()
  })

  async function openBrain(): Promise<Brainy> {
    const dir = mkdtempSync(join(tmpdir(), 'brainy-idle-'))
    dirs.push(dir)
    const brain = new Brainy({ requireSubtype: false, storage: { type: 'filesystem', path: dir } })
    brains.push(brain)
    await brain.init()
    return brain
  }

  it('flushes zero times over 90 idle seconds, and prints nothing', async () => {
    const brain = await openBrain()
    // One write and one flush to reach a clean, settled state — then nothing.
    await brain.add({ data: 'the only write this test performs', type: NounType.Concept })
    await brain.flush()

    const logged: string[] = []
    // The STACK behind each narration, kept beside the line it belongs to.
    // vitest tags a stdout block with the test that is RUNNING, not the brain
    // that wrote it, so teeing these lines through would only ever name this
    // test. The call stack does name the driver: `kickBackgroundFlush('idle')`
    // under `armIdleFlushTimer` is a cadence flush on some brain, the deferred-
    // embed worker's commit path is a brain still landing vectors, and a bare
    // `flush()` is an explicit caller. That distinction is the whole question.
    const stacks: string[] = []
    const origLog = console.log
    console.log = ((...a: unknown[]) => {
      const line = a.map(String).join(' ')
      logged.push(line)
      if (/All indexes flushed to disk|Flushing Brainy indexes/.test(line)) {
        stacks.push(new Error('flush narration').stack ?? '(no stack)')
      }
    }) as typeof console.log

    // Watch the providers directly: a flush that runs calls all of them.
    const storage = (brain as unknown as { storage: { flushCounts: () => Promise<void> } }).storage
    const metadataIndex = (brain as unknown as { metadataIndex: { flush: () => Promise<void> } }).metadataIndex
    const graphIndex = (brain as unknown as { graphIndex: { flush: () => Promise<void> } }).graphIndex
    const countsSpy = vi.spyOn(storage, 'flushCounts')
    const metadataSpy = vi.spyOn(metadataIndex, 'flush')
    const graphSpy = vi.spyOn(graphIndex, 'flush')

    try {
      await new Promise((r) => setTimeout(r, IDLE_WATCH_MS))
    } finally {
      console.log = origLog
    }

    // (a) + (b): nothing ran, nothing was said.
    //
    // THE SPIES COME FIRST, AND THEY ARE THE ATTRIBUTABLE HALF. They are bound
    // to THIS brain's providers, so they answer "did this brain flush?" and
    // nothing else. The console filters below cannot: the gate config runs the
    // whole suite in ONE process (`pool: 'forks'`, `singleFork: true`), so
    // `console.log` carries the narration of every brain alive in that
    // process — including one a previous file opened and never closed, whose
    // unref'd cadence timer is still doing honest work. A neighbour narrating
    // is a REAL finding about suite hygiene, but it is not this brain failing
    // its own law, and the two must not be reported as the same thing.
    //
    // So: spies first (whose failure means the engine broke the law), console
    // second (whose failure means SOMETHING in the process narrated), and the
    // console assertion carries the captured lines in its message. vitest's
    // stdout blocks are prefixed `stdout | <file> > <test>`, so those lines
    // plus the surrounding gate log name the brain that printed them.
    expect(countsSpy).not.toHaveBeenCalled()
    expect(metadataSpy).not.toHaveBeenCalled()
    expect(graphSpy).not.toHaveBeenCalled()

    const flushChatter = logged.filter(
      (l) => /All indexes flushed to disk/.test(l) || /Flushing Brainy indexes/.test(l)
    )
    expect(
      flushChatter,
      `${flushChatter.length} flush line(s) narrated during the ${IDLE_WATCH_MS}ms idle ` +
        `window. This brain's own providers were NOT called (asserted above), so another ` +
        `brain alive in this process printed them — the suite runs every file in ONE ` +
        `process and 67 test files create more brains than they close.\n` +
        `${flushChatter.join('\n')}\n\n` +
        `The stack behind the first one names the driver:\n${stacks[0] ?? '(none captured)'}`
    ).toEqual([])
  }, 180_000)

  it('an explicit flush over a clean brain calls no provider and prints nothing', async () => {
    const brain = await openBrain()
    await brain.add({ data: 'one write', type: NounType.Concept })
    await brain.flush() // this one does the work

    const storage = (brain as unknown as { storage: { flushCounts: () => Promise<void> } }).storage
    const metadataIndex = (brain as unknown as { metadataIndex: { flush: () => Promise<void> } }).metadataIndex
    const countsSpy = vi.spyOn(storage, 'flushCounts')
    const metadataSpy = vi.spyOn(metadataIndex, 'flush')
    const logged: string[] = []
    const origLog = console.log
    console.log = ((...a: unknown[]) => { logged.push(a.map(String).join(' ')) }) as typeof console.log
    try {
      await brain.flush() // ...and this one has nothing to do
      await brain.flush()
      await brain.flush()
    } finally {
      console.log = origLog
    }

    expect(countsSpy).not.toHaveBeenCalled()
    expect(metadataSpy).not.toHaveBeenCalled()
    expect(logged.filter((l) => /All indexes flushed to disk/.test(l))).toEqual([])
  }, 120_000)

  it('one write earns exactly one flush', async () => {
    const brain = await openBrain()
    await brain.add({ data: 'first', type: NounType.Concept })
    await brain.flush()
    // Settle: the first write also kicked a BACKGROUND flush, which is not
    // awaited by design. Drain it before counting, or its provider calls land
    // inside this test's window and are attributed to the write below.
    await drainCadence(brain)

    // Count the flushes that actually RAN. (Provider spies cannot answer this:
    // the storage adapter's own count ledger is write-through, so a write calls
    // flushCounts() on its own account, with no flush involved.)
    const logged: string[] = []
    const origLog = console.log
    console.log = ((...a: unknown[]) => { logged.push(a.map(String).join(' ')) }) as typeof console.log
    const ran = () => logged.filter((l) => /All indexes flushed to disk/.test(l)).length
    try {
      await brain.add({ data: 'second — this is the cause', type: NounType.Concept })
      await brain.flush()
      expect(ran()).toBe(1)

      // No further cause, no further work.
      await brain.flush()
      await brain.flush()
      expect(ran()).toBe(1)
    } finally {
      console.log = origLog
    }
  }, 120_000)
})