From 40e0f8b5ee2f36c9f99e6cc33f935f2763f15ec5 Mon Sep 17 00:00:00 2001 From: Sawyer Cutler Date: Fri, 7 Aug 2026 00:22:15 -0700 Subject: [PATCH 1/2] Route structured logs to a file instead of the console @intx/log installs a console sink as an import side effect, so a vendored logger's error could land on stdout mid-frame while the TUI held the alternate screen, corrupting the visible prompt box with a raw JSON log record. Install a file-backed sink as the first statement in mainWithRunners, before config loads or any other subsystem can log, replacing the console default entirely. The readable, human-facing error was already rendered elsewhere in the transcript; this only stops the duplicate raw log line from ever reaching the terminal. --- src/index.ts | 7 ++++ src/logging/sink.test.ts | 41 +++++++++++++++++++ src/logging/sink.ts | 62 ++++++++++++++++++++++++++++ src/tui-opentui/log-sink.test.ts | 69 ++++++++++++++++++++++++++++++++ 4 files changed, 179 insertions(+) create mode 100644 src/logging/sink.test.ts create mode 100644 src/logging/sink.ts create mode 100644 src/tui-opentui/log-sink.test.ts diff --git a/src/index.ts b/src/index.ts index 6fecafdd8..58f5cddca 100644 --- a/src/index.ts +++ b/src/index.ts @@ -3,6 +3,7 @@ import { LOG_NAMESPACE_ROOT } from "./branding.js"; import { primeCrashReporting, writeCrashReport, type CrashKind } from "./crash/report.js"; import { loadConfig } from "./config/index.js"; import { ensureTelemetrySettings, globalSettingsPath } from "./config/settings.js"; +import { installFileLogSink } from "./logging/sink.js"; import { flushPerfToOtel } from "./perf/index.js"; import { createTelemetry, telemetryDisabledByEnv } from "./telemetry/index.js"; import { getTelemetry, setTelemetry } from "./telemetry/singleton.js"; @@ -20,6 +21,12 @@ export async function mainWithRunners( argv: readonly string[], runners: Runners, ): Promise { + // Must run before any other line: @intx/log installs a console sink as a + // side effect of import, and loadConfig itself can log (e.g. healed + // settings). Once installed, this replaces that default so nothing — + // including a vendored dependency's logger — reaches the terminal the + // TUI is about to own. + installFileLogSink(); const config = await loadConfig(argv, { allowUnconfigured: true }); // Resolve the crash-report directory once, up front, while the process is // healthy. This is the only place project-key resolution (which shells diff --git a/src/logging/sink.test.ts b/src/logging/sink.test.ts new file mode 100644 index 000000000..03eb0d209 --- /dev/null +++ b/src/logging/sink.test.ts @@ -0,0 +1,41 @@ +import { describe, expect, spyOn, test } from "bun:test"; +import { mkdtempSync, readFileSync, rmSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { getLogger } from "@intx/log"; + +import { corbitsLogFilePath, installFileLogSink } from "./sink.js"; + +describe("corbitsLogFilePath", () => { + test("nests under the settings dir, not directly in home", () => { + expect(corbitsLogFilePath("/home/dev")).toBe("/home/dev/.corbits/logs/corbits.log"); + }); +}); + +describe("installFileLogSink", () => { + test("routes a logger's output to the file, never to stdout/stderr", () => { + const dir = mkdtempSync(join(tmpdir(), "corbits-sink-test-")); + const file = join(dir, "corbits.log"); + try { + installFileLogSink(file); + + const stdoutWrite = spyOn(process.stdout, "write"); + const stderrWrite = spyOn(process.stderr, "write"); + try { + getLogger(["some", "vendored", "logger"]).error("boom {detail}", { detail: "bad" }); + } finally { + stdoutWrite.mockRestore(); + stderrWrite.mockRestore(); + } + + expect(stdoutWrite).not.toHaveBeenCalled(); + expect(stderrWrite).not.toHaveBeenCalled(); + + const logged = readFileSync(file, "utf8"); + expect(logged).toContain("boom bad"); + expect(logged).toContain("some.vendored.logger"); + } finally { + rmSync(dir, { recursive: true, force: true }); + } + }); +}); diff --git a/src/logging/sink.ts b/src/logging/sink.ts new file mode 100644 index 000000000..f4f053d36 --- /dev/null +++ b/src/logging/sink.ts @@ -0,0 +1,62 @@ +import { appendFileSync, mkdirSync } from "node:fs"; +import { homedir } from "node:os"; +import { dirname, join } from "node:path"; + +import { configureSync } from "@intx/log"; + +import { SETTINGS_DIR_NAME } from "../branding.js"; + +// Matches LogTape's Sink shape structurally (see @logtape/logtape's +// sink.d.ts); not imported directly since only @intx/log is a declared +// dependency here. +type LogRecord = { + readonly category: readonly string[]; + readonly level: string; + readonly message: readonly unknown[]; + readonly timestamp: number; + readonly properties: Record; +}; + +export function corbitsLogFilePath(home: string = homedir()): string { + return join(home, SETTINGS_DIR_NAME, "logs", "corbits.log"); +} + +function formatRecord(record: LogRecord): string { + return ( + JSON.stringify({ + timestamp: new Date(record.timestamp).toISOString(), + level: record.level, + category: record.category.join("."), + message: record.message.join(""), + properties: record.properties, + }) + "\n" + ); +} + +/** + * Routes every logger — including ones inside vendored dependencies, which + * Corbits cannot edit — to a file instead of the console. + * + * `@intx/log` installs a console sink as a side effect of its first import + * (see its `default-sink` module), so a bare `getLogger` import is enough + * for a log call to reach stdout/stderr before Corbits does anything. This + * must run before any other Corbits code executes — first statement in + * `mainWithRunners` — so that race is never live: the TUI holds the + * alternate screen for the rest of the process, and anything landing on + * the real terminal mid-frame corrupts it. + */ +export function installFileLogSink(path: string = corbitsLogFilePath()): void { + mkdirSync(dirname(path), { recursive: true }); + configureSync({ + reset: true, + sinks: { + file: (record: LogRecord) => { + appendFileSync(path, formatRecord(record)); + }, + }, + loggers: [ + { category: ["logtape", "meta"], lowestLevel: "warning", sinks: ["file"] }, + { category: [], lowestLevel: "warning", sinks: ["file"] }, + ], + }); +} diff --git a/src/tui-opentui/log-sink.test.ts b/src/tui-opentui/log-sink.test.ts new file mode 100644 index 000000000..b9f77a0e0 --- /dev/null +++ b/src/tui-opentui/log-sink.test.ts @@ -0,0 +1,69 @@ +/** + * CL-5593: a raw structured log line from a vendored logger + * (`interchange.inference.default-director`) painted itself over the prompt + * box mid-frame, because nothing had ever pointed LogTape away from its + * default console sink. This drives the real shell in a live session and + * fires that exact logger the way the vendored code does, then asserts the + * rendered frame is untouched and nothing reached stdout/stderr. + */ +import { afterEach, beforeEach, describe, expect, spyOn, test } from "bun:test" +import { mkdtempSync, rmSync, readFileSync } from "node:fs" +import { tmpdir } from "node:os" +import { join } from "node:path" +import { getLogger } from "@intx/log" + +import { installFileLogSink } from "../logging/sink.js" +import { createAppShell } from "./shell.js" +import { withTestRenderer } from "./harness.js" + +describe("log sink during a live TUI session", () => { + let logDir: string + let logFile: string + + beforeEach(() => { + logDir = mkdtempSync(join(tmpdir(), "corbits-log-sink-test-")) + logFile = join(logDir, "corbits.log") + }) + + afterEach(() => { + rmSync(logDir, { recursive: true, force: true }) + }) + + test("a vendored logger's error never reaches stdout, stderr, or the frame", async () => { + installFileLogSink(logFile) + + const stdoutWrite = spyOn(process.stdout, "write") + const stderrWrite = spyOn(process.stderr, "write") + + try { + await withTestRenderer(async (h) => { + const shell = createAppShell(h.renderer, { cwd: "/workspace/corbits-code" }) + await h.renderOnce() + + const before = h.captureCharFrame() + expect(before).toContain("/workspace/corbits-code") + + // Same category and tagged-template call shape as + // vendor/intx-inference's default-director. + const vendoredLogger = getLogger(["interchange", "inference", "default-director"]) + vendoredLogger.error`Inference error in default director: ${"could not be verified"} [HTTP 400] (category: ${"fatal"})` + + await h.renderOnce() + const after = h.captureCharFrame() + + expect(after).toContain("/workspace/corbits-code") + expect(after).not.toContain("@timestamp") + expect(after).not.toContain("interchange.inference.default-director") + }) + } finally { + stdoutWrite.mockRestore() + stderrWrite.mockRestore() + } + + expect(stdoutWrite).not.toHaveBeenCalled() + expect(stderrWrite).not.toHaveBeenCalled() + + const logged = readFileSync(logFile, "utf8") + expect(logged).toContain("interchange.inference.default-director") + }) +}) From d1f982940e043df2d1fbf4d04cbf16ec61afdab1 Mon Sep 17 00:00:00 2001 From: Sawyer Cutler Date: Fri, 7 Aug 2026 00:36:20 -0700 Subject: [PATCH 2/2] Capture debug-level teardown diagnostics in the log file Filtering the file sink at warning silently disabled a dozen logger.debug calls written specifically to diagnose teardown races in the TUI and exec runners. A file has no screen to corrupt, so drop the floor to debug and let those diagnostics reach it. --- src/logging/sink.ts | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/logging/sink.ts b/src/logging/sink.ts index f4f053d36..45bb9d045 100644 --- a/src/logging/sink.ts +++ b/src/logging/sink.ts @@ -8,7 +8,9 @@ import { SETTINGS_DIR_NAME } from "../branding.js"; // Matches LogTape's Sink shape structurally (see @logtape/logtape's // sink.d.ts); not imported directly since only @intx/log is a declared -// dependency here. +// dependency here. The real type is strictly wider than this — if LogTape +// ever renames or narrows one of these fields, nothing here will catch the +// drift, so keep this in sync by hand if @intx/log's pinned version moves. type LogRecord = { readonly category: readonly string[]; readonly level: string; @@ -54,9 +56,14 @@ export function installFileLogSink(path: string = corbitsLogFilePath()): void { appendFileSync(path, formatRecord(record)); }, }, + // "debug" (not "warning"): a file has no screen to corrupt, and several + // teardown-race diagnostics (e.g. src/tui/runner.ts, src/exec/runner.ts) + // are logger.debug calls that exist specifically to be readable here + // after the fact. Filtering them out at the sink would silently disable + // the diagnostics the file exists to capture. loggers: [ { category: ["logtape", "meta"], lowestLevel: "warning", sinks: ["file"] }, - { category: [], lowestLevel: "warning", sinks: ["file"] }, + { category: [], lowestLevel: "debug", sinks: ["file"] }, ], }); }