From d49148e1407cc14a5de031f605e081bff30cb399 Mon Sep 17 00:00:00 2001 From: David Snelling Date: Fri, 28 Aug 2026 12:30:30 -0700 Subject: [PATCH] fix(vfs): the old-root sweep narrates only when it has something to say MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The release gate's own output caught this: every test brain printed "[VFS] old-root sweep complete in 1ms and recorded" — hundreds of lines — and a consumer would get two of them on the first open of every store. They were emitted on the always-visible channel, which a production log level deliberately CANNOT silence. That channel exists so an operator can always learn why a database is slow; a 0ms no-op on a fresh store is not that, and announcing it there trains people to ignore the one channel built to be impossible to ignore. It was also inconsistent with every other narration in this work, all of which is silent under a threshold. The sweep now speaks when it has something to say — duplicate roots removed, or a wall over a second that a person watching a slow first open deserves explained — and otherwise does its work, records its marker, and stays quiet. cleanupOldRoots() reports what it removed so the decision rests on a fact rather than on a guess. Pin: a fresh store's sweep emits nothing on the channel and still records its marker, so the silence can never be mistaken for the work being skipped. --- src/vfs/VirtualFileSystem.ts | 40 ++++++++++++++----- tests/integration/vfs-root-sweep-once.test.ts | 27 +++++++++++++ 2 files changed, 56 insertions(+), 11 deletions(-) diff --git a/src/vfs/VirtualFileSystem.ts b/src/vfs/VirtualFileSystem.ts index 19470b48..46c6a12d 100644 --- a/src/vfs/VirtualFileSystem.ts +++ b/src/vfs/VirtualFileSystem.ts @@ -76,6 +76,11 @@ export class VirtualFileSystem implements IVirtualFileSystem { * `_system/`, like every other marker there — never enumerated as data. */ private static readonly ROOT_SWEEP_MARKER_PATH = '_system/vfs-root-sweep.json' + /** + * Below this wall, a sweep that removed nothing says nothing — see + * {@link sweepOldRootsIfNeeded}. + */ + private static readonly ROOT_SWEEP_NARRATE_MS = 1_000 private currentUser: string = 'system' // Track current user for collaboration // Knowledge Layer features available via augmentation (brain.use('knowledge')) @@ -434,21 +439,31 @@ export class VirtualFileSystem implements IVirtualFileSystem { } catch { // Unreadable marker: sweep, and rewrite it below. } - prodLog.narrate( - '[VFS] one-time sweep for pre-fixed-id root directories running in the background — ' + - 'the open does not wait for it, and once it has run this store never sweeps again.' - ) + // NARRATION HAS A THRESHOLD, like every other line this engine emits on the + // always-visible channel. On a fresh or small store this sweep finds + // nothing and costs a millisecond, and announcing it — twice — on a + // channel a production log level deliberately CANNOT silence would train + // operators to ignore the one channel that exists to be impossible to + // ignore. It speaks when it has something to say: duplicates removed, or a + // wall long enough that somebody watching a slow first open deserves to + // know what is running. Otherwise it does its work and stays quiet. const startedAt = Date.now() - await this.cleanupOldRoots() + const duplicatesRemoved = await this.cleanupOldRoots() + const elapsedMs = Date.now() - startedAt try { await store.writeRawObject(VirtualFileSystem.ROOT_SWEEP_MARKER_PATH, { sweptAt: new Date().toISOString(), - durationMs: Date.now() - startedAt + durationMs: elapsedMs }) - prodLog.narrate( - `[VFS] old-root sweep complete in ${Date.now() - startedAt}ms and recorded — ` + - 'no future open pays for it.' - ) + if (duplicatesRemoved > 0 || elapsedMs >= VirtualFileSystem.ROOT_SWEEP_NARRATE_MS) { + prodLog.narrate( + `[VFS] one-time old-root sweep complete in ${elapsedMs}ms` + + (duplicatesRemoved > 0 + ? `, ${duplicatesRemoved} pre-fixed-id root(s) removed` + : '') + + ' and recorded — no future open pays for it.' + ) + } } catch (error) { // Unrecorded sweep = the next open sweeps again. Conservative, and said // out loud rather than quietly repeated forever. @@ -495,7 +510,8 @@ export class VirtualFileSystem implements IVirtualFileSystem { return null } - private async cleanupOldRoots(): Promise { + private async cleanupOldRoots(): Promise { + let removed = 0 try { // Find any old VFS roots with UUID-based IDs (not our fixed ID) const oldRoots = await this.brain.find({ @@ -517,6 +533,7 @@ export class VirtualFileSystem implements IVirtualFileSystem { for (const duplicate of duplicates) { try { await this.brain.remove(duplicate.id) + removed++ console.log(`VFS: Deleted old root ${duplicate.id.substring(0, 8)}`) } catch (error) { console.warn(`VFS: Failed to delete old root ${duplicate.id}:`, error) @@ -529,6 +546,7 @@ export class VirtualFileSystem implements IVirtualFileSystem { // Non-critical error - log and continue console.warn('VFS: Cleanup of old roots failed (non-critical):', error) } + return removed } /** diff --git a/tests/integration/vfs-root-sweep-once.test.ts b/tests/integration/vfs-root-sweep-once.test.ts index f84f4413..cac59b70 100644 --- a/tests/integration/vfs-root-sweep-once.test.ts +++ b/tests/integration/vfs-root-sweep-once.test.ts @@ -20,6 +20,7 @@ import { join } from 'node:path' import { Brainy } from '../../src/brainy.js' import { NounType } from '../../src/types/graphTypes.js' import { VirtualFileSystem } from '../../src/vfs/VirtualFileSystem.js' +import { prodLog } from '../../src/utils/logger.js' describe('the VFS old-root sweep', () => { const dirs: string[] = [] @@ -80,6 +81,32 @@ describe('the VFS old-root sweep', () => { expect(sweepSpy).not.toHaveBeenCalled() }, 180_000) + it('a sweep that removes nothing on a fresh store says nothing', async () => { + const dir = mkdtempSync(join(tmpdir(), 'brainy-root-sweep-quiet-')) + dirs.push(dir) + + // The always-visible channel cannot be silenced by a log level, so a line + // on it has to earn its place. A fresh store's sweep finds no duplicate + // roots and costs a millisecond — it must do its work, record its marker, + // and stay quiet, or it trains operators to ignore the one channel that + // exists to be impossible to ignore. + const narrated: string[] = [] + const spy = vi.spyOn(prodLog, 'narrate').mockImplementation(((...args: unknown[]) => { + narrated.push(args.map((a) => String(a)).join(' ')) + }) as typeof prodLog.narrate) + + const brain = await open(dir) + await (brain.vfs as unknown as { whenRootSweepSettled: () => Promise }).whenRootSweepSettled() + spy.mockRestore() + + expect(narrated.filter((l) => /old-root sweep/i.test(l))).toEqual([]) + // ...and it still did the work: the marker is recorded, so no future open sweeps. + expect( + existsSync(join(dir, '_system', 'vfs-root-sweep.json')) || + existsSync(join(dir, '_system', 'vfs-root-sweep.json.gz')) + ).toBe(true) + }, 180_000) + it('the open does not wait for the sweep', async () => { const dir = mkdtempSync(join(tmpdir(), 'brainy-root-sweep-async-')) dirs.push(dir)