From 53fe86991ccd188c346e0b85c22530d6552e9d21 Mon Sep 17 00:00:00 2001 From: Epinephrine Date: Thu, 15 Oct 2026 05:15:27 -0700 Subject: [PATCH] fix(service): guard log rotation file identities --- src/service/logging.ts | 81 +++++++++-- structure/ops/service-logging.md | 17 ++- tests/service/service-log.test.ts | 220 +++++++++++++++++++++++++++++- 3 files changed, 305 insertions(+), 13 deletions(-) diff --git a/src/service/logging.ts b/src/service/logging.ts index ce91623717d..31eff046bf6 100644 --- a/src/service/logging.ts +++ b/src/service/logging.ts @@ -1,24 +1,81 @@ -import { closeSync, fstatSync, ftruncateSync, openSync, readSync, renameSync, writeSync } from "node:fs"; +import { closeSync, constants, fstatSync, fsyncSync, ftruncateSync, lstatSync, openSync, readSync, realpathSync, renameSync, statSync, writeSync, type BigIntStats } from "node:fs"; import { formatWithOptions } from "node:util"; -import { dirname } from "node:path"; +import { basename, dirname, join } from "node:path"; import { recordOwnedConfigPath } from "../lib/config-ownership"; export const SERVICE_LOG_MAX_BYTES = 20 * 1024 * 1024; export const SERVICE_LOG_CHECK_INTERVAL_MS = 60_000; +function regularLeaf(path: string): BigIntStats | undefined { + try { + const info = lstatSync(path, { bigint: true }); + if (!info.isFile() || info.nlink !== 1n || info.ino === 0n) throw new Error("Unsafe service log leaf"); + return info; + } catch (error) { + if ((error as NodeJS.ErrnoException).code === "ENOENT") return undefined; + throw error; + } +} + +function sameFile(left: BigIntStats | undefined, right: BigIntStats | undefined): boolean { + return left !== undefined && right !== undefined && left.dev === right.dev && left.ino === right.ino; +} + +function matchesDescriptor(path: string, fd: number, expected: BigIntStats): boolean { + const info = fstatSync(fd, { bigint: true }); + return info.isFile() && info.nlink === 1n && sameFile(expected, info) + && sameFile(info, regularLeaf(path)); +} + /** Preserve the manager's open append descriptor; retain at most two bounded archives. */ -export function rotateServiceLog(path: string, maxBytes = SERVICE_LOG_MAX_BYTES): boolean { +export function rotateServiceLog(requestedPath: string, maxBytes = SERVICE_LOG_MAX_BYTES): boolean { let source: number | undefined; let archive: number | undefined; try { if (!Number.isSafeInteger(maxBytes) || maxBytes <= 0) return false; - source = openSync(path, "r+"); - const size = fstatSync(source).size; - if (size <= maxBytes) return false; - try { renameSync(`${path}.1`, `${path}.2`); } catch (error) { - if ((error as NodeJS.ErrnoException).code !== "ENOENT") return false; + // Resolve only the parent: exclusive creation through a Windows junction + // can report EEXIST for a missing leaf. Never resolve away a leaf symlink. + const parent = dirname(requestedPath); + const directory = statSync(parent, { bigint: true }); + if (!directory.isDirectory() || directory.ino === 0n) return false; + const canonicalParent = realpathSync(parent); + const path = join(canonicalParent, basename(requestedPath)); + const sameDirectory = () => { + const alias = statSync(parent, { bigint: true }); + const canonical = statSync(canonicalParent, { bigint: true }); + return alias.isDirectory() && canonical.isDirectory() + && sameFile(directory, alias) && sameFile(directory, canonical); + }; + const matches = (suffix: string, fd: number, expected: BigIntStats) => sameDirectory() + && matchesDescriptor(`${path}${suffix}`, fd, expected) + && matchesDescriptor(`${requestedPath}${suffix}`, fd, expected); + if (!sameDirectory()) return false; + const original = regularLeaf(requestedPath); + if (!original) return false; + // Windows does not expose O_NOFOLLOW: descriptor/leaf identity checks still + // apply there. Do not reject legitimate junctions in the home path. + const guardedFlags = process.platform === "win32" ? 0 : constants.O_NOFOLLOW | constants.O_NONBLOCK; + source = openSync(path, constants.O_RDWR | guardedFlags); + if (!matches("", source, original)) return false; + const size = Number(fstatSync(source, { bigint: true }).size); + if (!Number.isSafeInteger(size) || size <= maxBytes) return false; + const previous = regularLeaf(`${path}.1`); + const oldest = regularLeaf(`${path}.2`); + if (!matches("", source, original)) return false; + if (previous) { + if (!sameFile(previous, regularLeaf(`${path}.1`))) return false; + const currentOldest = regularLeaf(`${path}.2`); + if (oldest ? !sameFile(oldest, currentOldest) : currentOldest !== undefined) return false; + if (!sameDirectory()) return false; + renameSync(`${path}.1`, `${path}.2`); + if (!sameFile(previous, regularLeaf(`${path}.2`))) return false; } - archive = openSync(`${path}.1`, "w", 0o600); + // Never truncate an existing archive, even if another rotation or a path + // replacement wins the gap after rename. Failure leaves the source intact. + if (!sameDirectory()) return false; + archive = openSync(`${path}.1`, constants.O_WRONLY | constants.O_CREAT | constants.O_EXCL | guardedFlags, 0o600); + const created = fstatSync(archive, { bigint: true }); + if (!matches(".1", archive, created)) return false; // A legacy unbounded file may be huge. Copy only its newest cap-sized tail, // using fixed memory, before truncating the original inode. const buffer = Buffer.alloc(Math.min(64 * 1024, maxBytes)); @@ -28,12 +85,18 @@ export function rotateServiceLog(path: string, maxBytes = SERVICE_LOG_MAX_BYTES) if (read === 0) return false; let written = 0; while (written < read) { + if (!matches(".1", archive, created)) return false; const count = writeSync(archive, buffer, written, read - written); if (count === 0) return false; written += count; } position += read; } + fsyncSync(archive); + // Revalidate both names and open objects at the destructive boundary. These + // checks detect observed replacement; they are not an atomic namespace lock. + if (!matches(".1", archive, created) + || !matches("", source, original)) return false; ftruncateSync(source, 0); return true; } catch { diff --git a/structure/ops/service-logging.md b/structure/ops/service-logging.md index f7701e07c4d..dba9fc700d2 100644 --- a/structure/ops/service-logging.md +++ b/structure/ops/service-logging.md @@ -16,6 +16,19 @@ place, preserving the service manager's existing append descriptors. Both archives stay bounded even when a legacy active log is already very large. Archive paths join the config cleanup manifest. +Rotation accepts only regular, singly linked active and archive leaves. The +active descriptor must match the inspected leaf's device and inode; POSIX opens +also use no-follow and nonblocking flags. A new archive is created exclusively, +not opened with truncation. Descriptor/leaf identities are checked while copying +and again before truncating the active inode, after flushing the new archive. +Unsafe leaves, observed replacements, and copy or flush failures skip truncation. +Parent directory aliases remain supported: rotation resolves only the parent, +uses its canonical path for exclusive archive creation, and rechecks the original +and canonical directory identities and both leaf paths against the descriptors. +It never resolves the leaf itself to bypass symlink rejection. +These checks are not an atomic +namespace lock: concurrent directory or hardlink changes can race a final check. + The timer is unreferenced and filesystem failures are swallowed. The active log may exceed the threshold between checks. Copy-truncate can lose concurrent writes, and the retained tail can begin partway through a line. There is no @@ -23,4 +36,6 @@ per-write filesystem check and no timer when service logging is inactive. `tests/service/service-log.test.ts` covers service-only timestamps, multiline formatting, startup and periodic checks, bounded generations, failure handling, -and continued writes through an append descriptor opened before rotation. +continued writes through an append descriptor opened before rotation, unsafe +leaves, controlled identity replacements, exclusive archive creation, parent +aliases, and partial-copy/flush failures. diff --git a/tests/service/service-log.test.ts b/tests/service/service-log.test.ts index fe253c29dab..1a6272a7bf1 100644 --- a/tests/service/service-log.test.ts +++ b/tests/service/service-log.test.ts @@ -1,5 +1,6 @@ -import { afterEach, describe, expect, test } from "bun:test"; -import { closeSync, existsSync, mkdirSync, mkdtempSync, openSync, readFileSync, rmSync, statSync, writeFileSync, writeSync } from "node:fs"; +import { afterEach, describe, expect, spyOn, test } from "bun:test"; +import { closeSync, existsSync, linkSync, mkdirSync, mkdtempSync, openSync, readFileSync, realpathSync, renameSync, rmSync, statSync, symlinkSync, writeFileSync, writeSync } from "node:fs"; +import * as fs from "node:fs"; import { tmpdir } from "node:os"; import { join } from "node:path"; import { repoPath, repoRoot } from "../helpers/repo-root"; @@ -7,7 +8,7 @@ import { rotateServiceLog } from "../../src/service/logging"; const roots: string[] = []; function sandbox(): string { - const root = mkdtempSync(join(tmpdir(), "ocx-service-log-")); + const root = realpathSync(mkdtempSync(join(tmpdir(), "ocx-service-log-"))); roots.push(root); return root; } @@ -106,6 +107,219 @@ describe("managed service log", () => { expect(rotateServiceLog(path, 0)).toBe(false); }); + for (const suffix of ["", ".1", ".2"]) { + test(`hardlinked ${suffix || "active"} leaf is rejected without changing any file`, () => { + const root = sandbox(); + const path = join(root, "service.log"); + const target = join(root, "unrelated.txt"); + writeFileSync(target, "unrelated contents"); + for (const leaf of ["", ".1", ".2"]) { + if (leaf === suffix) linkSync(target, `${path}${leaf}`); + else writeFileSync(`${path}${leaf}`, `original ${leaf || "active"}`); + } + const before = ["", ".1", ".2"].map(leaf => readFileSync(`${path}${leaf}`, "utf8")); + expect(rotateServiceLog(path, 4)).toBe(false); + expect(["", ".1", ".2"].map(leaf => readFileSync(`${path}${leaf}`, "utf8"))).toEqual(before); + expect(readFileSync(target, "utf8")).toBe("unrelated contents"); + }); + + test.skipIf(process.platform === "win32")(`symlinked ${suffix || "active"} leaf is rejected`, () => { + const root = sandbox(); + const path = join(root, "service.log"); + const target = join(root, "unrelated.txt"); + writeFileSync(target, "unrelated contents"); + if (suffix) writeFileSync(path, "active contents"); + symlinkSync(target, `${path}${suffix}`); + expect(rotateServiceLog(path, 4)).toBe(false); + expect(readFileSync(target, "utf8")).toBe("unrelated contents"); + if (suffix) expect(readFileSync(path, "utf8")).toBe("active contents"); + }); + } + + test("a non-regular active leaf is rejected", () => { + const path = join(sandbox(), "service.log"); + mkdirSync(path); + expect(rotateServiceLog(path, 4)).toBe(false); + expect(existsSync(`${path}.1`)).toBe(false); + }); + + test("an allowed parent directory alias still rotates", () => { + const root = sandbox(); + const actual = join(root, "actual"); + const alias = join(root, "alias"); + mkdirSync(actual); + symlinkSync(actual, alias, process.platform === "win32" ? "junction" : "dir"); + const path = join(alias, "service.log"); + writeFileSync(path, "oldest latest"); + expect(rotateServiceLog(path, 6)).toBe(true); + expect(readFileSync(join(actual, "service.log.1"), "utf8")).toBe("latest"); + }); + + test("parent aliases use canonical exclusive creation without weakening flags", () => { + const root = sandbox(); + const actual = join(root, "actual"); + const alias = join(root, "alias"); + mkdirSync(actual); + symlinkSync(actual, alias, process.platform === "win32" ? "junction" : "dir"); + const path = join(alias, "service.log"); + writeFileSync(path, "oldest latest"); + const open = fs.openSync; + let exclusiveOpens = 0; + const hook = spyOn(fs, "openSync").mockImplementation(((file: fs.PathLike, flags: number, ...args: unknown[]) => { + if (String(file).endsWith(".1")) { + exclusiveOpens++; + expect(file).toBe(join(realpathSync(actual), "service.log.1")); + expect(flags & fs.constants.O_EXCL).toBe(fs.constants.O_EXCL); + expect(flags & fs.constants.O_CREAT).toBe(fs.constants.O_CREAT); + expect(flags & fs.constants.O_TRUNC).toBe(0); + } + return Reflect.apply(open, fs, [file, flags, ...args]); + }) as typeof fs.openSync); + try { expect(rotateServiceLog(path, 6)).toBe(true); } + finally { hook.mockRestore(); } + expect(exclusiveOpens).toBe(1); + expect(readFileSync(join(actual, "service.log.1"), "utf8")).toBe("latest"); + }); + + for (const boundary of ["resolve", "copy"] as const) { + test(`parent alias retargeted during ${boundary} preserves both source files`, () => { + const root = sandbox(); + const actual = join(root, "actual"); + const other = join(root, "other"); + const alias = join(root, "alias"); + mkdirSync(actual); mkdirSync(other); + writeFileSync(join(actual, "service.log"), "original contents"); + writeFileSync(join(other, "service.log"), "replacement contents"); + symlinkSync(actual, alias, process.platform === "win32" ? "junction" : "dir"); + const method = boundary === "resolve" ? "realpathSync" : "readSync"; + const original = fs[method]; + let changed = false; + const hook = spyOn(fs, method).mockImplementation(((...args: unknown[]) => { + const result = Reflect.apply(original, fs, args); + if (!changed) { + changed = true; + renameSync(alias, `${alias}.saved`); + symlinkSync(other, alias, process.platform === "win32" ? "junction" : "dir"); + } + return result; + }) as typeof original); + try { expect(rotateServiceLog(join(alias, "service.log"), 4)).toBe(false); } + finally { hook.mockRestore(); } + expect(changed).toBe(true); + expect(readFileSync(join(actual, "service.log"), "utf8")).toBe("original contents"); + expect(readFileSync(join(other, "service.log"), "utf8")).toBe("replacement contents"); + expect(existsSync(join(other, "service.log.1"))).toBe(false); + }); + } + + test("an archive inserted through a parent alias still fails exclusive creation", () => { + const root = sandbox(); + const actual = join(root, "actual"); + const alias = join(root, "alias"); + mkdirSync(actual); + symlinkSync(actual, alias, process.platform === "win32" ? "junction" : "dir"); + const path = join(alias, "service.log"); + writeFileSync(path, "original contents"); + const open = fs.openSync; + const hook = spyOn(fs, "openSync").mockImplementation(((file: fs.PathLike, ...args: unknown[]) => { + if (file === join(actual, "service.log.1")) writeFileSync(`${path}.1`, "inserted contents"); + return Reflect.apply(open, fs, [file, ...args]); + }) as typeof fs.openSync); + try { expect(rotateServiceLog(path, 4)).toBe(false); } + finally { hook.mockRestore(); } + expect(readFileSync(path, "utf8")).toBe("original contents"); + expect(readFileSync(`${path}.1`, "utf8")).toBe("inserted contents"); + }); + + test("replacement between leaf inspection and source open is not truncated", () => { + const path = join(sandbox(), "service.log"); + writeFileSync(path, "original contents"); + const open = fs.openSync; + const hook = spyOn(fs, "openSync").mockImplementation(((file: fs.PathLike, ...args: unknown[]) => { + if (file === path) { + renameSync(path, `${path}.saved`); + writeFileSync(path, "replacement contents"); + } + return Reflect.apply(open, fs, [file, ...args]); + }) as typeof fs.openSync); + try { expect(rotateServiceLog(path, 4)).toBe(false); } + finally { hook.mockRestore(); } + expect(readFileSync(path, "utf8")).toBe("replacement contents"); + expect(readFileSync(`${path}.saved`, "utf8")).toBe("original contents"); + expect(existsSync(`${path}.1`)).toBe(false); + }); + + test("an archive inserted after rename is not opened destructively", () => { + const path = join(sandbox(), "service.log"); + writeFileSync(path, "active contents"); + writeFileSync(`${path}.1`, "previous archive"); + const open = fs.openSync; + const hook = spyOn(fs, "openSync").mockImplementation(((file: fs.PathLike, ...args: unknown[]) => { + if (file === `${path}.1`) writeFileSync(`${path}.1`, "inserted contents"); + return Reflect.apply(open, fs, [file, ...args]); + }) as typeof fs.openSync); + try { expect(rotateServiceLog(path, 4)).toBe(false); } + finally { hook.mockRestore(); } + expect(readFileSync(path, "utf8")).toBe("active contents"); + expect(readFileSync(`${path}.1`, "utf8")).toBe("inserted contents"); + expect(readFileSync(`${path}.2`, "utf8")).toBe("previous archive"); + }); + + for (const change of ["replace-source", "link-source", "replace-archive", "link-archive", "read-failure"] as const) { + test(`copy boundary refuses ${change} and preserves the source`, () => { + const path = join(sandbox(), "service.log"); + writeFileSync(path, "original contents"); + const read = fs.readSync; + let changed = false; + const hook = spyOn(fs, "readSync").mockImplementation(((...args: unknown[]) => { + const count = Reflect.apply(read, fs, args); + if (!changed) { + changed = true; + const leaf = change.endsWith("archive") ? `${path}.1` : path; + if (change.startsWith("replace")) { + renameSync(leaf, `${leaf}.saved`); + writeFileSync(leaf, "replacement contents"); + } else if (change.startsWith("link")) linkSync(leaf, `${leaf}.linked`); + else throw new Error("synthetic copy failure"); + } + return count; + }) as typeof fs.readSync); + try { expect(rotateServiceLog(path, 4)).toBe(false); } + finally { hook.mockRestore(); } + expect(readFileSync(change === "replace-source" ? `${path}.saved` : path, "utf8")).toBe("original contents"); + if (change.startsWith("replace")) { + expect(readFileSync(change.endsWith("archive") ? `${path}.1` : path, "utf8")).toBe("replacement contents"); + } + if (change === "link-archive") expect(readFileSync(`${path}.1.linked`, "utf8")).toBe(""); + }); + } + + test("a write failure after a partial archive leaves the active log intact", () => { + const path = join(sandbox(), "service.log"); + const contents = "x".repeat(128 * 1024 + 1); + writeFileSync(path, contents); + const write = fs.writeSync; + let writes = 0; + const hook = spyOn(fs, "writeSync").mockImplementation(((...args: unknown[]) => { + if (++writes === 2) throw new Error("synthetic disk failure"); + return Reflect.apply(write, fs, args); + }) as typeof fs.writeSync); + try { expect(rotateServiceLog(path, 128 * 1024)).toBe(false); } + finally { hook.mockRestore(); } + expect(writes).toBe(2); + expect(readFileSync(path, "utf8")).toBe(contents); + expect(statSync(`${path}.1`).size).toBe(64 * 1024); + }); + + test("archive flush failure preserves the active source", () => { + const path = join(sandbox(), "service.log"); + writeFileSync(path, "original contents"); + const hook = spyOn(fs, "fsyncSync").mockImplementation(() => { throw new Error("synthetic flush failure"); }); + try { expect(rotateServiceLog(path, 4)).toBe(false); } + finally { hook.mockRestore(); } + expect(readFileSync(path, "utf8")).toBe("original contents"); + }); + test("rotation checks at startup and periodically only for service processes", async () => { const path = join(sandbox(), "service.log"); const child = Bun.spawn([process.execPath, "--eval", `