From 57330c8fd1bb058869803810f48cbbf92e7d317d Mon Sep 17 00:00:00 2001 From: Garry Tan Date: Mon, 20 Jul 2026 10:25:07 -0700 Subject: [PATCH] =?UTF-8?q?fix(cli):=20keep=20doctor=20--json=20stdout=20c?= =?UTF-8?q?lean=20=E2=80=94=20v123=20migration=20handler=20printed=20to=20?= =?UTF-8?q?stdout?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The v123 configurable-FTS migration (#2941) logged its completion notice via console.log. Migrations run lazily inside any command's first DB connect, so on the nightly heavy run (fresh Postgres service DB) the line landed as the first line of `gbrain doctor --json` stdout and broke the fm_wallclock jq parse ("Invalid numeric literal at line 1, column 7", run 29731426470). runMigrations' contract routes all migration noise to stderr; move the v123 prints (and the pre-existing v2 slug-rename print) there. Also un-vacuous the fm_wallclock harness: its register-source step used `bun run -e` (bun dumps usage with exit 0 instead of running the code) and `connect({})` (in-memory), so the source was never registered and doctor scanned nothing. It now resolves the engine the way the CLI does and registers the source in the DB doctor actually reads. Regression test: test/migrate-stdout-clean.test.ts re-runs migrations from v122 asserting zero stdout writes, plus a source-level guard that migrate.ts contains no console.log. Co-Authored-By: Claude Fable 5 --- src/core/migrate.ts | 12 +++- test/migrate-stdout-clean.test.ts | 68 +++++++++++++++++++++++ tests/heavy/frontmatter_scan_wallclock.sh | 19 +++++-- 3 files changed, 92 insertions(+), 7 deletions(-) create mode 100644 test/migrate-stdout-clean.test.ts diff --git a/src/core/migrate.ts b/src/core/migrate.ts index 7b95a5767..1e42a958f 100644 --- a/src/core/migrate.ts +++ b/src/core/migrate.ts @@ -135,7 +135,10 @@ export const MIGRATIONS: Migration[] = [ } } } - if (renamed > 0) console.log(` Renamed ${renamed} slugs`); + // Migration progress goes to stderr — stdout must stay clean for + // callers parsing JSON (e.g. `gbrain doctor --json | jq`); migrations + // can run lazily inside ANY command's first DB connect. + if (renamed > 0) process.stderr.write(` Renamed ${renamed} slugs\n`); }, }, { @@ -5572,7 +5575,10 @@ export const MIGRATIONS: Migration[] = [ await engine.executeRaw(recreateChunksFn); if (lang === 'english') { - console.log(` v123: trigger functions recreated with language='english' (default — no backfill needed)`); + // stderr, NOT stdout: migrations run lazily inside any command's + // first DB connect — a console.log here polluted `doctor --json` + // stdout and broke jq consumers (heavy-tests fm_wallclock). + process.stderr.write(` v123: trigger functions recreated with language='english' (default — no backfill needed)\n`); return; } @@ -5593,7 +5599,7 @@ export const MIGRATIONS: Migration[] = [ WHERE search_vector IS NOT NULL; `); - console.log(` v123: trigger functions recreated with language='${lang}' + backfilled existing rows`); + process.stderr.write(` v123: trigger functions recreated with language='${lang}' + backfilled existing rows\n`); }, }, ]; diff --git a/test/migrate-stdout-clean.test.ts b/test/migrate-stdout-clean.test.ts new file mode 100644 index 000000000..f33e194b0 --- /dev/null +++ b/test/migrate-stdout-clean.test.ts @@ -0,0 +1,68 @@ +/** + * Migrations must never write to stdout — regression for the heavy-tests + * fm_wallclock failure (run 29731426470). + * + * Migrations run lazily inside ANY command's first DB connect (initSchema → + * runMigrations), including JSON-emitting commands like `gbrain doctor --json`. + * The v123 FTS migration (#2941) printed its completion notice via + * `console.log`, which landed as the first line of `doctor --json` stdout and + * broke every jq consumer ("Invalid numeric literal at line 1, column 7"). + * runMigrations' own contract (see the comment above its progress writes) + * routes ALL migration noise to stderr. + */ + +import { describe, test, expect, beforeAll, afterAll } from 'bun:test'; +import { readFileSync } from 'node:fs'; +import { join } from 'node:path'; +import { PGLiteEngine } from '../src/core/pglite-engine.ts'; +import { runMigrations } from '../src/core/migrate.ts'; + +describe('migration output stays off stdout', () => { + let engine: PGLiteEngine; + + beforeAll(async () => { + engine = new PGLiteEngine(); + await engine.connect({}); + await engine.initSchema(); + }); + + afterAll(async () => { + await engine.disconnect(); + }); + + test('re-running pending migrations (v122 → latest) writes nothing to stdout', async () => { + // Rewind the version stamp so the v123 handler actually re-executes — + // the exact state a CI Postgres/older brain is in when doctor connects. + await engine.setConfig('version', '122'); + + const stdoutWrites: string[] = []; + const origWrite = process.stdout.write.bind(process.stdout); + const origLog = console.log; + process.stdout.write = ((chunk: unknown, ...rest: unknown[]) => { + stdoutWrites.push(String(chunk)); + return (origWrite as (...a: unknown[]) => boolean)(chunk, ...rest); + }) as typeof process.stdout.write; + console.log = (...args: unknown[]) => { stdoutWrites.push(args.map(String).join(' ')); }; + + try { + const res = await runMigrations(engine); + // Load-bearing: the migration must have actually run for the stdout + // assertion to prove anything. + expect(res.applied).toBeGreaterThanOrEqual(1); + } finally { + process.stdout.write = origWrite; + console.log = origLog; + } + + expect(stdoutWrites).toEqual([]); + }, 60000); + + test('migrate.ts contains no console.log (all migration noise goes to stderr)', () => { + const src = readFileSync(join(import.meta.dir, '../src/core/migrate.ts'), 'utf8'); + const offenders = src + .split('\n') + .map((line, i) => ({ line, n: i + 1 })) + .filter(({ line }) => line.includes('console.log(')); + expect(offenders).toEqual([]); + }); +}); diff --git a/tests/heavy/frontmatter_scan_wallclock.sh b/tests/heavy/frontmatter_scan_wallclock.sh index b3b952069..162e4d129 100755 --- a/tests/heavy/frontmatter_scan_wallclock.sh +++ b/tests/heavy/frontmatter_scan_wallclock.sh @@ -92,11 +92,22 @@ timeout 120s bun run src/cli.ts init --pglite --yes --no-embedding >> "$LOG" 2>& # Register the brain dir as a source. Use raw SQL since `gbrain sources add` # might not exist in this version-window; the schema is what doctor reads. +# NOTE: must be `bun -e`, not `bun run -e` — `bun run` treats -e as an +# unknown script name and dumps its usage/script listing with exit 0, so the +# INSERT silently never ran and doctor scanned zero sources (vacuous pass). +# Resolve the engine the same way the CLI does (config + env), so the source +# lands in the DB doctor actually reads (Postgres when CI sets DATABASE_URL, +# the PGLite brain otherwise) — a hardcoded `connect({})` is in-memory and +# the INSERT would vanish. echo "[fm_wallclock] register source..." | tee -a "$LOG" -bun run -e " -import { PGLiteEngine } from './src/core/pglite-engine.ts'; -const e = new PGLiteEngine(); -await e.connect({}); +bun -e " +import { loadConfig, toEngineConfig } from './src/core/config.ts'; +import { createEngine } from './src/core/engine-factory.ts'; +const cfg = loadConfig(); +if (!cfg) throw new Error('no gbrain config — init failed?'); +const engineConfig = toEngineConfig(cfg); +const e = await createEngine(engineConfig); +await e.connect(engineConfig); await e.initSchema(); await e.executeRaw( \"INSERT INTO sources (id, name, local_path) VALUES ('fm-wallclock', 'Frontmatter wallclock test', \\\$1)\",