From ee230fa93a861cb772d06ea80bbd09e5490dcdb1 Mon Sep 17 00:00:00 2001 From: Dizzle <112548150+maxmad64bis@users.noreply.github.com> Date: Thu, 20 Aug 2026 11:29:42 +0200 Subject: [PATCH] fix(logging): keep the component and apply printf formats in the app log (#10770) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Merged via merge-train (release/v3.8.50, batch1 2026-08-20) — static gates (typecheck/file-size/complexity/cognitive/changelog) green on the combined tree; test:unit reds observed in the boarded run were verified pre-existing on the pure release tip (unrelated flake), not caused by this PR. Thanks for the contribution! --- ...70-console-interceptor-message-fidelity.md | 1 + src/lib/consoleInterceptor.ts | 42 +++++++- ...nsole-interceptor-message-fidelity.test.ts | 95 +++++++++++++++++++ 3 files changed, 136 insertions(+), 2 deletions(-) create mode 100644 changelog.d/fixes/10770-console-interceptor-message-fidelity.md create mode 100644 tests/unit/console-interceptor-message-fidelity.test.ts diff --git a/changelog.d/fixes/10770-console-interceptor-message-fidelity.md b/changelog.d/fixes/10770-console-interceptor-message-fidelity.md new file mode 100644 index 0000000000..c35260f36a --- /dev/null +++ b/changelog.d/fixes/10770-console-interceptor-message-fidelity.md @@ -0,0 +1 @@ +- **fix(logging):** the app log is filterable and readable again. Entries from the tagged logger (`[LEVEL] [TAG] message`) were filed under the level instead of the component, and printf format strings were never applied, so `%s`/`%d` stayed literal with the values trailing behind them unlabelled — including every LiveWS connection line, where the format is deliberate hardening against injected format specifiers ([#PRNUM](https://github.com/diegosouzapw/OmniRoute/pull/10770)). diff --git a/src/lib/consoleInterceptor.ts b/src/lib/consoleInterceptor.ts index 19e245217e..9a56f2a550 100644 --- a/src/lib/consoleInterceptor.ts +++ b/src/lib/consoleInterceptor.ts @@ -12,6 +12,7 @@ import { appendFileSync, existsSync, mkdirSync } from "fs"; import { dirname, resolve } from "path"; +import { format } from "util"; import { getAppLogFilePath, getAppLogToFile } from "./logEnv"; const logToFile = getAppLogToFile(); @@ -91,18 +92,55 @@ function ensureDir() { } } +// Level tokens the in-repo tagged logger puts in front of the component. Keep in sync with +// LEVELS in open-sse/utils/logger.ts — that module keeps the type internal, so the list +// cannot be imported today. +const LEVEL_TOKENS = new Set(["DEBUG", "INFO", "WARN", "WARNING", "ERROR", "FATAL", "TRACE"]); + /** * Try to extract component name from message patterns like [COMPONENT] or [component]. + * + * The tagged logger emits `[LEVEL] [TAG] message` (open-sse/utils/logger.ts), so taking the + * first bracket recorded the level as the component and dropped the real one — the log stopped + * being filterable by component, which is the point of the field. Level tokens are skipped; the + * level already travels in the entry's own `level` field. */ function extractComponent(msg: string): string { - const match = msg.match(/^\[([^\]]+)\]/); - return match ? match[1] : "app"; + let rest = msg; + // Bounded: a message never legitimately carries more than a level plus a tag. + for (let depth = 0; depth < 3; depth++) { + const match = rest.match(/^\s*\[([^\]]+)\]/); + if (!match) break; + const token = match[1].trim(); + if (!LEVEL_TOKENS.has(token.toUpperCase())) return token; + rest = rest.slice(match[0].length); + } + return "app"; } /** * Convert arguments to a string message, handling objects and errors. + * + * `console.*` takes a printf-style format string, and first-party callers rely on it: + * src/server/ws/liveServer.ts passes `%s`/`%d` deliberately, to keep client-supplied values out + * of the format slot (CWE-134). Joining the arguments instead of formatting them left the + * placeholders literal and the values trailing without their labels, so a reader had to open the + * source to know which value was which. `util.format` appends surplus arguments exactly like the + * join below, so calls without a format string keep their current output. + * + * Guarded against an Error in `rest`: many call sites build the first argument from dynamic, + * non-format-string content (e.g. `` `[TAG] Failed to compile hook "${row.name}":` ``) that can + * coincidentally contain a `%s`/`%d`-like substring. If a trailing arg is an Error, util.format + * would silently consume it as a substitution value and drop its stack — skip the printf path + * so that Error still gets the full `message\nstack` treatment below. */ function argsToMessage(args: unknown[]): string { + const [first, ...rest] = args; + const hasFormatString = typeof first === "string" && /%[sdifjoOc%]/.test(first); + const restHasError = rest.some((arg) => arg instanceof Error); + if (hasFormatString && !restHasError) { + return format(first, ...rest); + } return args .map((arg) => { if (arg instanceof Error) return `${arg.message}\n${arg.stack || ""}`; diff --git a/tests/unit/console-interceptor-message-fidelity.test.ts b/tests/unit/console-interceptor-message-fidelity.test.ts new file mode 100644 index 0000000000..ab1cd6f90e --- /dev/null +++ b/tests/unit/console-interceptor-message-fidelity.test.ts @@ -0,0 +1,95 @@ +import test from "node:test"; +import assert from "node:assert/strict"; +import fs from "node:fs"; +import os from "node:os"; +import path from "node:path"; + +// Two defects in the same formatting path, both visible in a real app log: +// +// - the component was read as the first bracket, so entries from the tagged logger +// ("[INFO] [TAG] message") were filed under the level and the tag was lost; +// - printf format strings were not applied, so "%s"/"%d" stayed literal and the values +// trailed behind them without labels. +// +// Both assertions below fail against the previous implementation. +// +// consoleInterceptor freezes `logToFile` and `logFilePath` at import time, so the env has +// to be set before the module is loaded — hence the dynamic import. + +const LOG_DIR = fs.mkdtempSync(path.join(os.tmpdir(), "omniroute-interceptor-fidelity-")); +const LOG_PATH = path.join(LOG_DIR, "app.log"); + +process.env.APP_LOG_FILE_PATH = LOG_PATH; +process.env.APP_LOG_TO_FILE = "true"; + +const { initConsoleInterceptor, __consoleInterceptorInternals } = + await import("../../src/lib/consoleInterceptor.ts"); + +function readEntries(): Array> { + if (!fs.existsSync(LOG_PATH)) return []; + return fs + .readFileSync(LOG_PATH, "utf8") + .split("\n") + .filter((line) => line.trim().length > 0) + .map((line) => JSON.parse(line) as Record); +} + +test("the interceptor keeps the component and substitutes printf formats", () => { + try { + initConsoleInterceptor(); + + console.log("[INFO] [SKILLS_INJECTION] injected 3 skills"); + console.log("[LiveWS] Client connected: %s (%s) [%d total]", "37cb8f70", "127.0.0.1", 1); + console.log("plain message", { a: 1 }); + + __consoleInterceptorInternals.reset(); + + const entries = readEntries(); + assert.ok(entries.length > 0, "interceptor wrote nothing"); + + const tagged = entries.find((e) => String(e.message ?? "").includes("SKILLS_INJECTION")); + assert.ok(tagged, "tagged entry not written"); + assert.equal(tagged.component, "SKILLS_INJECTION"); + + const formatted = entries + .map((e) => String(e.message ?? "")) + .find((m) => m.includes("Client connected")); + assert.ok(formatted, "LiveWS entry not written"); + assert.equal(formatted, "[LiveWS] Client connected: 37cb8f70 (127.0.0.1) [1 total]"); + + // No format string: the previous join behaviour is preserved verbatim. + const plain = entries + .map((e) => String(e.message ?? "")) + .find((m) => m.startsWith("plain message")); + assert.equal(plain, 'plain message {"a":1}'); + } finally { + __consoleInterceptorInternals.reset(); + fs.rmSync(LOG_DIR, { recursive: true, force: true }); + } +}); + +test("a first argument that coincidentally contains a printf token does not swallow a trailing Error", () => { + try { + initConsoleInterceptor(); + + // Dynamic, non-format-string content (e.g. a hook/tag name) that happens to contain "%s" — + // the real defect this guards: util.format() would consume `err` as the %s substitution and + // drop its message/stack instead of appending them. + const err = new Error("boom"); + console.error('[Middleware] Failed to compile hook "handler%sname":', err); + + __consoleInterceptorInternals.reset(); + + const entries = readEntries(); + const entry = entries + .map((e) => String(e.message ?? "")) + .find((m) => m.includes("Failed to compile hook")); + + assert.ok(entry, "entry not written"); + assert.ok(entry.includes("boom"), "Error message was dropped"); + assert.ok(entry.includes(err.stack || ""), "Error stack was dropped"); + } finally { + __consoleInterceptorInternals.reset(); + fs.rmSync(LOG_DIR, { recursive: true, force: true }); + } +});