From c94da0df6f38fcbc26b6562e98119809d29654a3 Mon Sep 17 00:00:00 2001 From: qingminlong Date: Wed, 15 Jul 2026 05:47:53 +0800 Subject: [PATCH] fix(logs): preserve log tails across short reads (#105066) * fix(logs): preserve log tails across short reads * test(logging): track log-tail temp files --------- Co-authored-by: Peter Steinberger Co-authored-by: Peter Steinberger --- src/commands/channels.logs.test.ts | 34 ++++++++++++++++++++++++++++ src/commands/channels/logs.ts | 6 ++--- src/logging/log-tail.test.ts | 36 +++++++++++++++++++++++++++--- src/logging/log-tail.ts | 28 ++++++++++++++++++++--- 4 files changed, 95 insertions(+), 9 deletions(-) diff --git a/src/commands/channels.logs.test.ts b/src/commands/channels.logs.test.ts index 3cbc378e3fb2..a8155f705b1a 100644 --- a/src/commands/channels.logs.test.ts +++ b/src/commands/channels.logs.test.ts @@ -26,6 +26,12 @@ vi.mock("../channels/plugins/index.js", () => ({ import { channelsLogsCommand } from "./channels/logs.js"; const runtime = createTestRuntime(); +type PositionalRead = ( + buffer: Buffer, + offset: number, + length: number, + position: number | null, +) => Promise<{ bytesRead: number; buffer: Buffer }>; function logLine(params: { module: string; message: string }) { return JSON.stringify({ @@ -62,6 +68,7 @@ describe("channelsLogsCommand", () => { }); afterEach(async () => { + vi.restoreAllMocks(); setLoggerOverride(null); await fs.rm(tempDir, { recursive: true, force: true }); }); @@ -142,6 +149,33 @@ describe("channelsLogsCommand", () => { expect(payload.lines.map((line) => line.message)).toEqual(["current sent"]); }); + it("fills short positional reads before parsing channel log lines", async () => { + const realOpen = fs.open.bind(fs); + const readLengths: number[] = []; + vi.spyOn(fs, "open").mockImplementation(async (...args) => { + const handle = await realOpen(...args); + const realRead = handle.read.bind(handle) as PositionalRead; + const shortRead = vi.fn((buffer, offset, length, position) => { + readLengths.push(length); + return realRead(buffer, offset, Math.min(length, 4), position); + }); + Object.defineProperty(handle, "read", { configurable: true, value: shortRead }); + return handle; + }); + await fs.writeFile( + logPath, + [ + logLine({ module: "gateway/channels/slack/send", message: "first" }), + logLine({ module: "gateway/channels/slack/send", message: "second" }), + ].join("\n"), + ); + + await channelsLogsCommand({ channel: "slack", json: true }, runtime); + + expect(readJsonPayload().lines.map((line) => line.message)).toEqual(["first", "second"]); + expect(readLengths.length).toBeGreaterThan(1); + }); + it("returns the first line of the tail window when start aligns with a line boundary", async () => { // MAX_BYTES in readTailLines is 1_000_000. We build a file of 2_000_000 bytes // made of 10_000 lines each exactly 200 bytes (199 payload + "\n"), so the diff --git a/src/commands/channels/logs.ts b/src/commands/channels/logs.ts index 9dfb03c8ad8e..02ab7f8728a3 100644 --- a/src/commands/channels/logs.ts +++ b/src/commands/channels/logs.ts @@ -5,7 +5,7 @@ import { theme } from "../../../packages/terminal-core/src/theme.js"; import { normalizeChannelId as normalizeBundledChannelId } from "../../channels/registry.js"; import { parseStrictPositiveInteger } from "../../infra/parse-finite-number.js"; import { getResolvedLoggerSettings } from "../../logging.js"; -import { resolveLogFile } from "../../logging/log-tail.js"; +import { readLogWindowFully, resolveLogFile } from "../../logging/log-tail.js"; import { parseLogLine } from "../../logging/parse-log-line.js"; import { listManifestChannelContributionIds } from "../../plugins/manifest-contribution-ids.js"; import { defaultRuntime, type RuntimeEnv, writeRuntimeJson } from "../../runtime.js"; @@ -87,8 +87,8 @@ async function readTailLines(file: string, limit: number): Promise { return []; } const buffer = Buffer.alloc(length); - const readResult = await handle.read(buffer, 0, length, start); - const text = buffer.toString("utf8", 0, readResult.bytesRead); + const bytesRead = await readLogWindowFully(handle, buffer, start); + const text = buffer.toString("utf8", 0, bytesRead); let lines = text.split("\n"); if (start > 0 && prefix !== "\n") { lines = lines.slice(1); diff --git a/src/logging/log-tail.test.ts b/src/logging/log-tail.test.ts index 45fdec017c0a..b0fe6def33b8 100644 --- a/src/logging/log-tail.test.ts +++ b/src/logging/log-tail.test.ts @@ -1,11 +1,19 @@ // Log tail tests cover reading, parsing, and limiting recent log entries. import fs from "node:fs/promises"; -import os from "node:os"; import path from "node:path"; import { afterEach, describe, expect, it, vi } from "vitest"; +import { useAutoCleanupTempDirTracker } from "../../test/helpers/temp-dir.js"; import { resetLogger, setLoggerOverride } from "../logging.js"; +const tempDirs = useAutoCleanupTempDirTracker(afterEach); + const resolvedRedaction = { mode: "tools" as const, patterns: [/custom-secret-[a-z]+/g] }; +type PositionalRead = ( + buffer: Buffer, + offset: number, + length: number, + position: number | null, +) => Promise<{ bytesRead: number; buffer: Buffer }>; const { redactSensitiveLinesMock, resolveRedactOptionsMock } = vi.hoisted(() => ({ redactSensitiveLinesMock: vi.fn((lines: string[], options?: unknown) => @@ -28,6 +36,7 @@ vi.mock("./redact.js", async () => { describe("readConfiguredLogTail", () => { afterEach(() => { + vi.restoreAllMocks(); resolveRedactOptionsMock.mockClear(); redactSensitiveLinesMock.mockClear(); resetLogger(); @@ -36,7 +45,7 @@ describe("readConfiguredLogTail", () => { it("applies redaction once per request across all returned lines", async () => { const { readConfiguredLogTail } = await import("./log-tail.js"); - const tempDir = await fs.mkdtemp(path.join(os.tmpdir(), "openclaw-log-tail-")); + const tempDir = tempDirs.make("openclaw-log-tail-"); const file = path.join(tempDir, "openclaw-2026-01-22.log"); await fs.writeFile(file, "custom-secret-abcdefghijklmnopqrstuvwxyz\nsecond line\n"); @@ -51,7 +60,28 @@ describe("readConfiguredLogTail", () => { resolvedRedaction, ); expect(result.lines).toEqual(["custom…wxyz", "second line"]); + }); - await fs.rm(tempDir, { recursive: true, force: true }); + it("fills short positional reads before splitting log lines", async () => { + const { readConfiguredLogTail } = await import("./log-tail.js"); + const tempDir = tempDirs.make("openclaw-log-tail-"); + const file = path.join(tempDir, "openclaw-2026-01-22.log"); + const realOpen = fs.open.bind(fs); + vi.spyOn(fs, "open").mockImplementation(async (...args) => { + const handle = await realOpen(...args); + const realRead = handle.read.bind(handle) as PositionalRead; + const shortRead = vi.fn((buffer, offset, length, position) => + realRead(buffer, offset, Math.min(length, 4), position), + ); + Object.defineProperty(handle, "read", { configurable: true, value: shortRead }); + return handle; + }); + + await fs.writeFile(file, "old line\nrecent one\nrecent two\n"); + setLoggerOverride({ file }); + + const result = await readConfiguredLogTail(); + + expect(result.lines).toEqual(["old line", "recent one", "recent two"]); }); }); diff --git a/src/logging/log-tail.ts b/src/logging/log-tail.ts index acc8b313f169..d99f9e0acf0a 100644 --- a/src/logging/log-tail.ts +++ b/src/logging/log-tail.ts @@ -1,5 +1,5 @@ // Log tail helpers read recent log lines with optional parsing and redaction. -import fs from "node:fs/promises"; +import fs, { type FileHandle } from "node:fs/promises"; import path from "node:path"; import { getResolvedLoggerSettings } from "../logging.js"; import { clamp } from "../utils.js"; @@ -26,6 +26,28 @@ function isRollingLogFile(file: string): boolean { return ROLLING_LOG_RE.test(path.basename(file)); } +/** Fills a bounded positional-read buffer unless the file reaches EOF. */ +export async function readLogWindowFully( + handle: FileHandle, + buffer: Buffer, + position: number, +): Promise { + let bytesRead = 0; + while (bytesRead < buffer.length) { + const result = await handle.read( + buffer, + bytesRead, + buffer.length - bytesRead, + position + bytesRead, + ); + if (result.bytesRead === 0) { + break; + } + bytesRead += result.bytesRead; + } + return bytesRead; +} + /** Resolves a rolling daily log path to the newest existing rolling log when needed. */ export async function resolveLogFile(file: string): Promise { const stat = await fs.stat(file).catch(() => null); @@ -126,8 +148,8 @@ async function readLogSlice(params: { const length = Math.max(0, size - start); const buffer = Buffer.alloc(length); - const readResult = await handle.read(buffer, 0, length, start); - const text = buffer.toString("utf8", 0, readResult.bytesRead); + const bytesRead = await readLogWindowFully(handle, buffer, start); + const text = buffer.toString("utf8", 0, bytesRead); let lines = text.split("\n"); if (start > 0 && prefix !== "\n") { // Drop the first partial line when starting in the middle of a file.