fix(logging): keep the component and apply printf formats in the app log (#10770)

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!

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)).

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 || ""}`;

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<Record<string, unknown>> {
+  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<string, unknown>);
+}
+
+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 });
+  }
+});