diff --git a/src/agents/pi-tool-definition-adapter.ts b/src/agents/pi-tool-definition-adapter.ts index 9f4451625..95a261d6c 100644 --- a/src/agents/pi-tool-definition-adapter.ts +++ b/src/agents/pi-tool-definition-adapter.ts @@ -21,6 +21,67 @@ function describeToolExecutionError(err: unknown): { return { message: String(err) }; } +function asScalar(value: unknown): string | undefined { + if (typeof value === "string") { + const trimmed = value.trim(); + return trimmed ? trimmed : undefined; + } + if (typeof value === "number" && Number.isFinite(value)) return String(value); + if (typeof value === "bigint") return String(value); + return undefined; +} + +function summarizeList(value: unknown): string | undefined { + if (!Array.isArray(value)) return undefined; + const items = value.map(asScalar).filter((entry): entry is string => Boolean(entry)); + if (items.length === 0) return undefined; + const sample = items.slice(0, 3).join(", "); + const suffix = items.length > 3 ? ` (+${items.length - 3})` : ""; + return `${sample}${suffix}`; +} + +function looksLikeMemberTarget(value: string): boolean { + return /^user:/i.test(value) || value.startsWith("@") || /^<@!?/.test(value); +} + +function describeMessageToolContext(params: Record): string | undefined { + const action = asScalar(params.action); + const channel = asScalar(params.channel); + const accountId = asScalar(params.accountId); + const guildId = asScalar(params.guildId); + const channelId = asScalar(params.channelId); + const threadId = asScalar(params.threadId); + const messageId = asScalar(params.messageId); + const userId = asScalar(params.userId) ?? asScalar(params.authorId) ?? asScalar(params.participant); + const target = + asScalar(params.target) ?? + asScalar(params.to) ?? + summarizeList(params.targets) ?? + summarizeList(params.target); + + const member = + userId ?? (target && looksLikeMemberTarget(target) ? target : undefined) ?? undefined; + const pairs: string[] = []; + if (action) pairs.push(`action=${action}`); + if (channel) pairs.push(`channel=${channel}`); + if (accountId) pairs.push(`accountId=${accountId}`); + if (member) { + pairs.push(`member=${member}`); + } else if (target) { + pairs.push(`target=${target}`); + } + if (guildId) pairs.push(`guildId=${guildId}`); + if (channelId) pairs.push(`channelId=${channelId}`); + if (threadId) pairs.push(`threadId=${threadId}`); + if (messageId) pairs.push(`messageId=${messageId}`); + return pairs.length > 0 ? pairs.join(" ") : undefined; +} + +function describeToolContext(toolName: string, params: Record): string | undefined { + if (toolName === "message") return describeMessageToolContext(params); + return undefined; +} + export function toToolDefinitions(tools: AnyAgentTool[]): ToolDefinition[] { return tools.map((tool) => { const name = tool.name || "tool"; @@ -52,7 +113,9 @@ export function toToolDefinitions(tools: AnyAgentTool[]): ToolDefinition[] { if (described.stack && described.stack !== described.message) { logDebug(`tools: ${tool.name} failed stack:\n${described.stack}`); } - logError(`[tools] ${tool.name} failed: ${described.message}`); + const context = describeToolContext(tool.name, params); + const suffix = context ? ` (${context})` : ""; + logError(`tools: ${tool.name} failed: ${described.message}${suffix}`); return jsonResult({ status: "error", tool: tool.name, diff --git a/src/cli/gateway-cli/run.ts b/src/cli/gateway-cli/run.ts index b8f512b4b..5c83aa2ff 100644 --- a/src/cli/gateway-cli/run.ts +++ b/src/cli/gateway-cli/run.ts @@ -15,7 +15,11 @@ import { setGatewayWsLogStyle } from "../../gateway/ws-logging.js"; import { setVerbose } from "../../globals.js"; import { GatewayLockError } from "../../infra/gateway-lock.js"; import { formatPortDiagnostics, inspectPortUsage } from "../../infra/ports.js"; -import { createSubsystemLogger, setConsoleSubsystemFilter } from "../../logging.js"; +import { + createSubsystemLogger, + setConsoleSubsystemFilter, + setConsoleTimestampPrefix, +} from "../../logging.js"; import { defaultRuntime } from "../../runtime.js"; import { forceFreePortAndWait } from "../ports.js"; import { ensureDevGatewayConfig } from "./dev.js"; @@ -59,6 +63,7 @@ async function runGatewayCommand(opts: GatewayRunOpts) { return; } + setConsoleTimestampPrefix(true); setVerbose(Boolean(opts.verbose)); if (opts.claudeCliLogs) { setConsoleSubsystemFilter(["agent/claude-cli"]); diff --git a/src/logging/console-capture.test.ts b/src/logging/console-capture.test.ts index 623587604..fe10a6da4 100644 --- a/src/logging/console-capture.test.ts +++ b/src/logging/console-capture.test.ts @@ -8,6 +8,7 @@ import { enableConsoleCapture, resetLogger, routeLogsToStderr, + setConsoleTimestampPrefix, setLoggerOverride, } from "../logging.js"; import { loggingState } from "./state.js"; @@ -34,6 +35,7 @@ beforeEach(() => { }; loggingState.consolePatched = false; loggingState.forceConsoleToStderr = false; + loggingState.consoleTimestampPrefix = false; loggingState.rawConsole = null; resetLogger(); }); @@ -47,6 +49,7 @@ afterEach(() => { console.trace = snapshot.trace; loggingState.consolePatched = false; loggingState.forceConsoleToStderr = false; + loggingState.consoleTimestampPrefix = false; loggingState.rawConsole = null; resetLogger(); setLoggerOverride(null); @@ -72,6 +75,43 @@ describe("enableConsoleCapture", () => { enableConsoleCapture(); expect(() => console.log("hello")).not.toThrow(); }); + + it("prefixes console output with timestamps when enabled", () => { + setLoggerOverride({ level: "info", file: tempLogPath() }); + const now = new Date("2026-01-17T18:01:02.000Z"); + vi.useFakeTimers(); + vi.setSystemTime(now); + const warn = vi.fn(); + console.warn = warn; + setConsoleTimestampPrefix(true); + enableConsoleCapture(); + console.warn("[EventQueue] Slow listener detected"); + expect(warn).toHaveBeenCalledTimes(1); + const firstArg = String(warn.mock.calls[0]?.[0] ?? ""); + expect(firstArg.startsWith("2026-01-17T18:01:02.000Z [EventQueue]")).toBe(true); + vi.useRealTimers(); + }); + + it("does not double-prefix timestamps", () => { + setLoggerOverride({ level: "info", file: tempLogPath() }); + const warn = vi.fn(); + console.warn = warn; + setConsoleTimestampPrefix(true); + enableConsoleCapture(); + console.warn("12:34:56 [exec] hello"); + expect(warn).toHaveBeenCalledWith("12:34:56 [exec] hello"); + }); + + it("leaves JSON output unchanged when timestamp prefix is enabled", () => { + setLoggerOverride({ level: "info", file: tempLogPath() }); + const log = vi.fn(); + console.log = log; + setConsoleTimestampPrefix(true); + enableConsoleCapture(); + const payload = JSON.stringify({ ok: true }); + console.log(payload); + expect(log).toHaveBeenCalledWith(payload); + }); }); function tempLogPath() { diff --git a/src/logging/console.ts b/src/logging/console.ts index 88adbb1b1..013ec4bfb 100644 --- a/src/logging/console.ts +++ b/src/logging/console.ts @@ -67,6 +67,10 @@ export function setConsoleSubsystemFilter(filters?: string[] | null): void { loggingState.consoleSubsystemFilter = normalized.length > 0 ? normalized : null; } +export function setConsoleTimestampPrefix(enabled: boolean): void { + loggingState.consoleTimestampPrefix = enabled; +} + export function shouldLogSubsystemToConsole(subsystem: string): boolean { const filter = loggingState.consoleSubsystemFilter; if (!filter || filter.length === 0) { @@ -93,6 +97,33 @@ function isEpipeError(err: unknown): boolean { return code === "EPIPE" || code === "EIO"; } +function formatConsoleTimestamp(style: ConsoleStyle): string { + const now = new Date().toISOString(); + if (style === "pretty") return now.slice(11, 19); + return now; +} + +function hasTimestampPrefix(value: string): boolean { + return /^(?:\d{2}:\d{2}:\d{2}|\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(?:\.\d+)?Z?)/.test( + value, + ); +} + +function isJsonPayload(value: string): boolean { + const trimmed = value.trim(); + if (!trimmed.startsWith("{") && !trimmed.startsWith("[")) return false; + try { + JSON.parse(trimmed); + return true; + } catch { + return false; + } +} + +function stripAnsi(value: string): string { + return value.replace(/\u001b\[[0-9;]*m/g, ""); +} + /** * Route console.* calls through file logging while still emitting to stdout/stderr. * This keeps user-facing output unchanged but guarantees every console call is captured in log files. @@ -123,6 +154,15 @@ export function enableConsoleCapture(): void { (...args: unknown[]) => { const formatted = util.format(...args); if (shouldSuppressConsoleMessage(formatted)) return; + const trimmed = stripAnsi(formatted).trimStart(); + const shouldPrefixTimestamp = + loggingState.consoleTimestampPrefix && + trimmed.length > 0 && + !hasTimestampPrefix(trimmed) && + !isJsonPayload(trimmed); + const timestamp = shouldPrefixTimestamp + ? formatConsoleTimestamp(getConsoleSettings().style) + : ""; try { // Map console levels to file logger if (level === "trace") { @@ -144,14 +184,27 @@ export function enableConsoleCapture(): void { if (loggingState.forceConsoleToStderr) { // in RPC/JSON mode, keep stdout clean try { - process.stderr.write(`${formatted}\n`); + const line = timestamp ? `${timestamp} ${formatted}` : formatted; + process.stderr.write(`${line}\n`); } catch (err) { if (isEpipeError(err)) return; throw err; } } else { try { - orig.apply(console, args as []); + if (!timestamp) { + orig.apply(console, args as []); + return; + } + if (args.length === 0) { + orig.call(console, timestamp); + return; + } + if (typeof args[0] === "string") { + orig.call(console, `${timestamp} ${args[0]}`, ...args.slice(1)); + return; + } + orig.call(console, timestamp, ...args); } catch (err) { if (isEpipeError(err)) return; throw err; diff --git a/src/logging/state.ts b/src/logging/state.ts index 0481430b1..77badf8ea 100644 --- a/src/logging/state.ts +++ b/src/logging/state.ts @@ -5,6 +5,7 @@ export const loggingState = { overrideSettings: null as unknown, consolePatched: false, forceConsoleToStderr: false, + consoleTimestampPrefix: false, consoleSubsystemFilter: null as string[] | null, rawConsole: null as { log: typeof console.log;