Files
openclaw/src/plugins/tools.ts
Peter Steinberger 0df90d9b8d 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
2026-05-01 23:14:18 +01:00

371 lines
12 KiB
TypeScript

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";
import { loadPluginRegistrySnapshot } from "./plugin-registry-snapshot.js";
import { getActivePluginRegistry } from "./runtime.js";
import {
buildPluginRuntimeLoadOptions,
resolvePluginRuntimeLoadContext,
} from "./runtime/load-context.js";
import type { OpenClawPluginToolContext } from "./types.js";
export type PluginToolMeta = {
pluginId: string;
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<AnyAgentTool, PluginToolMeta>();
export function setPluginToolMeta(tool: AnyAgentTool, meta: PluginToolMeta): void {
pluginToolMeta.set(tool, meta);
}
export function getPluginToolMeta(tool: AnyAgentTool): PluginToolMeta | undefined {
return pluginToolMeta.get(tool);
}
export function copyPluginToolMeta(source: AnyAgentTool, target: AnyAgentTool): void {
const meta = pluginToolMeta.get(source);
if (meta) {
pluginToolMeta.set(target, meta);
}
}
/**
* Builds a collision-proof key for plugin-owned tool metadata lookups.
*/
export function buildPluginToolMetadataKey(pluginId: string, toolName: string): string {
return JSON.stringify([pluginId, toolName]);
}
function normalizeAllowlist(list?: string[]) {
return new Set((list ?? []).map(normalizeToolName).filter(Boolean));
}
function isOptionalToolAllowed(params: {
toolName: string;
pluginId: string;
allowlist: Set<string>;
}): boolean {
if (params.allowlist.size === 0) {
return false;
}
const toolName = normalizeToolName(params.toolName);
if (params.allowlist.has(toolName)) {
return true;
}
const pluginKey = normalizeToolName(params.pluginId);
if (params.allowlist.has(pluginKey)) {
return true;
}
return params.allowlist.has("group:plugins");
}
function isRecord(value: unknown): value is Record<string, unknown> {
return Boolean(value && typeof value === "object" && !Array.isArray(value));
}
function readPluginToolName(tool: unknown): string {
if (!isRecord(tool)) {
return "";
}
// Optional-tool allowlists need a best-effort name before full shape validation.
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";
}
const name = readPluginToolName(tool);
if (!name) {
return "missing non-empty name";
}
if (typeof tool.execute !== "function") {
return `${name} missing execute function`;
}
if (!isRecord(tool.parameters)) {
return `${name} missing parameters object`;
}
return undefined;
}
function resolvePluginToolRuntimePluginIds(params: {
config: PluginLoadOptions["config"];
workspaceDir?: string;
env: NodeJS.ProcessEnv;
}): string[] | undefined {
const pluginIds = new Set<string>();
const activeRegistry = getActivePluginRegistry();
for (const plugin of activeRegistry?.plugins ?? []) {
if (plugin.status === undefined || plugin.status === "loaded") {
pluginIds.add(plugin.id);
}
}
const index = loadPluginRegistrySnapshot({
config: params.config,
workspaceDir: params.workspaceDir,
env: params.env,
});
for (const plugin of listEnabledInstalledPluginRecords(index, params.config)) {
pluginIds.add(plugin.pluginId);
}
return pluginIds.size > 0
? [...pluginIds].toSorted((left, right) => left.localeCompare(right))
: undefined;
}
export function resolvePluginTools(params: {
context: OpenClawPluginToolContext;
existingToolNames?: Set<string>;
toolAllowlist?: string[];
suppressNameConflicts?: boolean;
allowGatewaySubagentBinding?: boolean;
env?: NodeJS.ProcessEnv;
}): AnyAgentTool[] {
// Fast path: when plugins are effectively disabled, avoid discovery/jiti entirely.
// This matters a lot for unit tests and for tool construction hot paths.
const env = params.env ?? process.env;
const baseConfig = applyTestPluginDefaults(params.context.config ?? {}, env);
const context = resolvePluginRuntimeLoadContext({
config: baseConfig,
env,
workspaceDir: params.context.workspaceDir,
});
const normalized = normalizePluginsConfig(context.config.plugins);
if (!normalized.enabled) {
return [];
}
const runtimeOptions = params.allowGatewaySubagentBinding
? { allowGatewaySubagentBinding: true as const }
: undefined;
const onlyPluginIds = resolvePluginToolRuntimePluginIds({
config: context.config,
workspaceDir: context.workspaceDir,
env,
});
const loadOptions = buildPluginRuntimeLoadOptions(context, {
activate: false,
toolDiscovery: true,
...(onlyPluginIds !== undefined ? { onlyPluginIds } : {}),
runtimeOptions,
});
const registry = resolveRuntimePluginRegistry(loadOptions);
if (!registry) {
return [];
}
const tools: AnyAgentTool[] = [];
const existing = params.existingToolNames ?? new Set<string>();
const existingNormalized = new Set(Array.from(existing, (tool) => normalizeToolName(tool)));
const allowlist = normalizeAllowlist(params.toolAllowlist);
const blockedPlugins = new Set<string>();
const factoryTimingStartedAt = Date.now();
const factoryTimings: PluginToolFactoryTiming[] = [];
for (const entry of registry.tools) {
if (blockedPlugins.has(entry.pluginId)) {
continue;
}
const pluginIdKey = normalizeToolName(entry.pluginId);
if (existingNormalized.has(pluginIdKey)) {
const message = `plugin id conflicts with core tool name (${entry.pluginId})`;
if (!params.suppressNameConflicts) {
context.logger.error(message);
registry.diagnostics.push({
level: "error",
pluginId: entry.pluginId,
source: entry.source,
message,
});
}
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 (declaredNames.length > 0) {
context.logger.debug?.(
`plugin tool factory returned null (${entry.pluginId}): [${declaredNames.join(", ")}]`,
);
}
continue;
}
const listRaw: unknown[] = Array.isArray(resolved) ? resolved : [resolved];
const list = entry.optional
? listRaw.filter((tool) =>
isOptionalToolAllowed({
toolName: readPluginToolName(tool),
pluginId: entry.pluginId,
allowlist,
}),
)
: listRaw;
if (list.length === 0) {
continue;
}
const nameSet = new Set<string>();
for (const toolRaw of list) {
// Plugin factories run at request time and can return arbitrary values; isolate
// malformed tools here so one bad plugin tool cannot poison every provider.
const malformedReason = describeMalformedPluginTool(toolRaw);
if (malformedReason) {
const message = `plugin tool is malformed (${entry.pluginId}): ${malformedReason}`;
context.logger.error(message);
registry.diagnostics.push({
level: "error",
pluginId: entry.pluginId,
source: entry.source,
message,
});
continue;
}
const tool = toolRaw as AnyAgentTool;
if (nameSet.has(tool.name) || existing.has(tool.name)) {
const message = `plugin tool name conflict (${entry.pluginId}): ${tool.name}`;
if (!params.suppressNameConflicts) {
context.logger.error(message);
registry.diagnostics.push({
level: "error",
pluginId: entry.pluginId,
source: entry.source,
message,
});
}
continue;
}
nameSet.add(tool.name);
existing.add(tool.name);
pluginToolMeta.set(tool, {
pluginId: entry.pluginId,
optional: entry.optional,
});
tools.push(tool);
}
}
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;
}