Merge pull request #3870 from cvqluu/fix/3772-log-bloat-and-epipe-suppression

fix(shared): cap log file growth via size-based rotation
2026-05-18 11:09:37 +09:00
parent 6037b91706 4713a90816
commit baa0470e2f
5 changed files with 301 additions and 5 deletions
@@ -4,7 +4,7 @@

 ## OVERVIEW

-Cross-cutting utilities used throughout the plugin. Barrel-exported from `index.ts`. Logger writes to `/tmp/oh-my-opencode.log`. Includes runtime shims for `Bun.file`, `Bun.write`, `Bun.hash`, `Bun.which`, `Bun.spawn` to support non-Bun runtimes (Electron-hosted OpenCode).
+Cross-cutting utilities used throughout the plugin. Barrel-exported from `index.ts`. Logger writes `oh-my-opencode.log` to the OS temp dir (Node's `os.tmpdir()` — `/tmp` on Linux, `%TEMP%` on Windows, etc.); rotated at 50 MB; up to 2 backups at `.1` / `.2`. Includes runtime shims for `Bun.file`, `Bun.write`, `Bun.hash`, `Bun.which`, `Bun.spawn` to support non-Bun runtimes (Electron-hosted OpenCode).

 ## CATEGORY MAP

@@ -47,7 +47,7 @@ Automatically transforms legacy config on load:

 | Utility | Import Count | Purpose |
 |---------|-------------|---------|
-| `logger.ts` | 62 | `/tmp/oh-my-opencode.log` |
+| `logger.ts` | 62 | `oh-my-opencode.log` in `os.tmpdir()` (50 MB cap, rotates to `.1`/`.2`) |
 | `data-path.ts` | 11 | XDG storage resolution |
 | `model-requirements.ts` | 11 | Agent fallback chains |
 | `system-directive.ts` | 11 | System message filtering |
@@ -0,0 +1,185 @@
+/// <reference types="bun-types" />
+
+// This test file mutates the logger module's singleton state. It must run in an
+// isolated CI batch so that other test files mocking `./shared` (the barrel that
+// re-exports this logger) cannot leak a no-op `log` into our imports. See
+// script/run-ci-tests.ts — the `mock.module(` substring routes the file out of
+// the shared batch.
+import { afterEach, beforeEach, describe, expect, mock, test } from "bun:test"
+mock.module("./logger-test-isolation", () => ({}))
+
+import * as fs from "fs"
+import * as os from "os"
+import * as path from "path"
+
+import {
+  _flushForTesting,
+  _resetLoggerForTesting,
+  _setLoggerForTesting,
+  getLogFilePath,
+  log,
+} from "./logger"
+
+const TEST_PREFIX = "oh-my-opencode-logger-test"
+
+function makeTempDir(): string {
+  return fs.mkdtempSync(path.join(os.tmpdir(), `${TEST_PREFIX}-`))
+}
+
+describe("#given the shared logger", () => {
+  let tempDir: string
+  let logFilePath: string
+
+  beforeEach(() => {
+    tempDir = makeTempDir()
+    logFilePath = path.join(tempDir, "log.txt")
+  })
+
+  afterEach(() => {
+    _resetLoggerForTesting()
+    fs.rmSync(tempDir, { recursive: true, force: true })
+  })
+
+  describe("#given log file size under threshold", () => {
+    test("#when log() is called and flushed #then the file is not rotated", () => {
+      _setLoggerForTesting({ filePath: logFilePath, maxSizeBytes: 1024, maxBackups: 2 })
+
+      log("small entry")
+      _flushForTesting()
+
+      expect(fs.existsSync(logFilePath)).toBe(true)
+      expect(fs.existsSync(`${logFilePath}.1`)).toBe(false)
+    })
+  })
+
+  describe("#given log file size over threshold", () => {
+    test("#when next flush runs #then the file rotates to .1 and a fresh file is created", () => {
+      _setLoggerForTesting({ filePath: logFilePath, maxSizeBytes: 100, maxBackups: 2 })
+
+      // Pre-fill the log file beyond the threshold so the next flush triggers rotation.
+      fs.writeFileSync(logFilePath, "x".repeat(200))
+
+      log("after rotation")
+      _flushForTesting()
+
+      // flush() appends first, then rotates — the in-flight batch becomes part
+      // of .1 so the post-flush primary is bounded to ≤ cap. The primary path
+      // is left absent after rotation; the next log() will re-create it on
+      // its next flush.
+      expect(fs.existsSync(`${logFilePath}.1`)).toBe(true)
+      const rotated = fs.readFileSync(`${logFilePath}.1`, "utf8")
+      expect(rotated).toContain("xxxx")
+      expect(rotated).toContain("after rotation")
+      expect(rotated.length).toBeGreaterThan(200)
+
+      expect(fs.existsSync(logFilePath)).toBe(false)
+
+      // A subsequent log() recreates the primary on its flush.
+      log("after recreation")
+      _flushForTesting()
+      expect(fs.existsSync(logFilePath)).toBe(true)
+      expect(fs.readFileSync(logFilePath, "utf8")).toContain("after recreation")
+    })
+
+    test("#when rotation happens repeatedly #then only maxBackups files are kept and the ladder shifts in order", () => {
+      _setLoggerForTesting({ filePath: logFilePath, maxSizeBytes: 100, maxBackups: 2 })
+
+      // First rotation
+      fs.writeFileSync(logFilePath, "first".repeat(50))
+      log("entry-A")
+      _flushForTesting()
+      expect(fs.existsSync(`${logFilePath}.1`)).toBe(true)
+      expect(fs.existsSync(`${logFilePath}.2`)).toBe(false)
+
+      // Second rotation
+      fs.writeFileSync(logFilePath, "second".repeat(50))
+      log("entry-B")
+      _flushForTesting()
+      expect(fs.existsSync(`${logFilePath}.1`)).toBe(true)
+      expect(fs.existsSync(`${logFilePath}.2`)).toBe(true)
+      // The previous .1 (containing entry-A) should now live at .2 — assert the
+      // ladder shifts in the expected direction so a regression that reverses
+      // the loop (.2 → .1) would fail here, not just silently keep two files.
+      expect(fs.readFileSync(`${logFilePath}.2`, "utf8")).toContain("entry-A")
+      expect(fs.readFileSync(`${logFilePath}.1`, "utf8")).toContain("entry-B")
+
+      // Third rotation should drop the oldest (.2) and shift .1 -> .2
+      fs.writeFileSync(logFilePath, "third".repeat(50))
+      log("entry-C")
+      _flushForTesting()
+      expect(fs.existsSync(`${logFilePath}.1`)).toBe(true)
+      expect(fs.existsSync(`${logFilePath}.2`)).toBe(true)
+      expect(fs.existsSync(`${logFilePath}.3`)).toBe(false)
+      // entry-A (oldest) was dropped; entry-B shifted from .1 to .2; entry-C is now .1.
+      expect(fs.readFileSync(`${logFilePath}.2`, "utf8")).toContain("entry-B")
+      expect(fs.readFileSync(`${logFilePath}.1`, "utf8")).toContain("entry-C")
+
+      // Total worst-case files on disk: primary + 2 backups
+      const survivors = fs
+        .readdirSync(tempDir)
+        .filter((name) => name.startsWith(path.basename(logFilePath)))
+      expect(survivors.length).toBeLessThanOrEqual(3)
+    })
+
+    test("#when log() is called past BUFFER_SIZE_LIMIT without explicit flush #then the inline flush path writes to disk", () => {
+      // BUFFER_SIZE_LIMIT in logger.ts is 50 — past that, log() flushes
+      // synchronously rather than scheduling a timer. A regression that drops
+      // the inline flush in favor of always scheduling would only surface here.
+      _setLoggerForTesting({ filePath: logFilePath, maxSizeBytes: 1024 * 1024, maxBackups: 2 })
+
+      for (let i = 0; i < 100; i += 1) {
+        log(`entry-${i}`)
+      }
+      // Note: no _flushForTesting() — relies on the inline flush at i=49 and i=99.
+
+      expect(fs.existsSync(logFilePath)).toBe(true)
+      const contents = fs.readFileSync(logFilePath, "utf8")
+      expect(contents).toContain("entry-0")
+      expect(contents).toContain("entry-99")
+    })
+  })
+
+  describe("#given filesystem failures during flush", () => {
+    test("#when the parent directory is missing #then append fails silently and does not throw", () => {
+      _setLoggerForTesting({
+        filePath: path.join(tempDir, "no-such-dir", "log.txt"),
+        maxSizeBytes: 10,
+        maxBackups: 2,
+      })
+
+      expect(() => {
+        log("entry")
+        _flushForTesting()
+      }).not.toThrow()
+    })
+
+    test("#when rotation fails partway through #then log() does not throw and primary keeps the entry", () => {
+      _setLoggerForTesting({ filePath: logFilePath, maxSizeBytes: 10, maxBackups: 2 })
+
+      // Pre-fill primary past the cap so rotateLogFileIfNeeded() actually triggers.
+      fs.writeFileSync(logFilePath, "x".repeat(200))
+      // Sabotage the oldest-eviction step: occupy the `.2` slot with a directory so
+      // unlinkSync inside rotateLogFileIfNeeded throws, exercising its inner catch.
+      // Portable: unlinkSync on a directory throws EISDIR on Linux/macOS and
+      // EPERM/EISDIR on Windows — both hit the catch.
+      fs.mkdirSync(`${logFilePath}.2`)
+
+      expect(() => {
+        log("entry")
+        _flushForTesting()
+      }).not.toThrow()
+
+      // appendFileSync succeeded; rotation failed silently; the primary still holds
+      // the new entry (rotation didn't move it) — confirms we reached the rotation
+      // path and recovered cleanly rather than short-circuiting on append failure.
+      expect(fs.readFileSync(logFilePath, "utf8")).toContain("entry")
+    })
+  })
+
+  describe("#given default configuration", () => {
+    test("#when getLogFilePath is called #then it points at os.tmpdir()", () => {
+      _resetLoggerForTesting()
+      expect(getLogFilePath().startsWith(os.tmpdir())).toBe(true)
+    })
+  })
+})
@@ -4,19 +4,53 @@ import * as path from "path"

 import { LOG_FILENAME } from "./plugin-identity"

-const logFile = path.join(os.tmpdir(), LOG_FILENAME)
+const DEFAULT_MAX_LOG_FILE_SIZE_BYTES = 50 * 1024 * 1024
+const DEFAULT_MAX_LOG_FILE_BACKUPS = 2
+
+let logFile = path.join(os.tmpdir(), LOG_FILENAME)
+let maxLogFileSizeBytes = DEFAULT_MAX_LOG_FILE_SIZE_BYTES
+let maxLogFileBackups = DEFAULT_MAX_LOG_FILE_BACKUPS

 let buffer: string[] = []
 let flushTimer: ReturnType<typeof setTimeout> | null = null
 const FLUSH_INTERVAL_MS = 500
 const BUFFER_SIZE_LIMIT = 50

+function rotateLogFileIfNeeded(): void {
+  // Best-effort, single-process: not safe under concurrent writers from sibling
+  // agents sharing the same tmpdir (worst case: one rotated backup is clobbered;
+  // primary writes still succeed). Same TOCTOU profile as
+  // src/openclaw/reply-listener-log.ts. All errors are swallowed because logging
+  // itself must never throw — a corrupt rotation state is preferable to crashing
+  // the agent over a temp-file rename failure.
+  try {
+    if (!fs.existsSync(logFile)) return
+    const stats = fs.statSync(logFile)
+    if (stats.size <= maxLogFileSizeBytes) return
+
+    const oldest = `${logFile}.${maxLogFileBackups}`
+    if (fs.existsSync(oldest)) {
+      fs.unlinkSync(oldest)
+    }
+    for (let i = maxLogFileBackups - 1; i >= 1; i -= 1) {
+      const src = `${logFile}.${i}`
+      const dst = `${logFile}.${i + 1}`
+      if (fs.existsSync(src)) {
+        fs.renameSync(src, dst)
+      }
+    }
+    fs.renameSync(logFile, `${logFile}.1`)
+  } catch {
+  }
+}
+
 function flush(): void {
  if (buffer.length === 0) return
  const data = buffer.join("")
  buffer = []
  try {
    fs.appendFileSync(logFile, data)
+    rotateLogFileIfNeeded()
  } catch {
  }
 }
@@ -46,3 +80,37 @@ export function log(message: string, data?: unknown): void {
 export function getLogFilePath(): string {
  return logFile
 }
+
+interface LoggerTestOverrides {
+  filePath?: string
+  maxSizeBytes?: number
+  maxBackups?: number
+}
+
+/** @internal test-only seam */
+export function _setLoggerForTesting(overrides: LoggerTestOverrides): void {
+  if (overrides.filePath !== undefined) logFile = overrides.filePath
+  if (overrides.maxSizeBytes !== undefined) maxLogFileSizeBytes = overrides.maxSizeBytes
+  if (overrides.maxBackups !== undefined) maxLogFileBackups = overrides.maxBackups
+}
+
+/** @internal test-only seam */
+export function _resetLoggerForTesting(): void {
+  logFile = path.join(os.tmpdir(), LOG_FILENAME)
+  maxLogFileSizeBytes = DEFAULT_MAX_LOG_FILE_SIZE_BYTES
+  maxLogFileBackups = DEFAULT_MAX_LOG_FILE_BACKUPS
+  buffer = []
+  if (flushTimer) {
+    clearTimeout(flushTimer)
+    flushTimer = null
+  }
+}
+
+/** @internal test-only seam: synchronously flush the buffer */
+export function _flushForTesting(): void {
+  if (flushTimer) {
+    clearTimeout(flushTimer)
+    flushTimer = null
+  }
+  flush()
+}