From cd89adf0ac01c169ecd002cea7bc1615705c295e Mon Sep 17 00:00:00 2001 From: Vincent Koc Date: Sat, 25 Apr 2026 22:50:38 -0700 Subject: [PATCH] fix(logging): rotate file logs instead of suppressing --- CHANGELOG.md | 4 ++ docs/gateway/configuration-reference.md | 2 +- docs/gateway/logging.md | 2 + docs/logging.md | 5 ++ src/config/types.base.ts | 2 +- src/logging/log-file-size-cap.test.ts | 57 +++++++++++----- src/logging/logger-env.test.ts | 2 +- src/logging/logger.ts | 88 ++++++++++++++++++------- src/logging/subsystem.test.ts | 34 +++++++++- src/logging/subsystem.ts | 11 +--- 10 files changed, 155 insertions(+), 52 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index ff8aa448e42..27f171d4ccf 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -104,6 +104,10 @@ Docs: https://docs.openclaw.ai OpenClaw config path in bundled runtimes, so packaged gateways stop falling back to `/tmp/openclaw`. Fixes #59370, #67168, and #61295. Thanks @KeaneYan, @Pan9hu, and @zsjlovelike. +- Logging: rotate file logs at `logging.maxFileBytes`, keep bounded numbered + archives, and make long-lived rolling loggers follow the current-day file + instead of suppressing diagnostics or writing stale dated files. Fixes #58583 + and #62381. Thanks @jpeghead and @zhaoleink. - Agents/groups: treat clean empty assistant stops as silent `NO_REPLY` only for always-on groups where silent replies are allowed, while keeping direct and mention-gated sessions on the incomplete-turn retry path. Thanks @MagnaAI. - macOS/Node: keep native remote app nodes from advertising `browser.proxy`, start browser-capable CLI node services through the restored diff --git a/docs/gateway/configuration-reference.md b/docs/gateway/configuration-reference.md index 8c8402affee..5458564605b 100644 --- a/docs/gateway/configuration-reference.md +++ b/docs/gateway/configuration-reference.md @@ -858,7 +858,7 @@ Notes: - Default log file: `/tmp/openclaw/openclaw-YYYY-MM-DD.log`. - Set `logging.file` for a stable path. - `consoleLevel` bumps to `debug` when `--verbose`. -- `maxFileBytes`: maximum log file size in bytes before writes are suppressed (positive integer; default: `524288000` = 500 MB). Use external log rotation for production deployments. +- `maxFileBytes`: maximum active log file size in bytes before rotation (positive integer; default: `104857600` = 100 MB). OpenClaw keeps up to five numbered archives beside the active file. --- diff --git a/docs/gateway/logging.md b/docs/gateway/logging.md index 881ae5d3ada..7fe1a17d1c1 100644 --- a/docs/gateway/logging.md +++ b/docs/gateway/logging.md @@ -19,6 +19,8 @@ OpenClaw has two log “surfaces”: - Default rolling log file is under `/tmp/openclaw/` (one file per day): `openclaw-YYYY-MM-DD.log` - Date uses the gateway host's local timezone. +- Active log files rotate at `logging.maxFileBytes` (default: 100 MB), keeping + up to five numbered archives and continuing to write a fresh active file. - The log file path and level can be configured via `~/.openclaw/openclaw.json`: - `logging.file` - `logging.level` diff --git a/docs/logging.md b/docs/logging.md index 563a0d2f111..8fb1489439c 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -23,6 +23,11 @@ By default, the Gateway writes a rolling log file under: The date uses the gateway host's local timezone. +Each file rotates when it reaches `logging.maxFileBytes` (default: 100 MB). +OpenClaw keeps up to five numbered archives beside the active file, such as +`openclaw-YYYY-MM-DD.1.log`, and keeps writing to a fresh active log instead of +suppressing diagnostics. + You can override this in `~/.openclaw/openclaw.json`: ```json diff --git a/src/config/types.base.ts b/src/config/types.base.ts index eb58997a9da..8b3a9cf82dd 100644 --- a/src/config/types.base.ts +++ b/src/config/types.base.ts @@ -221,7 +221,7 @@ export type SessionMaintenanceConfig = { export type LoggingConfig = { level?: "silent" | "fatal" | "error" | "warn" | "info" | "debug" | "trace"; file?: string; - /** Maximum size of a single log file in bytes before writes are suppressed. Default: 500 MB. */ + /** Maximum size of a single log file in bytes before rotation. Default: 100 MB. */ maxFileBytes?: number; consoleLevel?: "silent" | "fatal" | "error" | "warn" | "info" | "debug" | "trace"; consoleStyle?: "pretty" | "compact" | "json"; diff --git a/src/logging/log-file-size-cap.test.ts b/src/logging/log-file-size-cap.test.ts index 45007bd632b..d1c451a6da9 100644 --- a/src/logging/log-file-size-cap.test.ts +++ b/src/logging/log-file-size-cap.test.ts @@ -1,4 +1,5 @@ import fs from "node:fs"; +import path from "node:path"; import { afterAll, afterEach, beforeAll, beforeEach, describe, expect, it, vi } from "vitest"; import { getLogger, @@ -8,9 +9,15 @@ import { } from "../logging.js"; import { createSuiteLogPathTracker } from "./log-test-helpers.js"; -const DEFAULT_MAX_FILE_BYTES = 500 * 1024 * 1024; +const DEFAULT_MAX_FILE_BYTES = 100 * 1024 * 1024; const logPathTracker = createSuiteLogPathTracker("openclaw-log-cap-"); +function rotatedLogPath(file: string, index: number): string { + const ext = path.extname(file); + const base = file.slice(0, file.length - ext.length); + return `${base}.${index}${ext}`; +} + describe("log file size cap", () => { let logPath = ""; @@ -27,6 +34,7 @@ describe("log file size cap", () => { afterEach(() => { resetLogger(); setLoggerOverride(null); + vi.useRealTimers(); vi.restoreAllMocks(); try { fs.rmSync(logPath, { force: true }); @@ -39,7 +47,7 @@ describe("log file size cap", () => { await logPathTracker.cleanup(); }); - it("defaults maxFileBytes to 500 MB when unset", () => { + it("defaults maxFileBytes to 100 MB when unset", () => { setLoggerOverride({ level: "info", file: logPath }); expect(getResolvedLoggerSettings().maxFileBytes).toBe(DEFAULT_MAX_FILE_BYTES); }); @@ -49,27 +57,42 @@ describe("log file size cap", () => { expect(getResolvedLoggerSettings().maxFileBytes).toBe(2048); }); - it("suppresses file writes after cap is reached and warns once", () => { + it("rotates file writes after cap is reached and keeps logging", () => { const stderrSpy = vi.spyOn(process.stderr, "write").mockImplementation( () => true as unknown as ReturnType, // preserve stream contract in test spy ); - setLoggerOverride({ level: "info", file: logPath, maxFileBytes: 1024 }); + setLoggerOverride({ level: "info", file: logPath, maxFileBytes: 256 }); const logger = getLogger(); - for (let i = 0; i < 200; i++) { - logger.error(`network-failure-${i}-${"x".repeat(80)}`); - } - const sizeAfterCap = fs.statSync(logPath).size; - for (let i = 0; i < 20; i++) { - logger.error(`post-cap-${i}-${"y".repeat(80)}`); - } - const sizeAfterExtraLogs = fs.statSync(logPath).size; + logger.error(`network-failure-${"x".repeat(400)}`); + logger.error("post-rotation-diagnostic"); - expect(sizeAfterExtraLogs).toBe(sizeAfterCap); - expect(sizeAfterCap).toBeLessThanOrEqual(1024 + 512); - const capWarnings = stderrSpy.mock.calls + const currentContent = fs.readFileSync(logPath, "utf8"); + const archiveContent = fs.readFileSync(rotatedLogPath(logPath, 1), "utf8"); + expect(currentContent).toContain("post-rotation-diagnostic"); + expect(currentContent).not.toContain("network-failure"); + expect(archiveContent).toContain("network-failure"); + const rotationWarnings = stderrSpy.mock.calls .map(([firstArg]) => String(firstArg)) - .filter((line) => line.includes("log file size cap reached")); - expect(capWarnings).toHaveLength(1); + .filter((line) => line.includes("log file rotation failed")); + expect(rotationWarnings).toHaveLength(0); + }); + + it("keeps cached default rolling loggers on the current-day file", () => { + const logDir = path.dirname(logPath); + const firstDay = path.join(logDir, "openclaw-2026-01-01.log"); + const secondDay = path.join(logDir, "openclaw-2026-01-02.log"); + vi.useFakeTimers(); + vi.setSystemTime(new Date("2026-01-01T08:00:00Z")); + setLoggerOverride({ level: "info", file: firstDay }); + const logger = getLogger(); + + logger.info({ message: "first day" }); + vi.setSystemTime(new Date("2026-01-02T08:00:00Z")); + logger.info({ message: "second day" }); + + expect(fs.readFileSync(firstDay, "utf8")).toContain("first day"); + expect(fs.readFileSync(secondDay, "utf8")).toContain("second day"); + expect(fs.readFileSync(firstDay, "utf8")).not.toContain("second day"); }); }); diff --git a/src/logging/logger-env.test.ts b/src/logging/logger-env.test.ts index a40179ea08d..7b923b76240 100644 --- a/src/logging/logger-env.test.ts +++ b/src/logging/logger-env.test.ts @@ -8,7 +8,7 @@ import { import { createSuiteLogPathTracker } from "./log-test-helpers.js"; import { loggingState } from "./state.js"; -const defaultMaxFileBytes = 500 * 1024 * 1024; +const defaultMaxFileBytes = 100 * 1024 * 1024; const logPathTracker = createSuiteLogPathTracker("openclaw-test-env-log-level-"); describe("OPENCLAW_LOG_LEVEL", () => { diff --git a/src/logging/logger.ts b/src/logging/logger.ts index 8a750c9b800..db3ccbd2ba0 100644 --- a/src/logging/logger.ts +++ b/src/logging/logger.ts @@ -55,7 +55,8 @@ export const DEFAULT_LOG_FILE = resolveDefaultLogFile(DEFAULT_LOG_DIR); // legac const LOG_PREFIX = "openclaw"; const LOG_SUFFIX = ".log"; const MAX_LOG_AGE_MS = 24 * 60 * 60 * 1000; // 24h -const DEFAULT_MAX_LOG_FILE_BYTES = 500 * 1024 * 1024; // 500 MB +const DEFAULT_MAX_LOG_FILE_BYTES = 100 * 1024 * 1024; // 100 MB +const MAX_ROTATED_LOG_FILES = 5; type LogObj = { date?: Date } & Record; @@ -397,39 +398,45 @@ function buildLogger(settings: ResolvedSettings): TsLogger { return logger; } - fs.mkdirSync(path.dirname(settings.file), { recursive: true }); + const rollingFile = isRollingPath(settings.file); + let activeFile = resolveActiveLogFile(settings.file); + fs.mkdirSync(path.dirname(activeFile), { recursive: true }); // Clean up stale rolling logs when using a dated log filename. - if (isRollingPath(settings.file)) { - pruneOldRollingLogs(path.dirname(settings.file)); + if (rollingFile) { + pruneOldRollingLogs(path.dirname(activeFile)); } - let currentFileBytes = getCurrentLogFileBytes(settings.file); - let warnedAboutSizeCap = false; + let currentFileBytes = getCurrentLogFileBytes(activeFile); + let warnedAboutRotationFailure = false; logger.attachTransport((logObj: LogObj) => { try { + const nextActiveFile = resolveActiveLogFile(settings.file); + if (nextActiveFile !== activeFile) { + activeFile = nextActiveFile; + fs.mkdirSync(path.dirname(activeFile), { recursive: true }); + if (rollingFile) { + pruneOldRollingLogs(path.dirname(activeFile)); + } + currentFileBytes = getCurrentLogFileBytes(activeFile); + } const time = formatTimestamp(logObj.date ?? new Date(), { style: "long" }); const line = redactSensitiveText(JSON.stringify({ ...logObj, time })); const payload = `${line}\n`; const payloadBytes = Buffer.byteLength(payload, "utf8"); const nextBytes = currentFileBytes + payloadBytes; - if (nextBytes > settings.maxFileBytes) { - if (!warnedAboutSizeCap) { - warnedAboutSizeCap = true; - const warningLine = JSON.stringify({ - time: formatTimestamp(new Date(), { style: "long" }), - level: "warn", - subsystem: "logging", - message: `log file size cap reached; suppressing writes file=${settings.file} maxFileBytes=${settings.maxFileBytes}`, - }); - appendLogLine(settings.file, `${warningLine}\n`); + if (currentFileBytes > 0 && nextBytes > settings.maxFileBytes) { + if (rotateLogFile(activeFile)) { + currentFileBytes = getCurrentLogFileBytes(activeFile); + warnedAboutRotationFailure = false; + } else if (!warnedAboutRotationFailure) { + warnedAboutRotationFailure = true; process.stderr.write( - `[openclaw] log file size cap reached; suppressing writes file=${settings.file} maxFileBytes=${settings.maxFileBytes}\n`, + `[openclaw] log file rotation failed; continuing writes file=${activeFile} maxFileBytes=${settings.maxFileBytes}\n`, ); } - return; } - if (appendLogLine(settings.file, payload)) { - currentFileBytes = nextBytes; + if (appendLogLine(activeFile, payload)) { + currentFileBytes += payloadBytes; } } catch { // never block on logging failures @@ -554,8 +561,19 @@ function formatLocalDate(date: Date): string { } function defaultRollingPathForToday(): string { - const today = formatLocalDate(new Date()); - return path.join(DEFAULT_LOG_DIR, `${LOG_PREFIX}-${today}${LOG_SUFFIX}`); + return rollingPathForDate(DEFAULT_LOG_DIR, new Date()); +} + +function rollingPathForDate(dir: string, date: Date): string { + const today = formatLocalDate(date); + return path.join(dir, `${LOG_PREFIX}-${today}${LOG_SUFFIX}`); +} + +function resolveActiveLogFile(file: string): string { + if (!isRollingPath(file)) { + return file; + } + return rollingPathForDate(path.dirname(file), new Date()); } function isRollingPath(file: string): boolean { @@ -592,3 +610,29 @@ function pruneOldRollingLogs(dir: string): void { // ignore missing dir or read errors } } + +function rotatedLogPath(file: string, index: number): string { + const ext = path.extname(file); + const base = file.slice(0, file.length - ext.length); + return `${base}.${index}${ext}`; +} + +function rotateLogFile(file: string): boolean { + try { + fs.mkdirSync(path.dirname(file), { recursive: true }); + fs.rmSync(rotatedLogPath(file, MAX_ROTATED_LOG_FILES), { force: true }); + for (let index = MAX_ROTATED_LOG_FILES - 1; index >= 1; index -= 1) { + const from = rotatedLogPath(file, index); + if (!fs.existsSync(from)) { + continue; + } + fs.renameSync(from, rotatedLogPath(file, index + 1)); + } + if (fs.existsSync(file)) { + fs.renameSync(file, rotatedLogPath(file, 1)); + } + return true; + } catch { + return false; + } +} diff --git a/src/logging/subsystem.test.ts b/src/logging/subsystem.test.ts index 92c40f35334..b53c72da23f 100644 --- a/src/logging/subsystem.test.ts +++ b/src/logging/subsystem.test.ts @@ -1,9 +1,14 @@ -import { afterEach, describe, expect, it, vi } from "vitest"; +import fs from "node:fs"; +import path from "node:path"; +import { afterAll, afterEach, beforeAll, describe, expect, it, vi } from "vitest"; import { setConsoleSubsystemFilter, shouldLogSubsystemToConsole } from "./console.js"; +import { createSuiteLogPathTracker } from "./log-test-helpers.js"; import { resetLogger, setLoggerOverride } from "./logger.js"; import { loggingState } from "./state.js"; import { createSubsystemLogger } from "./subsystem.js"; +const logPathTracker = createSuiteLogPathTracker("openclaw-subsystem-log-"); + function installConsoleMethodSpy(method: "warn" | "error") { const spy = vi.fn(); loggingState.rawConsole = { @@ -15,11 +20,20 @@ function installConsoleMethodSpy(method: "warn" | "error") { return spy; } +beforeAll(async () => { + await logPathTracker.setup(); +}); + afterEach(() => { setConsoleSubsystemFilter(null); setLoggerOverride(null); loggingState.rawConsole = null; resetLogger(); + vi.useRealTimers(); +}); + +afterAll(async () => { + await logPathTracker.cleanup(); }); describe("createSubsystemLogger().isEnabled", () => { @@ -190,4 +204,22 @@ describe("createSubsystemLogger().isEnabled", () => { expect(warn).toHaveBeenCalledTimes(1); }); + + it("keeps long-lived subsystem loggers on the current-day rolling file", () => { + const logDir = path.dirname(logPathTracker.nextPath()); + const firstDay = path.join(logDir, "openclaw-2026-01-01.log"); + const secondDay = path.join(logDir, "openclaw-2026-01-02.log"); + vi.useFakeTimers(); + vi.setSystemTime(new Date("2026-01-01T08:00:00Z")); + setLoggerOverride({ level: "info", consoleLevel: "silent", file: firstDay }); + const log = createSubsystemLogger("diagnostics"); + + log.info("first day subsystem log"); + vi.setSystemTime(new Date("2026-01-02T08:00:00Z")); + log.info("second day subsystem log"); + + expect(fs.readFileSync(firstDay, "utf8")).toContain("first day subsystem log"); + expect(fs.readFileSync(secondDay, "utf8")).toContain("second day subsystem log"); + expect(fs.readFileSync(firstDay, "utf8")).not.toContain("second day subsystem log"); + }); }); diff --git a/src/logging/subsystem.ts b/src/logging/subsystem.ts index 5d35ad73930..e8acab0f432 100644 --- a/src/logging/subsystem.ts +++ b/src/logging/subsystem.ts @@ -324,7 +324,6 @@ function logToFile( export function createSubsystemLogger(subsystem: string): SubsystemLogger { const resolvedSubsystem = normalizeSubsystemLabel(subsystem); - let fileLogger: TsLogger | null = null; const emitLog = (level: LogLevel, message: string, meta?: Record) => { const consoleSettings = getConsoleSettings(); @@ -347,10 +346,7 @@ export function createSubsystemLogger(subsystem: string): SubsystemLogger { fileMeta = Object.keys(rest).length > 0 ? rest : undefined; } if (fileEnabled) { - if (!fileLogger) { - fileLogger = getChildLogger({ subsystem: resolvedSubsystem }); - } - logToFile(fileLogger, level, message, fileMeta); + logToFile(getChildLogger({ subsystem: resolvedSubsystem }), level, message, fileMeta); } if (!consoleEnabled) { return; @@ -413,10 +409,7 @@ export function createSubsystemLogger(subsystem: string): SubsystemLogger { }, raw(message) { if (isFileLogLevelEnabled("info")) { - if (!fileLogger) { - fileLogger = getChildLogger({ subsystem: resolvedSubsystem }); - } - logToFile(fileLogger, "info", message, { raw: true }); + logToFile(getChildLogger({ subsystem: resolvedSubsystem }), "info", message, { raw: true }); } if ( shouldLogToConsole("info", { level: getConsoleSettings().level }) &&