From 0df90d9b8d5c4b67ca3e583fafef4a5163ed4a70 Mon Sep 17 00:00:00 2001 From: Peter Steinberger Date: Fri, 1 May 2026 23:14:18 +0100 Subject: [PATCH] fix: trace plugin tool factory timings (#75823) * fix: trace plugin tool factory timings * docs: document plugin tool timing traces * fix: keep plugin tools mcp stdout clean * test: type plugin tools mcp mock * test: complete plugin tools mcp mock * test: preserve console helpers in mcp test * chore: refresh generated protocol models --- .../OpenClawProtocol/GatewayModels.swift | 22 ++++ .../OpenClawProtocol/GatewayModels.swift | 22 ++++ docs/gateway/logging.md | 3 + docs/tools/plugin.md | 31 +++++ src/mcp/plugin-tools-serve.test.ts | 58 +++++++++ src/mcp/plugin-tools-serve.ts | 5 + src/plugins/tools.optional.test.ts | 99 +++++++++++++++ src/plugins/tools.ts | 119 +++++++++++++++++- 8 files changed, 357 insertions(+), 2 deletions(-) diff --git a/apps/macos/Sources/OpenClawProtocol/GatewayModels.swift b/apps/macos/Sources/OpenClawProtocol/GatewayModels.swift index 4b5a3336cc7..3a29531e182 100644 --- a/apps/macos/Sources/OpenClawProtocol/GatewayModels.swift +++ b/apps/macos/Sources/OpenClawProtocol/GatewayModels.swift @@ -2343,6 +2343,7 @@ public struct WizardStep: Codable, Sendable { public let type: AnyCodable public let title: String? public let message: String? + public let format: AnyCodable? public let options: [[String: AnyCodable]]? public let initialvalue: AnyCodable? public let placeholder: String? @@ -2354,6 +2355,7 @@ public struct WizardStep: Codable, Sendable { type: AnyCodable, title: String?, message: String?, + format: AnyCodable?, options: [[String: AnyCodable]]?, initialvalue: AnyCodable?, placeholder: String?, @@ -2364,6 +2366,7 @@ public struct WizardStep: Codable, Sendable { self.type = type self.title = title self.message = message + self.format = format self.options = options self.initialvalue = initialvalue self.placeholder = placeholder @@ -2376,6 +2379,7 @@ public struct WizardStep: Codable, Sendable { case type case title case message + case format case options case initialvalue = "initialValue" case placeholder @@ -2802,6 +2806,24 @@ public struct ChannelsStartParams: Codable, Sendable { } } +public struct ChannelsStopParams: Codable, Sendable { + public let channel: String + public let accountid: String? + + public init( + channel: String, + accountid: String?) + { + self.channel = channel + self.accountid = accountid + } + + private enum CodingKeys: String, CodingKey { + case channel + case accountid = "accountId" + } +} + public struct ChannelsLogoutParams: Codable, Sendable { public let channel: String public let accountid: String? diff --git a/apps/shared/OpenClawKit/Sources/OpenClawProtocol/GatewayModels.swift b/apps/shared/OpenClawKit/Sources/OpenClawProtocol/GatewayModels.swift index 4b5a3336cc7..3a29531e182 100644 --- a/apps/shared/OpenClawKit/Sources/OpenClawProtocol/GatewayModels.swift +++ b/apps/shared/OpenClawKit/Sources/OpenClawProtocol/GatewayModels.swift @@ -2343,6 +2343,7 @@ public struct WizardStep: Codable, Sendable { public let type: AnyCodable public let title: String? public let message: String? + public let format: AnyCodable? public let options: [[String: AnyCodable]]? public let initialvalue: AnyCodable? public let placeholder: String? @@ -2354,6 +2355,7 @@ public struct WizardStep: Codable, Sendable { type: AnyCodable, title: String?, message: String?, + format: AnyCodable?, options: [[String: AnyCodable]]?, initialvalue: AnyCodable?, placeholder: String?, @@ -2364,6 +2366,7 @@ public struct WizardStep: Codable, Sendable { self.type = type self.title = title self.message = message + self.format = format self.options = options self.initialvalue = initialvalue self.placeholder = placeholder @@ -2376,6 +2379,7 @@ public struct WizardStep: Codable, Sendable { case type case title case message + case format case options case initialvalue = "initialValue" case placeholder @@ -2802,6 +2806,24 @@ public struct ChannelsStartParams: Codable, Sendable { } } +public struct ChannelsStopParams: Codable, Sendable { + public let channel: String + public let accountid: String? + + public init( + channel: String, + accountid: String?) + { + self.channel = channel + self.accountid = accountid + } + + private enum CodingKeys: String, CodingKey { + case channel + case accountid = "accountId" + } +} + public struct ChannelsLogoutParams: Codable, Sendable { public let channel: String public let accountid: String? diff --git a/docs/gateway/logging.md b/docs/gateway/logging.md index 22b2ba6ad77..543623f7d88 100644 --- a/docs/gateway/logging.md +++ b/docs/gateway/logging.md @@ -41,6 +41,9 @@ openclaw logs --follow raise the file log level. - To capture verbose-only details in file logs, set `logging.level` to `debug` or `trace`. +- Trace logging also includes diagnostic timing summaries for selected hot paths, + such as plugin tool factory preparation. See + [/tools/plugin#slow-plugin-tool-setup](/tools/plugin#slow-plugin-tool-setup). ## Console capture diff --git a/docs/tools/plugin.md b/docs/tools/plugin.md index c756c3e4504..40257858886 100644 --- a/docs/tools/plugin.md +++ b/docs/tools/plugin.md @@ -334,6 +334,37 @@ do not run in live chat traffic, check these first: Gateway session/status surfaces and, when debugging provider payloads, start the Gateway with `--raw-stream --raw-stream-path `. +### Slow plugin tool setup + +If agent turns appear to stall while preparing tools, enable trace logging and +check for plugin tool factory timing lines: + +```bash +openclaw config set logging.level trace +openclaw logs --follow +``` + +Look for: + +```text +[trace:plugin-tools] factory timings ... +``` + +The summary lists total factory time and the slowest plugin tool factories, +including plugin id, declared tool names, result shape, and whether the tool is +optional. Slow lines are promoted to warnings when a single factory takes at +least 1s or total plugin tool factory prep takes at least 5s. + +If one plugin dominates the timing, inspect its runtime registrations: + +```bash +openclaw plugins inspect --runtime --json +``` + +Then update, reinstall, or disable that plugin. Plugin authors should move +expensive dependency loading behind the tool execution path instead of doing it +inside the tool factory. + ### Duplicate channel or tool ownership Symptoms: diff --git a/src/mcp/plugin-tools-serve.test.ts b/src/mcp/plugin-tools-serve.test.ts index 8e0622e5361..f5bf216adcb 100644 --- a/src/mcp/plugin-tools-serve.test.ts +++ b/src/mcp/plugin-tools-serve.test.ts @@ -8,18 +8,76 @@ import { createMockPluginRegistry } from "../plugins/hooks.test-helpers.js"; import { createPluginToolsMcpHandlers } from "./plugin-tools-handlers.js"; const callGatewayTool = vi.hoisted(() => vi.fn()); +const connectToolsMcpServerToStdioMock = vi.hoisted(() => vi.fn()); +const createToolsMcpServerMock = vi.hoisted(() => vi.fn(() => ({ close: vi.fn() }))); +const getRuntimeConfigMock = vi.hoisted(() => vi.fn(() => ({ plugins: { enabled: true } }))); +const resolvePluginToolsMock = vi.hoisted(() => vi.fn<() => AnyAgentTool[]>(() => [])); +const routeLogsToStderrMock = vi.hoisted(() => vi.fn()); vi.mock("../agents/tools/gateway.js", () => ({ callGatewayTool, })); +vi.mock("../config/config.js", () => ({ + getRuntimeConfig: getRuntimeConfigMock, +})); + +vi.mock("../logging/console.js", async (importOriginal) => { + const actual = await importOriginal(); + return { + ...actual, + routeLogsToStderr: routeLogsToStderrMock, + }; +}); + +vi.mock("../plugins/tools.js", async (importOriginal) => { + const actual = await importOriginal(); + return { + ...actual, + resolvePluginTools: resolvePluginToolsMock, + }; +}); + +vi.mock("./tools-stdio-server.js", () => ({ + connectToolsMcpServerToStdio: connectToolsMcpServerToStdioMock, + createToolsMcpServer: createToolsMcpServerMock, +})); + afterEach(() => { vi.restoreAllMocks(); callGatewayTool.mockReset(); + connectToolsMcpServerToStdioMock.mockReset(); + createToolsMcpServerMock.mockClear(); + getRuntimeConfigMock.mockClear(); + resolvePluginToolsMock.mockReset(); + resolvePluginToolsMock.mockReturnValue([]); + routeLogsToStderrMock.mockReset(); resetGlobalHookRunner(); }); describe("plugin tools MCP server", () => { + it("routes logs to stderr before resolving tools for stdio", async () => { + const { servePluginToolsMcp } = await import("./plugin-tools-serve.js"); + resolvePluginToolsMock.mockReturnValue([ + { + name: "memory_recall", + label: "Recall memory", + description: "Recall stored memory", + parameters: { type: "object", properties: {} }, + execute: vi.fn(), + }, + ]); + + await servePluginToolsMcp(); + + expect(routeLogsToStderrMock).toHaveBeenCalledTimes(1); + expect(resolvePluginToolsMock).toHaveBeenCalledTimes(1); + expect(routeLogsToStderrMock.mock.invocationCallOrder[0]).toBeLessThan( + resolvePluginToolsMock.mock.invocationCallOrder[0] ?? 0, + ); + expect(connectToolsMcpServerToStdioMock).toHaveBeenCalledOnce(); + }); + it("lists registered plugin tools and serializes non-array tool content", async () => { const execute = vi.fn().mockResolvedValue({ content: "Stored.", diff --git a/src/mcp/plugin-tools-serve.ts b/src/mcp/plugin-tools-serve.ts index 0610616f702..010f7983a0e 100644 --- a/src/mcp/plugin-tools-serve.ts +++ b/src/mcp/plugin-tools-serve.ts @@ -12,6 +12,7 @@ import type { AnyAgentTool } from "../agents/tools/common.js"; import { getRuntimeConfig } from "../config/config.js"; import type { OpenClawConfig } from "../config/types.openclaw.js"; import { formatErrorMessage } from "../infra/errors.js"; +import { routeLogsToStderr } from "../logging/console.js"; import { resolvePluginTools } from "../plugins/tools.js"; import { connectToolsMcpServerToStdio, createToolsMcpServer } from "./tools-stdio-server.js"; @@ -34,6 +35,10 @@ export function createPluginToolsMcpServer( } export async function servePluginToolsMcp(): Promise { + // MCP stdio requires stdout to stay protocol-only, including during plugin + // tool discovery before the transport is connected. + routeLogsToStderr(); + const config = getRuntimeConfig(); const tools = resolveTools(config); const server = createPluginToolsMcpServer({ config, tools }); diff --git a/src/plugins/tools.optional.test.ts b/src/plugins/tools.optional.test.ts index e88fcca6667..8c3e79e991d 100644 --- a/src/plugins/tools.optional.test.ts +++ b/src/plugins/tools.optional.test.ts @@ -1,7 +1,10 @@ import { afterEach, beforeAll, beforeEach, describe, expect, it, vi } from "vitest"; +import { resetLogger, setLoggerOverride } from "../logging/logger.js"; +import { loggingState } from "../logging/state.js"; type MockRegistryToolEntry = { pluginId: string; + names?: string[]; optional: boolean; source: string; factory: (ctx: unknown) => unknown; @@ -93,6 +96,7 @@ function setMultiToolRegistry() { function createOptionalDemoEntry(): MockRegistryToolEntry { return { pluginId: "optional-demo", + names: ["optional_tool"], optional: true, source: "/tmp/optional-demo.js", factory: () => makeTool("optional_tool"), @@ -110,6 +114,17 @@ function createMalformedTool(name: string) { }; } +function installConsoleMethodSpy(method: "log" | "warn") { + const spy = vi.fn(); + loggingState.rawConsole = { + log: method === "log" ? spy : vi.fn(), + info: vi.fn(), + warn: method === "warn" ? spy : vi.fn(), + error: vi.fn(), + }; + return spy; +} + function resolveWithConflictingCoreName(options?: { suppressNameConflicts?: boolean }) { return resolvePluginTools( createResolveToolsParams({ @@ -227,6 +242,10 @@ describe("resolvePluginTools optional tools", () => { afterEach(() => { resetPluginRuntimeStateForTest?.(); + setLoggerOverride(null); + loggingState.rawConsole = null; + resetLogger(); + vi.useRealTimers(); }); it("skips optional tools without explicit allowlist", () => { @@ -342,6 +361,86 @@ describe("resolvePluginTools optional tools", () => { ); }); + it("warns with plugin factory timing details when a factory is slow", () => { + vi.useFakeTimers({ now: 0 }); + const warnSpy = installConsoleMethodSpy("warn"); + setLoggerOverride({ level: "silent", consoleLevel: "warn" }); + setRegistry([ + { + pluginId: "optional-demo", + names: ["optional_tool"], + optional: true, + source: "/tmp/optional-demo.js", + factory: () => { + vi.advanceTimersByTime(1200); + return makeTool("optional_tool"); + }, + }, + ]); + + const tools = resolveOptionalDemoTools(["optional_tool"]); + + expectResolvedToolNames(tools, ["optional_tool"]); + expect(warnSpy).toHaveBeenCalledTimes(1); + const message = String(warnSpy.mock.calls[0]?.[0] ?? ""); + expect(message).toContain("[trace:plugin-tools] factory timings"); + expect(message).toContain("totalMs=1200"); + expect(message).toContain("optional-demo:1200ms@1200ms"); + expect(message).toContain("names=[optional_tool]"); + expect(message).toContain("result=single"); + expect(message).toContain("count=1"); + }); + + it("emits trace factory timings below the warn threshold when trace logging is enabled", () => { + vi.useFakeTimers({ now: 0 }); + const logSpy = installConsoleMethodSpy("log"); + setLoggerOverride({ level: "silent", consoleLevel: "trace" }); + setRegistry([ + { + pluginId: "optional-demo", + names: ["optional_tool"], + optional: true, + source: "/tmp/optional-demo.js", + factory: () => { + vi.advanceTimersByTime(5); + return makeTool("optional_tool"); + }, + }, + ]); + + const tools = resolveOptionalDemoTools(["optional_tool"]); + + expectResolvedToolNames(tools, ["optional_tool"]); + expect(logSpy).toHaveBeenCalledTimes(1); + const message = String(logSpy.mock.calls[0]?.[0] ?? ""); + expect(message).toContain("[trace:plugin-tools] factory timings"); + expect(message).toContain("totalMs=5"); + expect(message).toContain("optional-demo:5ms@5ms"); + }); + + it("does not log plugin factory timings for fast factories without trace logging", () => { + vi.useFakeTimers({ now: 0 }); + const warnSpy = installConsoleMethodSpy("warn"); + setLoggerOverride({ level: "silent", consoleLevel: "warn" }); + setRegistry([ + { + pluginId: "optional-demo", + names: ["optional_tool"], + optional: true, + source: "/tmp/optional-demo.js", + factory: () => { + vi.advanceTimersByTime(5); + return makeTool("optional_tool"); + }, + }, + ]); + + const tools = resolveOptionalDemoTools(["optional_tool"]); + + expectResolvedToolNames(tools, ["optional_tool"]); + expect(warnSpy).not.toHaveBeenCalled(); + }); + it("skips allowlisted optional malformed plugin tools", () => { const registry = setRegistry([ { diff --git a/src/plugins/tools.ts b/src/plugins/tools.ts index 06bb8a00c6e..acd07480ebd 100644 --- a/src/plugins/tools.ts +++ b/src/plugins/tools.ts @@ -1,5 +1,6 @@ import { normalizeToolName } from "../agents/tool-policy.js"; import type { AnyAgentTool } from "../agents/tools/common.js"; +import { createSubsystemLogger } from "../logging/subsystem.js"; import { applyTestPluginDefaults, normalizePluginsConfig } from "./config-state.js"; import { listEnabledInstalledPluginRecords } from "./installed-plugin-index.js"; import { resolveRuntimePluginRegistry, type PluginLoadOptions } from "./loader.js"; @@ -16,6 +17,23 @@ export type PluginToolMeta = { optional: boolean; }; +type PluginToolFactoryTimingResult = "array" | "error" | "null" | "single"; + +type PluginToolFactoryTiming = { + pluginId: string; + names: string[]; + durationMs: number; + elapsedMs: number; + result: PluginToolFactoryTimingResult; + resultCount: number; + optional: boolean; +}; + +const log = createSubsystemLogger("plugins/tools"); +const PLUGIN_TOOL_FACTORY_WARN_TOTAL_MS = 5_000; +const PLUGIN_TOOL_FACTORY_WARN_FACTORY_MS = 1_000; +const PLUGIN_TOOL_FACTORY_SUMMARY_LIMIT = 20; + const pluginToolMeta = new WeakMap(); export function setPluginToolMeta(tool: AnyAgentTool, meta: PluginToolMeta): void { @@ -75,6 +93,72 @@ function readPluginToolName(tool: unknown): string { return typeof tool.name === "string" ? tool.name.trim() : ""; } +function toElapsedMs(value: number): number { + return Math.max(0, Math.round(value)); +} + +function describePluginToolFactoryResult( + resolved: AnyAgentTool | AnyAgentTool[] | null | undefined, + failed: boolean, +): { result: PluginToolFactoryTimingResult; resultCount: number } { + if (failed) { + return { result: "error", resultCount: 0 }; + } + if (!resolved) { + return { result: "null", resultCount: 0 }; + } + if (Array.isArray(resolved)) { + return { result: "array", resultCount: resolved.length }; + } + return { result: "single", resultCount: 1 }; +} + +function formatPluginToolFactoryTiming(timing: PluginToolFactoryTiming): string { + const names = timing.names.length > 0 ? timing.names.join("|") : "-"; + return [ + `${timing.pluginId}:${timing.durationMs}ms@${timing.elapsedMs}ms`, + `names=[${names}]`, + `result=${timing.result}`, + `count=${timing.resultCount}`, + `optional=${String(timing.optional)}`, + ].join(" "); +} + +function formatPluginToolFactoryTimingSummary(params: { + totalMs: number; + timings: PluginToolFactoryTiming[]; +}): string { + const ranked = params.timings + .toSorted( + (left, right) => + right.durationMs - left.durationMs || left.pluginId.localeCompare(right.pluginId), + ) + .slice(0, PLUGIN_TOOL_FACTORY_SUMMARY_LIMIT); + const omitted = Math.max(0, params.timings.length - ranked.length); + const factories = + ranked.length > 0 + ? ranked.map((timing) => formatPluginToolFactoryTiming(timing)).join(", ") + : "none"; + return [ + "[trace:plugin-tools] factory timings", + `totalMs=${params.totalMs}`, + `factoryCount=${params.timings.length}`, + `shown=${ranked.length}`, + `omitted=${omitted}`, + `factories=${factories}`, + ].join(" "); +} + +function shouldWarnPluginToolFactoryTimings(params: { + totalMs: number; + timings: PluginToolFactoryTiming[]; +}): boolean { + return ( + params.totalMs >= PLUGIN_TOOL_FACTORY_WARN_TOTAL_MS || + params.timings.some((timing) => timing.durationMs >= PLUGIN_TOOL_FACTORY_WARN_FACTORY_MS) + ); +} + function describeMalformedPluginTool(tool: unknown): string | undefined { if (!isRecord(tool)) { return "tool must be an object"; @@ -163,6 +247,8 @@ export function resolvePluginTools(params: { const existingNormalized = new Set(Array.from(existing, (tool) => normalizeToolName(tool))); const allowlist = normalizeAllowlist(params.toolAllowlist); const blockedPlugins = new Set(); + const factoryTimingStartedAt = Date.now(); + const factoryTimings: PluginToolFactoryTiming[] = []; for (const entry of registry.tools) { if (blockedPlugins.has(entry.pluginId)) { @@ -183,17 +269,35 @@ export function resolvePluginTools(params: { blockedPlugins.add(entry.pluginId); continue; } + const declaredNames = entry.names ?? []; let resolved: AnyAgentTool | AnyAgentTool[] | null | undefined = null; + let factoryFailed = false; + const factoryStartedAt = Date.now(); try { resolved = entry.factory(params.context); } catch (err) { + factoryFailed = true; context.logger.error(`plugin tool failed (${entry.pluginId}): ${String(err)}`); + } finally { + const factoryEndedAt = Date.now(); + const result = describePluginToolFactoryResult(resolved, factoryFailed); + factoryTimings.push({ + pluginId: entry.pluginId, + names: declaredNames, + durationMs: toElapsedMs(factoryEndedAt - factoryStartedAt), + elapsedMs: toElapsedMs(factoryEndedAt - factoryTimingStartedAt), + result: result.result, + resultCount: result.resultCount, + optional: entry.optional, + }); + } + if (factoryFailed) { continue; } if (!resolved) { - if (entry.names.length > 0) { + if (declaredNames.length > 0) { context.logger.debug?.( - `plugin tool factory returned null (${entry.pluginId}): [${entry.names.join(", ")}]`, + `plugin tool factory returned null (${entry.pluginId}): [${declaredNames.join(", ")}]`, ); } continue; @@ -251,5 +355,16 @@ export function resolvePluginTools(params: { } } + if (factoryTimings.length > 0) { + const totalMs = + factoryTimings.at(-1)?.elapsedMs ?? toElapsedMs(Date.now() - factoryTimingStartedAt); + const timingSummary = { totalMs, timings: factoryTimings }; + if (shouldWarnPluginToolFactoryTimings(timingSummary)) { + log.warn(formatPluginToolFactoryTimingSummary(timingSummary)); + } else if (log.isEnabled("trace")) { + log.trace(formatPluginToolFactoryTimingSummary(timingSummary)); + } + } + return tools; }