perf(logging): buffer the file sink and rotate it

Each record opened, wrote, and closed the log file on the calling
turn, and the file grew without a cap. Batching keeps that path off
disk, and crash and exit flushes keep the tail.

Author: TheGreatAxios

src/index.ts

@@ -11,7 +11,7 @@ import {
   ensureTelemetrySettings,
   globalSettingsPath,
 } from "./config/settings.js";
-import { installFileLogSink } from "./logging/sink.js";
+import { flushFileLogSinkSync, 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";
@@ -120,6 +120,9 @@ export async function mainWithRunners(
   // Keep process.exit from dropping in-flight captures; the flush itself is
   // deadline-capped so exit stays snappy.
   await getTelemetry().flush();
+  // The file sink only queues on the hot path. Flush before returning so a
+  // normal exit does not lose the diagnostic tail.
+  flushFileLogSinkSync();
   return exitCode;
 }
 
@@ -165,5 +168,9 @@ if (import.meta.main) {
     dest.write(exit.text);
     code = exit.code;
   }
+  // Covers logs emitted after main returns, and the catch path, which never
+  // reaches the flush inside mainWithRunners. process.exit skips the microtask
+  // drain, so this has to be synchronous.
+  flushFileLogSinkSync();
   process.exit(code);
 }

src/logging/sink.test.ts

@@ -1,10 +1,19 @@
 import { describe, expect, spyOn, test } from "bun:test";
-import { mkdtempSync, readFileSync, rmSync } from "node:fs";
+import fs from "node:fs";
 import { tmpdir } from "node:os";
 import { join } from "node:path";
 import { getLogger } from "@intx/log";
 
-import { corbitsLogFilePath, installFileLogSink } from "./sink.js";
+import {
+  corbitsLogFilePath,
+  flushFileLogSinkSync,
+  installFileLogSink,
+} from "./sink.js";
+
+function tempLogFile(): { dir: string; file: string } {
+  const dir = fs.mkdtempSync(join(tmpdir(), "corbits-sink-test-"));
+  return { dir, file: join(dir, "corbits.log") };
+}
 
 describe("corbitsLogFilePath", () => {
   test("nests under the settings dir, not directly in home", () => {
@@ -16,8 +25,7 @@ describe("corbitsLogFilePath", () => {
 
 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");
+    const { dir, file } = tempLogFile();
     try {
       installFileLogSink(file);
 
@@ -27,6 +35,7 @@ describe("installFileLogSink", () => {
         getLogger(["some", "vendored", "logger"]).error("boom {detail}", {
           detail: "bad",
         });
+        flushFileLogSinkSync();
       } finally {
         stdoutWrite.mockRestore();
         stderrWrite.mockRestore();
@@ -35,11 +44,95 @@ describe("installFileLogSink", () => {
       expect(stdoutWrite).not.toHaveBeenCalled();
       expect(stderrWrite).not.toHaveBeenCalled();
 
-      const logged = readFileSync(file, "utf8");
+      const logged = fs.readFileSync(file, "utf8");
       expect(logged).toContain("boom bad");
       expect(logged).toContain("some.vendored.logger");
     } finally {
-      rmSync(dir, { recursive: true, force: true });
+      fs.rmSync(dir, { recursive: true, force: true });
+    }
+  });
+
+  test("queues records instead of appending once per call", () => {
+    const { dir, file } = tempLogFile();
+    const calls: string[] = [];
+    const append = spyOn(fs, "appendFileSync").mockImplementation((path) => {
+      calls.push(String(path));
+      const until = performance.now() + 5;
+      while (performance.now() < until) {
+        // A per-record sync append would make the burst pay this stall each time.
+      }
+    });
+    try {
+      installFileLogSink(file, { maxBytes: 10 * 1024 * 1024 });
+      const logger = getLogger(["logging", "burst"]);
+      const started = performance.now();
+      for (let i = 0; i < 20; i++) logger.info(`burst-${i}`);
+      const elapsed = performance.now() - started;
+      const duringBurst = calls.length;
+      expect(duringBurst).toBe(0);
+      // 20 sync appends would spend about 100ms inside the loop.
+      expect(elapsed).toBeLessThan(50);
+      expect(existsUnwritten(file)).not.toContain("burst-19");
+      flushFileLogSinkSync();
+      expect(calls.length).toBeGreaterThan(0);
+      expect(calls.length).toBeLessThan(20);
+    } finally {
+      append.mockRestore();
+      fs.rmSync(dir, { recursive: true, force: true });
+    }
+  });
+
+  test("rotates the active log once it passes the size cap", () => {
+    const { dir, file } = tempLogFile();
+    try {
+      installFileLogSink(file, { maxBytes: 500 });
+      const logger = getLogger(["logging", "rotate"]);
+      for (let i = 0; i < 40; i++) {
+        logger.info(`rotate-line-${i}-xxxxxxxxxxxxxxxxxxxx`);
+      }
+      flushFileLogSinkSync();
+      const rotated = `${file}.1`;
+      expect(fs.existsSync(rotated)).toBe(true);
+      const previous = fs.readFileSync(rotated, "utf8");
+      const active = fs.readFileSync(file, "utf8");
+      const earlier = lineIndex(previous);
+      const later = lineIndex(active);
+      expect(earlier).toBeLessThan(later);
+      expect(active).not.toContain(`rotate-line-${earlier}-`);
+      expect(Buffer.byteLength(previous)).toBeLessThanOrEqual(500);
+      expect(Buffer.byteLength(active)).toBeLessThanOrEqual(500);
+      expect(previous + active).not.toContain("rotate-line-0-");
+      expect(active).toContain("rotate-line-39-");
+    } finally {
+      fs.rmSync(dir, { recursive: true, force: true });
+    }
+  });
+
+  test("a crash or exit flush writes the pending tail", () => {
+    const { dir, file } = tempLogFile();
+    try {
+      installFileLogSink(file);
+      expect(process.listeners("exit")).toContain(flushFileLogSinkSync);
+      getLogger(["logging", "crash"]).error("pending-tail");
+      const before = fs.existsSync(file) ? fs.readFileSync(file, "utf8") : "";
+      expect(before).not.toContain("pending-tail");
+      // Same function handleFatal, signal exit, and process exit call.
+      flushFileLogSinkSync();
+      expect(fs.readFileSync(file, "utf8")).toContain("pending-tail");
+    } finally {
+      fs.rmSync(dir, { recursive: true, force: true });
     }
   });
 });
+
+function lineIndex(text: string): number {
+  const match = /rotate-line-(\d+)-/.exec(text);
+  if (match === null || match[1] === undefined) {
+    throw new Error("rotated log is missing a record");
+  }
+  return Number(match[1]);
+}
+
+function existsUnwritten(file: string): string {
+  return fs.existsSync(file) ? fs.readFileSync(file, "utf8") : "";
+}

src/logging/sink.ts

@@ -1,4 +1,4 @@
-import { appendFileSync, mkdirSync } from "node:fs";
+import fs from "node:fs";
 import { homedir } from "node:os";
 import { dirname, join } from "node:path";
 
@@ -19,10 +19,24 @@ interface LogRecord {
   readonly properties: Record<string, unknown>;
 }
 
+/** One generation is kept beside the active file (`corbits.log.1`). */
+const LOG_MAX_BYTES = 10 * 1024 * 1024;
+
 export function corbitsLogFilePath(home: string = homedir()): string {
   return join(home, SETTINGS_DIR_NAME, "logs", "corbits.log");
 }
 
+interface FileSinkState {
+  readonly path: string;
+  readonly maxBytes: number;
+  buffer: string[];
+  size: number;
+  drainScheduled: boolean;
+}
+
+let state: FileSinkState | null = null;
+let exitHookInstalled = false;
+
 function formatRecord(record: LogRecord): string {
   return (
     JSON.stringify({
@@ -35,6 +49,107 @@ function formatRecord(record: LogRecord): string {
   );
 }
 
+function fileSize(path: string): number {
+  try {
+    return fs.statSync(path).size;
+  } catch {
+    return 0;
+  }
+}
+
+function rotateActive(current: FileSinkState): void {
+  const rotated = `${current.path}.1`;
+  try {
+    fs.rmSync(rotated, { force: true });
+    fs.renameSync(current.path, rotated);
+    current.size = 0;
+  } catch {
+    try {
+      // rename can fail (missing file, cross-device); truncating still caps growth.
+      fs.truncateSync(current.path, 0);
+      current.size = 0;
+    } catch {
+      // Keep `size` so a later flush retries instead of appending forever.
+    }
+  }
+}
+
+function writeBatch(
+  current: FileSinkState,
+  batch: string[],
+  bytes: number,
+): void {
+  if (bytes === 0) return;
+  try {
+    fs.appendFileSync(current.path, batch.join(""));
+    current.size += bytes;
+  } catch {
+    // A full disk must not paint the terminal or abort a crash exit.
+  }
+}
+
+function writeLines(current: FileSinkState, lines: readonly string[]): void {
+  let batch: string[] = [];
+  let batchBytes = 0;
+  const flushBatch = (): void => {
+    writeBatch(current, batch, batchBytes);
+    batch = [];
+    batchBytes = 0;
+  };
+  for (const line of lines) {
+    const lineBytes = Buffer.byteLength(line);
+    if (
+      batchBytes > 0 &&
+      current.size + batchBytes + lineBytes > current.maxBytes
+    ) {
+      flushBatch();
+    }
+    // Rotate only once the active file already holds bytes. A single record
+    // larger than the cap still lands, then the next record starts a new file.
+    if (current.size > 0 && current.size + lineBytes > current.maxBytes) {
+      rotateActive(current);
+    }
+    batch.push(line);
+    batchBytes += lineBytes;
+  }
+  flushBatch();
+}
+
+/**
+ * Writes the buffered tail. Crash and exit paths must call this: the hot
+ * path only queues, and `process.exit` does not run the microtask drain.
+ * Also registered on `exit` so a path that skips the explicit call still
+ * keeps the tail. Buffering can still drop records if the process is killed
+ * before either flush runs.
+ */
+export function flushFileLogSinkSync(): void {
+  const current = state;
+  if (current === null) return;
+  current.drainScheduled = false;
+  if (current.buffer.length === 0) return;
+  const lines = current.buffer;
+  current.buffer = [];
+  writeLines(current, lines);
+}
+
+function enqueue(record: LogRecord): void {
+  const current = state;
+  if (current === null) return;
+  current.buffer.push(formatRecord(record));
+  if (current.drainScheduled) return;
+  current.drainScheduled = true;
+  const scheduled = current;
+  queueMicrotask(() => {
+    if (state !== scheduled) return;
+    flushFileLogSinkSync();
+  });
+}
+
+interface FileLogSinkOptions {
+  /** Rotate the active file once it reaches this many bytes. */
+  readonly maxBytes?: number;
+}
+
 /**
  * Routes every logger — including ones inside vendored dependencies, which
  * Corbits cannot edit — to a file instead of the console.
@@ -45,14 +160,35 @@ function formatRecord(record: LogRecord): string {
  * statement in `mainWithRunners`: the TUI holds the alternate screen for
  * the rest of the process, and anything landing on the real terminal
  * mid-frame corrupts it.
+ *
+ * Records are queued and appended in batches so a burst does not open the
+ * file once per line. The active log rotates once it reaches 10 MiB.
  */
-export function installFileLogSink(path: string = corbitsLogFilePath()): void {
-  mkdirSync(dirname(path), { recursive: true });
+export function installFileLogSink(
+  path: string = corbitsLogFilePath(),
+  options?: FileLogSinkOptions,
+): void {
+  // A later install must not drop lines still queued for the previous path.
+  flushFileLogSinkSync();
+  fs.mkdirSync(dirname(path), { recursive: true });
+  const requested = options?.maxBytes;
+  state = {
+    path,
+    maxBytes:
+      requested !== undefined && requested > 0 ? requested : LOG_MAX_BYTES,
+    buffer: [],
+    size: fileSize(path),
+    drainScheduled: false,
+  };
+  if (!exitHookInstalled) {
+    exitHookInstalled = true;
+    process.on("exit", flushFileLogSinkSync);
+  }
   configureSync({
     reset: true,
     sinks: {
       file: (record: LogRecord) => {
-        appendFileSync(path, formatRecord(record));
+        enqueue(record);
       },
     },
     // "debug" (not "warning"): a file has no screen to corrupt, and the

src/process-handlers.ts

@@ -3,6 +3,7 @@ import {
   writeCrashReport,
   type CrashKind,
 } from "./crash/report.js";
+import { flushFileLogSinkSync } from "./logging/sink.js";
 import { getActiveRun, markCrashed } from "./session/active-run.js";
 import { printResumeHint } from "./session/resume-hint.js";
 import { getActiveDisposeHost } from "./session/active-host.js";
@@ -84,6 +85,8 @@ export async function handleFatal(
     error_class: classifyErrorClass(error),
   });
   await getTelemetry().flush();
+  // Buffered log lines never reach disk if we exit before the microtask drain.
+  flushFileLogSinkSync();
   process.exit(1);
 }
 
@@ -194,6 +197,7 @@ export function installSignalHandlers(options?: ProcessHandlerOptions): void {
         const run = getActiveRun();
         if (run !== null) printResumeHint(run.sessionId);
         await finalizeActiveRunOnSignal(signal);
+        flushFileLogSinkSync();
         process.exit(128 + SIGNAL_EXIT_NUMBER[signal]);
       })();
     });