From a48ffda7f74719a0d7137d0b06ddbaae62da0b02 Mon Sep 17 00:00:00 2001 From: Shakker Date: Tue, 28 Apr 2026 15:54:25 +0100 Subject: [PATCH] chore: trace plugin lifecycle phases --- CHANGELOG.md | 1 + docs/cli/plugins.md | 4 + docs/help/debugging.md | 26 +++ src/cli/plugins-cli.ts | 101 ++++++--- src/cli/plugins-install-command.ts | 34 ++- src/cli/plugins-install-persist.ts | 31 ++- src/cli/plugins-registry-refresh.ts | 27 ++- src/plugins/bundled-runtime-mirror.ts | 39 ++-- src/plugins/discovery.ts | 229 +++++++++++---------- src/plugins/manifest-registry-installed.ts | 105 +++++----- src/plugins/plugin-lifecycle-trace.test.ts | 79 +++++++ src/plugins/plugin-lifecycle-trace.ts | 68 ++++++ src/plugins/status.ts | 66 +++--- 13 files changed, 566 insertions(+), 244 deletions(-) create mode 100644 src/plugins/plugin-lifecycle-trace.test.ts create mode 100644 src/plugins/plugin-lifecycle-trace.ts diff --git a/CHANGELOG.md b/CHANGELOG.md index 0eec478d0a8..b5b650434bc 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,7 @@ Docs: https://docs.openclaw.ai ### Fixes +- CLI/plugins: use plugin metadata snapshots for install slot selection and add opt-in plugin lifecycle timing traces, so plugin install avoids runtime-loading the plugin registry for metadata-only decisions. Thanks @shakkernerd. - fix(plugins): restrict bundled plugin dir resolution to trusted package roots. (#73275) Thanks @pgondhi987. - fix(security): prevent workspace PATH injection via service env and trash helpers. (#73264) Thanks @pgondhi987. - Active Memory: allow `allowedChatTypes` to include explicit portal/webchat sessions and classify `agent:...:explicit:...` session keys before opaque session ids can shadow the chat type. Fixes #65775. (#66285) Thanks @Lidang-Jiang. diff --git a/docs/cli/plugins.md b/docs/cli/plugins.md index 3a71b83a8f7..90803bebe33 100644 --- a/docs/cli/plugins.md +++ b/docs/cli/plugins.md @@ -48,6 +48,10 @@ openclaw plugins marketplace list openclaw plugins marketplace list --json ``` +For slow install, inspect, uninstall, or registry-refresh investigation, run the +command with `OPENCLAW_PLUGIN_LIFECYCLE_TRACE=1`. The trace writes phase timings +to stderr and keeps JSON output parseable. See [Debugging](/help/debugging#plugin-lifecycle-trace). + Bundled plugins ship with OpenClaw. Some are enabled by default (for example bundled model providers, bundled speech providers, and the bundled browser plugin); others require `plugins enable`. diff --git a/docs/help/debugging.md b/docs/help/debugging.md index 285c2402313..08f95ba5c53 100644 --- a/docs/help/debugging.md +++ b/docs/help/debugging.md @@ -43,6 +43,32 @@ Use `/trace` for plugin diagnostics such as Active Memory debug summaries. Keep using `/verbose` for normal verbose status/tool output, and keep using `/debug` for runtime-only config overrides. +## Plugin lifecycle trace + +Use `OPENCLAW_PLUGIN_LIFECYCLE_TRACE=1` when plugin lifecycle commands feel slow +and you need a built-in phase breakdown for plugin metadata, discovery, registry, +runtime mirror, config mutation, and refresh work. The trace is opt-in and writes +to stderr, so JSON command output remains parseable. + +Example: + +```bash +OPENCLAW_PLUGIN_LIFECYCLE_TRACE=1 openclaw plugins install tokenjuice --force +``` + +Example output: + +```text +[plugins:lifecycle] phase="config read" ms=6.83 status=ok command="install" +[plugins:lifecycle] phase="slot selection" ms=94.31 status=ok command="install" pluginId="tokenjuice" +[plugins:lifecycle] phase="registry refresh" ms=51.56 status=ok command="install" reason="source-changed" +``` + +Use this for plugin lifecycle investigation before reaching for a CPU profiler. +If the command is running from a source checkout, prefer measuring the built +runtime with `node dist/entry.js ...` after `pnpm build`; `pnpm openclaw ...` +also measures source-runner overhead. + ## Temporary CLI debug timing OpenClaw keeps `src/cli/debug-timing.ts` as a small helper for local diff --git a/src/cli/plugins-cli.ts b/src/cli/plugins-cli.ts index 85fe8cc43d1..f4958441b2b 100644 --- a/src/cli/plugins-cli.ts +++ b/src/cli/plugins-cli.ts @@ -5,6 +5,10 @@ import { getRuntimeConfig, readConfigFileSnapshot, replaceConfigFile } from "../ import { resolveStateDir } from "../config/paths.js"; import type { OpenClawConfig } from "../config/types.openclaw.js"; import type { PluginInstallRecord } from "../config/types.plugins.js"; +import { + tracePluginLifecyclePhase, + tracePluginLifecyclePhaseAsync, +} from "../plugins/plugin-lifecycle-trace.js"; import { formatPluginSourceForTable, resolvePluginSourceRoots } from "../plugins/source-display.js"; import type { PluginLogger } from "../plugins/types.js"; import { defaultRuntime } from "../runtime.js"; @@ -264,18 +268,29 @@ export function registerPluginsCli(program: Command) { } = await import("../plugins/status.js"); const { loadInstalledPluginIndexInstallRecords } = await import("../plugins/installed-plugin-index-records.js"); - const cfg = getRuntimeConfig(); - const installRecords = await loadInstalledPluginIndexInstallRecords(); + const cfg = tracePluginLifecyclePhase("config read", () => getRuntimeConfig(), { + command: "inspect", + }); + const installRecords = await tracePluginLifecyclePhaseAsync( + "install records load", + () => loadInstalledPluginIndexInstallRecords(), + { command: "inspect" }, + ); const loggerParams = opts.json ? { logger: quietPluginJsonLogger } : {}; if (opts.all) { if (id) { defaultRuntime.error("Pass either a plugin id or --all, not both."); return defaultRuntime.exit(1); } - const report = buildPluginDiagnosticsReport({ - config: cfg, - ...loggerParams, - }); + const report = tracePluginLifecyclePhase( + "runtime plugin registry load", + () => + buildPluginDiagnosticsReport({ + config: cfg, + ...loggerParams, + }), + { command: "inspect", all: true }, + ); const inspectAll = buildAllPluginInspectReports({ config: cfg, ...loggerParams, @@ -344,10 +359,15 @@ export function registerPluginsCli(program: Command) { return defaultRuntime.exit(1); } - const snapshotReport = buildPluginSnapshotReport({ - config: cfg, - ...loggerParams, - }); + const snapshotReport = tracePluginLifecyclePhase( + "plugin registry snapshot", + () => + buildPluginSnapshotReport({ + config: cfg, + ...loggerParams, + }), + { command: "inspect" }, + ); const targetPlugin = snapshotReport.plugins.find( (entry) => entry.id === id || entry.name === id, ); @@ -355,11 +375,16 @@ export function registerPluginsCli(program: Command) { defaultRuntime.error(`Plugin not found: ${id}`); return defaultRuntime.exit(1); } - const report = buildPluginDiagnosticsReport({ - config: cfg, - ...loggerParams, - onlyPluginIds: [targetPlugin.id], - }); + const report = tracePluginLifecyclePhase( + "runtime plugin registry load", + () => + buildPluginDiagnosticsReport({ + config: cfg, + ...loggerParams, + onlyPluginIds: [targetPlugin.id], + }), + { command: "inspect", pluginId: targetPlugin.id }, + ); const inspect = buildPluginInspectReport({ id: targetPlugin.id, config: cfg, @@ -603,11 +628,23 @@ export function registerPluginsCli(program: Command) { await import("./plugins-registry-refresh.js"); const { resolvePluginUninstallId } = await import("./plugins-uninstall-selection.js"); const { promptYesNo } = await import("./prompt.js"); - const snapshot = await readConfigFileSnapshot(); + const snapshot = await tracePluginLifecyclePhaseAsync( + "config read", + () => readConfigFileSnapshot(), + { command: "uninstall" }, + ); const sourceConfig = (snapshot.sourceConfig ?? snapshot.config) as OpenClawConfig; - const installRecords = await loadInstalledPluginIndexInstallRecords(); + const installRecords = await tracePluginLifecyclePhaseAsync( + "install records load", + () => loadInstalledPluginIndexInstallRecords(), + { command: "uninstall" }, + ); const cfg = withPluginInstallRecords(sourceConfig, installRecords); - const report = buildPluginSnapshotReport({ config: cfg }); + const report = tracePluginLifecyclePhase( + "plugin registry snapshot", + () => buildPluginSnapshotReport({ config: cfg }), + { command: "uninstall" }, + ); const extensionsDir = path.join(resolveStateDir(process.env, os.homedir), "extensions"); const keepFiles = Boolean(opts.keepFiles || opts.keepConfig); @@ -702,12 +739,17 @@ export function registerPluginsCli(program: Command) { const nextInstallRecords = removePluginInstallRecordFromRecords(installRecords, pluginId); const nextConfig = withoutPluginInstallRecords(plan.config); - await commitPluginInstallRecordsWithConfig({ - previousInstallRecords: installRecords, - nextInstallRecords, - nextConfig, - ...(snapshot.hash !== undefined ? { baseHash: snapshot.hash } : {}), - }); + await tracePluginLifecyclePhaseAsync( + "config mutation", + () => + commitPluginInstallRecordsWithConfig({ + previousInstallRecords: installRecords, + nextInstallRecords, + nextConfig, + ...(snapshot.hash !== undefined ? { baseHash: snapshot.hash } : {}), + }), + { command: "uninstall" }, + ); const directoryResult = await applyPluginUninstallDirectoryRemoval(plan.directoryRemoval); for (const warning of directoryResult.warnings) { defaultRuntime.log(theme.warn(warning)); @@ -716,6 +758,7 @@ export function registerPluginsCli(program: Command) { config: nextConfig, reason: "source-changed", installRecords: nextInstallRecords, + traceCommand: "uninstall", logger: { warn: (message) => defaultRuntime.log(theme.warn(message)), }, @@ -764,8 +807,14 @@ export function registerPluginsCli(program: Command) { marketplace?: string; }, ) => { - const { runPluginInstallCommand } = await import("./plugins-install-command.js"); - await runPluginInstallCommand({ raw, opts }); + await tracePluginLifecyclePhaseAsync( + "install command", + async () => { + const { runPluginInstallCommand } = await import("./plugins-install-command.js"); + await runPluginInstallCommand({ raw, opts }); + }, + { command: "install" }, + ); }, ); diff --git a/src/cli/plugins-install-command.ts b/src/cli/plugins-install-command.ts index 18946c19ef5..765679cc4ed 100644 --- a/src/cli/plugins-install-command.ts +++ b/src/cli/plugins-install-command.ts @@ -20,6 +20,7 @@ import { installPluginFromMarketplace, resolveMarketplaceInstallShortcut, } from "../plugins/marketplace.js"; +import { tracePluginLifecyclePhaseAsync } from "../plugins/plugin-lifecycle-trace.js"; import { validateJsonSchemaValue } from "../plugins/schema-validator.js"; import { defaultRuntime } from "../runtime.js"; import { theme } from "../terminal/theme.js"; @@ -394,7 +395,11 @@ async function loadConfigFromSnapshotForInstall( export async function loadConfigForInstall( request: PluginInstallRequestContext, ): Promise { - const snapshot = await readConfigFileSnapshot(); + const snapshot = await tracePluginLifecyclePhaseAsync( + "config read", + () => readConfigFileSnapshot(), + { command: "install" }, + ); if (snapshot.valid) { return { config: snapshot.sourceConfig, @@ -414,7 +419,11 @@ export async function runPluginInstallCommand(params: { }; }) { const shorthand = !params.opts.marketplace - ? await resolveMarketplaceInstallShortcut(params.raw) + ? await tracePluginLifecyclePhaseAsync( + "marketplace shortcut resolution", + () => resolveMarketplaceInstallShortcut(params.raw), + { command: "install" }, + ) : null; if (shorthand?.ok === false) { defaultRuntime.error(shorthand.error); @@ -641,12 +650,21 @@ export async function runPluginInstallCommand(params: { findBundledSource: (lookup) => findBundledPluginSource({ lookup }), }); if (bundledPreNpmPlan) { - await installBundledPluginSource({ - snapshot, - rawSpec: raw, - bundledSource: bundledPreNpmPlan.bundledSource, - warning: bundledPreNpmPlan.warning, - }); + await tracePluginLifecyclePhaseAsync( + "install execution", + () => + installBundledPluginSource({ + snapshot, + rawSpec: raw, + bundledSource: bundledPreNpmPlan.bundledSource, + warning: bundledPreNpmPlan.warning, + }), + { + command: "install", + source: "bundled", + pluginId: bundledPreNpmPlan.bundledSource.pluginId, + }, + ); return; } diff --git a/src/cli/plugins-install-persist.ts b/src/cli/plugins-install-persist.ts index 34813aa74e9..3a73e46fc6a 100644 --- a/src/cli/plugins-install-persist.ts +++ b/src/cli/plugins-install-persist.ts @@ -8,6 +8,7 @@ import { withoutPluginInstallRecords, } from "../plugins/installed-plugin-index-records.js"; import type { PluginInstallUpdate } from "../plugins/installs.js"; +import { tracePluginLifecyclePhaseAsync } from "../plugins/plugin-lifecycle-trace.js"; import { defaultRuntime } from "../runtime.js"; import { theme } from "../terminal/theme.js"; import { @@ -78,7 +79,11 @@ export async function persistPluginInstall(params: { : enablePluginInConfig(installConfig, params.pluginId, { updateChannelConfig: false, }).config; - const installRecords = await loadInstalledPluginIndexInstallRecords(); + const installRecords = await tracePluginLifecyclePhaseAsync( + "install records load", + () => loadInstalledPluginIndexInstallRecords(), + { command: "install" }, + ); const nextInstallRecords = recordPluginInstallInRecords(installRecords, { pluginId: params.pluginId, ...params.install, @@ -86,18 +91,28 @@ export async function persistPluginInstall(params: { const slotResult = params.enable === false ? { config: next, warnings: [] } - : applySlotSelectionForPlugin(next, params.pluginId); + : await tracePluginLifecyclePhaseAsync( + "slot selection", + async () => applySlotSelectionForPlugin(next, params.pluginId), + { command: "install", pluginId: params.pluginId }, + ); next = withoutPluginInstallRecords(slotResult.config); - await commitPluginInstallRecordsWithConfig({ - previousInstallRecords: installRecords, - nextInstallRecords, - nextConfig: next, - baseHash: params.snapshot.baseHash, - }); + await tracePluginLifecyclePhaseAsync( + "config mutation", + () => + commitPluginInstallRecordsWithConfig({ + previousInstallRecords: installRecords, + nextInstallRecords, + nextConfig: next, + baseHash: params.snapshot.baseHash, + }), + { command: "install" }, + ); await refreshPluginRegistryAfterConfigMutation({ config: next, reason: "source-changed", installRecords: nextInstallRecords, + traceCommand: "install", logger: { warn: (message) => defaultRuntime.log(theme.warn(message)), }, diff --git a/src/cli/plugins-registry-refresh.ts b/src/cli/plugins-registry-refresh.ts index c0c9dc466e3..11307f8ce5e 100644 --- a/src/cli/plugins-registry-refresh.ts +++ b/src/cli/plugins-registry-refresh.ts @@ -2,6 +2,7 @@ import type { OpenClawConfig } from "../config/types.openclaw.js"; import { formatErrorMessage } from "../infra/errors.js"; import { loadInstalledPluginIndexInstallRecords } from "../plugins/installed-plugin-index-records.js"; import type { InstalledPluginIndexRefreshReason } from "../plugins/installed-plugin-index.js"; +import { tracePluginLifecyclePhaseAsync } from "../plugins/plugin-lifecycle-trace.js"; import { refreshPluginRegistry } from "../plugins/plugin-registry.js"; export type PluginRegistryRefreshLogger = { @@ -14,19 +15,29 @@ export async function refreshPluginRegistryAfterConfigMutation(params: { workspaceDir?: string; env?: NodeJS.ProcessEnv; installRecords?: Awaited>; + traceCommand?: string; logger?: PluginRegistryRefreshLogger; }): Promise { try { const installRecords = params.installRecords ?? - (await loadInstalledPluginIndexInstallRecords(params.env ? { env: params.env } : {})); - await refreshPluginRegistry({ - config: params.config, - reason: params.reason, - installRecords, - ...(params.workspaceDir ? { workspaceDir: params.workspaceDir } : {}), - ...(params.env ? { env: params.env } : {}), - }); + (await tracePluginLifecyclePhaseAsync( + "install records load", + () => loadInstalledPluginIndexInstallRecords(params.env ? { env: params.env } : {}), + { command: params.traceCommand ?? "registry-refresh" }, + )); + await tracePluginLifecyclePhaseAsync( + "registry refresh", + () => + refreshPluginRegistry({ + config: params.config, + reason: params.reason, + installRecords, + ...(params.workspaceDir ? { workspaceDir: params.workspaceDir } : {}), + ...(params.env ? { env: params.env } : {}), + }), + { command: params.traceCommand ?? "registry-refresh", reason: params.reason }, + ); } catch (error) { params.logger?.warn?.(`Plugin registry refresh failed: ${formatErrorMessage(error)}`); } diff --git a/src/plugins/bundled-runtime-mirror.ts b/src/plugins/bundled-runtime-mirror.ts index ffb8a1148be..0dcfb8a83be 100644 --- a/src/plugins/bundled-runtime-mirror.ts +++ b/src/plugins/bundled-runtime-mirror.ts @@ -1,6 +1,7 @@ import { createHash } from "node:crypto"; import fs from "node:fs"; import path from "node:path"; +import { tracePluginLifecyclePhase } from "./plugin-lifecycle-trace.js"; const BUNDLED_RUNTIME_MIRROR_METADATA_FILE = ".openclaw-runtime-mirror.json"; const BUNDLED_RUNTIME_MIRROR_METADATA_VERSION = 1; @@ -24,16 +25,22 @@ export function refreshBundledPluginRuntimeMirrorRoot(params: { tempDirParent?: string; precomputedSourceMetadata?: PrecomputedBundledRuntimeMirrorMetadata; }): boolean { - if (path.resolve(params.sourceRoot) === path.resolve(params.targetRoot)) { - return false; - } - const metadata = createBundledRuntimeMirrorMetadata(params, params.precomputedSourceMetadata); - if (isBundledRuntimeMirrorRootFresh(params.targetRoot, metadata)) { - return false; - } - copyBundledPluginRuntimeRoot(params.sourceRoot, params.targetRoot); - writeBundledRuntimeMirrorMetadata(params.targetRoot, metadata); - return true; + return tracePluginLifecyclePhase( + "runtime mirror refresh", + () => { + if (path.resolve(params.sourceRoot) === path.resolve(params.targetRoot)) { + return false; + } + const metadata = createBundledRuntimeMirrorMetadata(params, params.precomputedSourceMetadata); + if (isBundledRuntimeMirrorRootFresh(params.targetRoot, metadata)) { + return false; + } + copyBundledPluginRuntimeRoot(params.sourceRoot, params.targetRoot); + writeBundledRuntimeMirrorMetadata(params.targetRoot, metadata); + return true; + }, + { pluginId: params.pluginId }, + ); } export function copyBundledPluginRuntimeRoot(sourceRoot: string, targetRoot: string): void { @@ -218,9 +225,15 @@ function writeBundledRuntimeMirrorMetadata( } function fingerprintBundledRuntimeMirrorSourceRoot(sourceRoot: string): string { - const hash = createHash("sha256"); - hashBundledRuntimeMirrorDirectory(hash, sourceRoot, sourceRoot); - return hash.digest("hex"); + return tracePluginLifecyclePhase( + "runtime mirror fingerprint", + () => { + const hash = createHash("sha256"); + hashBundledRuntimeMirrorDirectory(hash, sourceRoot, sourceRoot); + return hash.digest("hex"); + }, + { sourceRoot }, + ); } function hashBundledRuntimeMirrorDirectory( diff --git a/src/plugins/discovery.ts b/src/plugins/discovery.ts index ec65fc6d279..65a1aa55c7b 100644 --- a/src/plugins/discovery.ts +++ b/src/plugins/discovery.ts @@ -24,6 +24,7 @@ import { resolvePackageSetupSource, } from "./package-entry-resolution.js"; import { formatPosixMode, isPathInside, safeRealpathSync, safeStatSync } from "./path-safety.js"; +import { tracePluginLifecyclePhase } from "./plugin-lifecycle-trace.js"; import type { PluginOrigin } from "./plugin-origin.types.js"; import { resolvePluginCacheInputs, resolvePluginSourceRoots } from "./roots.js"; @@ -942,65 +943,70 @@ export function discoverOpenClawPlugins(params: { env, }), env, - load: () => { - const result = createDiscoveryResult(); - const seen = new Set(); - const realpathCache = new Map(); - const extra = params.extraPaths ?? []; - for (const extraPath of extra) { - if (typeof extraPath !== "string") { - continue; - } - const trimmed = extraPath.trim(); - if (!trimmed) { - continue; - } - const bundledAlias = resolvePackagedBundledLoadPathAlias({ - bundledRoot: roots.stock, - loadPath: resolveUserPath(trimmed, env), - }); - if (bundledAlias) { - result.diagnostics.push({ - level: "warn", - source: trimmed, - message: `ignored plugins.load.paths entry that points at OpenClaw's ${bundledAlias.kind} bundled plugin directory; remove this redundant path or run openclaw doctor --fix`, - }); - continue; - } - discoverFromPath({ - rawPath: trimmed, - origin: "config", - ownershipUid: params.ownershipUid, - workspaceDir, - env, - candidates: result.candidates, - diagnostics: result.diagnostics, - seen, - realpathCache, - }); - } - const workspaceMatchesBundledRoot = resolvesToSameDirectory( - workspaceRoot, - roots.stock, - realpathCache, - ); - if (roots.workspace && workspaceRoot && !workspaceMatchesBundledRoot) { - // Keep workspace auto-discovery constrained to the OpenClaw extensions root. - // Recursively scanning the full workspace treats arbitrary project folders as - // plugin candidates and causes noisy "plugin manifest not found" validation failures. - discoverInDirectory({ - dir: roots.workspace, - origin: "workspace", - ownershipUid: params.ownershipUid, - workspaceDir: workspaceRoot, - candidates: result.candidates, - diagnostics: result.diagnostics, - seen, - realpathCache, - }); - } - return result; - }, + load: () => + tracePluginLifecyclePhase( + "discovery scan", + () => { + const result = createDiscoveryResult(); + const seen = new Set(); + const realpathCache = new Map(); + const extra = params.extraPaths ?? []; + for (const extraPath of extra) { + if (typeof extraPath !== "string") { + continue; + } + const trimmed = extraPath.trim(); + if (!trimmed) { + continue; + } + const bundledAlias = resolvePackagedBundledLoadPathAlias({ + bundledRoot: roots.stock, + loadPath: resolveUserPath(trimmed, env), + }); + if (bundledAlias) { + result.diagnostics.push({ + level: "warn", + source: trimmed, + message: `ignored plugins.load.paths entry that points at OpenClaw's ${bundledAlias.kind} bundled plugin directory; remove this redundant path or run openclaw doctor --fix`, + }); + continue; + } + discoverFromPath({ + rawPath: trimmed, + origin: "config", + ownershipUid: params.ownershipUid, + workspaceDir, + env, + candidates: result.candidates, + diagnostics: result.diagnostics, + seen, + realpathCache, + }); + } + const workspaceMatchesBundledRoot = resolvesToSameDirectory( + workspaceRoot, + roots.stock, + realpathCache, + ); + if (roots.workspace && workspaceRoot && !workspaceMatchesBundledRoot) { + // Keep workspace auto-discovery constrained to the OpenClaw extensions root. + // Recursively scanning the full workspace treats arbitrary project folders as + // plugin candidates and causes noisy "plugin manifest not found" validation failures. + discoverInDirectory({ + dir: roots.workspace, + origin: "workspace", + ownershipUid: params.ownershipUid, + workspaceDir: workspaceRoot, + candidates: result.candidates, + diagnostics: result.diagnostics, + seen, + realpathCache, + }); + } + return result; + }, + { scope: "scoped", extraPathCount: params.extraPaths?.length ?? 0 }, + ), }); const sharedResult = getCachedDiscoveryResult({ cacheEnabled, @@ -1009,56 +1015,61 @@ export function discoverOpenClawPlugins(params: { env, }), env, - load: () => { - const result = createDiscoveryResult(); - const seen = new Set(); - const realpathCache = new Map(); - for (const sourceOverlayDir of listBundledSourceOverlayDirs({ - bundledRoot: roots.stock, - env, - })) { - discoverFromPath({ - rawPath: sourceOverlayDir, - origin: "bundled", - ownershipUid: params.ownershipUid, - workspaceDir, - env, - candidates: result.candidates, - diagnostics: result.diagnostics, - seen, - realpathCache, - }); - result.diagnostics.push({ - level: "warn", - source: sourceOverlayDir, - message: - "using bind-mounted bundled plugin source overlay; this source overrides the packaged dist bundle for the same plugin id", - }); - } - if (roots.stock) { - discoverInDirectory({ - dir: roots.stock, - origin: "bundled", - ownershipUid: params.ownershipUid, - candidates: result.candidates, - diagnostics: result.diagnostics, - seen, - realpathCache, - }); - } - // Keep auto-discovered global extensions behind bundled plugins. - // Users can still intentionally override via plugins.load.paths (origin=config). - discoverInDirectory({ - dir: roots.global, - origin: "global", - ownershipUid: params.ownershipUid, - candidates: result.candidates, - diagnostics: result.diagnostics, - seen, - realpathCache, - }); - return result; - }, + load: () => + tracePluginLifecyclePhase( + "discovery scan", + () => { + const result = createDiscoveryResult(); + const seen = new Set(); + const realpathCache = new Map(); + for (const sourceOverlayDir of listBundledSourceOverlayDirs({ + bundledRoot: roots.stock, + env, + })) { + discoverFromPath({ + rawPath: sourceOverlayDir, + origin: "bundled", + ownershipUid: params.ownershipUid, + workspaceDir, + env, + candidates: result.candidates, + diagnostics: result.diagnostics, + seen, + realpathCache, + }); + result.diagnostics.push({ + level: "warn", + source: sourceOverlayDir, + message: + "using bind-mounted bundled plugin source overlay; this source overrides the packaged dist bundle for the same plugin id", + }); + } + if (roots.stock) { + discoverInDirectory({ + dir: roots.stock, + origin: "bundled", + ownershipUid: params.ownershipUid, + candidates: result.candidates, + diagnostics: result.diagnostics, + seen, + realpathCache, + }); + } + // Keep auto-discovered global extensions behind bundled plugins. + // Users can still intentionally override via plugins.load.paths (origin=config). + discoverInDirectory({ + dir: roots.global, + origin: "global", + ownershipUid: params.ownershipUid, + candidates: result.candidates, + diagnostics: result.diagnostics, + seen, + realpathCache, + }); + return result; + }, + { scope: "shared" }, + ), }); const result = createDiscoveryResult(); const seenSources = new Set(); diff --git a/src/plugins/manifest-registry-installed.ts b/src/plugins/manifest-registry-installed.ts index b9817b2f708..94ab4301e17 100644 --- a/src/plugins/manifest-registry-installed.ts +++ b/src/plugins/manifest-registry-installed.ts @@ -14,6 +14,7 @@ import { type OpenClawPackageManifest, type PackageManifest, } from "./manifest.js"; +import { tracePluginLifecyclePhase } from "./plugin-lifecycle-trace.js"; const INSTALLED_MANIFEST_REGISTRY_FALLBACK_CACHE_MAX_ENTRIES = 64; @@ -262,54 +263,64 @@ export function loadPluginManifestRegistryForInstalledIndex(params: { includeDisabled?: boolean; bundledChannelConfigCollector?: BundledChannelConfigCollector; }): PluginManifestRegistry { - if (params.pluginIds && params.pluginIds.length === 0) { - return { plugins: [], diagnostics: [] }; - } - const env = params.env ?? process.env; - const cacheKey = shouldUseInstalledManifestRegistryCache({ - env, - bundledChannelConfigCollector: params.bundledChannelConfigCollector, - }) - ? buildInstalledManifestRegistryCacheKey({ - index: params.index, + return tracePluginLifecyclePhase( + "manifest registry", + () => { + if (params.pluginIds && params.pluginIds.length === 0) { + return { plugins: [], diagnostics: [] }; + } + const env = params.env ?? process.env; + const cacheKey = shouldUseInstalledManifestRegistryCache({ + env, + bundledChannelConfigCollector: params.bundledChannelConfigCollector, + }) + ? buildInstalledManifestRegistryCacheKey({ + index: params.index, + config: params.config, + workspaceDir: params.workspaceDir, + env, + pluginIds: params.pluginIds, + includeDisabled: params.includeDisabled, + }) + : undefined; + if (cacheKey) { + const cached = getCachedInstalledManifestRegistry(cacheKey); + if (cached) { + return cached; + } + } + const pluginIdSet = params.pluginIds?.length ? new Set(params.pluginIds) : null; + const diagnostics = pluginIdSet + ? params.index.diagnostics.filter((diagnostic) => { + const pluginId = diagnostic.pluginId; + return !pluginId || pluginIdSet.has(pluginId); + }) + : params.index.diagnostics; + const candidates = params.index.plugins + .filter((plugin) => params.includeDisabled || plugin.enabled) + .filter((plugin) => !pluginIdSet || pluginIdSet.has(plugin.pluginId)) + .map(toPluginCandidate); + const registry = loadPluginManifestRegistry({ config: params.config, workspaceDir: params.workspaceDir, env, - pluginIds: params.pluginIds, - includeDisabled: params.includeDisabled, - }) - : undefined; - if (cacheKey) { - const cached = getCachedInstalledManifestRegistry(cacheKey); - if (cached) { - return cached; - } - } - const pluginIdSet = params.pluginIds?.length ? new Set(params.pluginIds) : null; - const diagnostics = pluginIdSet - ? params.index.diagnostics.filter((diagnostic) => { - const pluginId = diagnostic.pluginId; - return !pluginId || pluginIdSet.has(pluginId); - }) - : params.index.diagnostics; - const candidates = params.index.plugins - .filter((plugin) => params.includeDisabled || plugin.enabled) - .filter((plugin) => !pluginIdSet || pluginIdSet.has(plugin.pluginId)) - .map(toPluginCandidate); - const registry = loadPluginManifestRegistry({ - config: params.config, - workspaceDir: params.workspaceDir, - env, - cache: false, - candidates, - diagnostics: [...diagnostics], - installRecords: extractPluginInstallRecordsFromInstalledPluginIndex(params.index), - ...(params.bundledChannelConfigCollector - ? { bundledChannelConfigCollector: params.bundledChannelConfigCollector } - : {}), - }); - if (cacheKey) { - setCachedInstalledManifestRegistry(cacheKey, registry); - } - return registry; + cache: false, + candidates, + diagnostics: [...diagnostics], + installRecords: extractPluginInstallRecordsFromInstalledPluginIndex(params.index), + ...(params.bundledChannelConfigCollector + ? { bundledChannelConfigCollector: params.bundledChannelConfigCollector } + : {}), + }); + if (cacheKey) { + setCachedInstalledManifestRegistry(cacheKey, registry); + } + return registry; + }, + { + includeDisabled: params.includeDisabled === true, + pluginIdCount: params.pluginIds?.length, + indexPluginCount: params.index.plugins.length, + }, + ); } diff --git a/src/plugins/plugin-lifecycle-trace.test.ts b/src/plugins/plugin-lifecycle-trace.test.ts new file mode 100644 index 00000000000..de430ed4f4c --- /dev/null +++ b/src/plugins/plugin-lifecycle-trace.test.ts @@ -0,0 +1,79 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import { + tracePluginLifecyclePhase, + tracePluginLifecyclePhaseAsync, +} from "./plugin-lifecycle-trace.js"; + +describe("plugin lifecycle trace", () => { + const originalTraceEnv = process.env.OPENCLAW_PLUGIN_LIFECYCLE_TRACE; + let errorSpy: ReturnType; + + beforeEach(() => { + errorSpy = vi.spyOn(console, "error").mockImplementation(() => undefined); + }); + + afterEach(() => { + if (originalTraceEnv === undefined) { + delete process.env.OPENCLAW_PLUGIN_LIFECYCLE_TRACE; + } else { + process.env.OPENCLAW_PLUGIN_LIFECYCLE_TRACE = originalTraceEnv; + } + errorSpy.mockRestore(); + }); + + it("does not emit when the trace env var is disabled", () => { + delete process.env.OPENCLAW_PLUGIN_LIFECYCLE_TRACE; + + expect(tracePluginLifecyclePhase("config read", () => "done")).toBe("done"); + expect(errorSpy).not.toHaveBeenCalled(); + }); + + it("emits a successful sync phase with details when enabled", () => { + process.env.OPENCLAW_PLUGIN_LIFECYCLE_TRACE = "1"; + + expect( + tracePluginLifecyclePhase("config read", () => 42, { + command: "inspect", + includeDisabled: true, + skipped: undefined, + }), + ).toBe(42); + + expect(errorSpy).toHaveBeenCalledTimes(1); + expect(errorSpy.mock.calls[0]?.[0]).toMatch( + /^\[plugins:lifecycle\] phase="config read" ms=\d+\.\d{2} status=ok command="inspect" includeDisabled=true$/, + ); + }); + + it("emits failed sync phases before rethrowing", () => { + process.env.OPENCLAW_PLUGIN_LIFECYCLE_TRACE = "true"; + const error = new Error("boom"); + + expect(() => + tracePluginLifecyclePhase("registry refresh", () => { + throw error; + }), + ).toThrow(error); + + expect(errorSpy).toHaveBeenCalledTimes(1); + expect(errorSpy.mock.calls[0]?.[0]).toMatch( + /^\[plugins:lifecycle\] phase="registry refresh" ms=\d+\.\d{2} status=error$/, + ); + }); + + it("emits failed async phases before rejecting", async () => { + process.env.OPENCLAW_PLUGIN_LIFECYCLE_TRACE = "yes"; + const error = new Error("async boom"); + + await expect( + tracePluginLifecyclePhaseAsync("manifest registry", async () => { + throw error; + }), + ).rejects.toThrow(error); + + expect(errorSpy).toHaveBeenCalledTimes(1); + expect(errorSpy.mock.calls[0]?.[0]).toMatch( + /^\[plugins:lifecycle\] phase="manifest registry" ms=\d+\.\d{2} status=error$/, + ); + }); +}); diff --git a/src/plugins/plugin-lifecycle-trace.ts b/src/plugins/plugin-lifecycle-trace.ts new file mode 100644 index 00000000000..f70f2505942 --- /dev/null +++ b/src/plugins/plugin-lifecycle-trace.ts @@ -0,0 +1,68 @@ +type TraceDetails = Record; + +function isPluginLifecycleTraceEnabled(): boolean { + const raw = process.env.OPENCLAW_PLUGIN_LIFECYCLE_TRACE?.trim().toLowerCase(); + return raw === "1" || raw === "true" || raw === "yes"; +} + +function formatTraceValue(value: boolean | number | string): string { + if (typeof value === "number" || typeof value === "boolean") { + return String(value); + } + return JSON.stringify(value); +} + +function emitPluginLifecycleTrace(params: { + phase: string; + start: bigint; + status: "error" | "ok"; + details?: TraceDetails; +}): void { + const elapsedMs = Number(process.hrtime.bigint() - params.start) / 1_000_000; + const detailText = Object.entries(params.details ?? {}) + .filter((entry): entry is [string, boolean | number | string] => entry[1] !== undefined) + .map(([key, value]) => `${key}=${formatTraceValue(value)}`) + .join(" "); + const suffix = detailText ? ` ${detailText}` : ""; + console.error( + `[plugins:lifecycle] phase=${JSON.stringify(params.phase)} ms=${elapsedMs.toFixed(2)} status=${params.status}${suffix}`, + ); +} + +export function tracePluginLifecyclePhase( + phase: string, + fn: () => T, + details?: TraceDetails, +): T { + if (!isPluginLifecycleTraceEnabled()) { + return fn(); + } + const start = process.hrtime.bigint(); + let status: "error" | "ok" = "error"; + try { + const result = fn(); + status = "ok"; + return result; + } finally { + emitPluginLifecycleTrace({ phase, start, status, details }); + } +} + +export async function tracePluginLifecyclePhaseAsync( + phase: string, + fn: () => Promise, + details?: TraceDetails, +): Promise { + if (!isPluginLifecycleTraceEnabled()) { + return fn(); + } + const start = process.hrtime.bigint(); + let status: "error" | "ok" = "error"; + try { + const result = await fn(); + status = "ok"; + return result; + } finally { + emitPluginLifecycleTrace({ phase, start, status, details }); + } +} diff --git a/src/plugins/status.ts b/src/plugins/status.ts index 4508111fa9b..a4fcbe2db57 100644 --- a/src/plugins/status.ts +++ b/src/plugins/status.ts @@ -22,6 +22,7 @@ import { loadOpenClawPlugins } from "./loader.js"; import { loadPluginManifestRegistryForInstalledIndex } from "./manifest-registry-installed.js"; import type { PluginManifestRecord } from "./manifest-registry.js"; import type { PluginDiagnostic } from "./manifest-types.js"; +import { tracePluginLifecyclePhase } from "./plugin-lifecycle-trace.js"; import { loadPluginRegistrySnapshotWithMetadata, type PluginRegistrySnapshotDiagnostic, @@ -224,11 +225,16 @@ export function buildPluginRegistrySnapshotReport( params?: PluginReportParams, ): PluginRegistryStatusReport { const config = params?.config ?? getRuntimeConfig(); - const result = loadPluginRegistrySnapshotWithMetadata({ - config, - env: params?.env, - workspaceDir: params?.workspaceDir, - }); + const result = tracePluginLifecyclePhase( + "plugin registry snapshot", + () => + loadPluginRegistrySnapshotWithMetadata({ + config, + env: params?.env, + workspaceDir: params?.workspaceDir, + }), + { surface: "status" }, + ); const manifestRegistry = loadPluginManifestRegistryForInstalledIndex({ index: result.snapshot, config, @@ -301,27 +307,37 @@ function buildPluginReport( : [...params.onlyPluginIds]; const registry = loadModules - ? loadOpenClawPlugins( - buildPluginRuntimeLoadOptions(context, { - config: runtimeCompatConfig, - activationSourceConfig: rawConfig, - workspaceDir, - env: params?.env, - loadModules, - activate: false, - cache: false, - onlyPluginIds, - }), + ? tracePluginLifecyclePhase( + "runtime plugin registry load", + () => + loadOpenClawPlugins( + buildPluginRuntimeLoadOptions(context, { + config: runtimeCompatConfig, + activationSourceConfig: rawConfig, + workspaceDir, + env: params?.env, + loadModules, + activate: false, + cache: false, + onlyPluginIds, + }), + ), + { surface: "status", onlyPluginCount: onlyPluginIds?.length }, ) - : loadPluginMetadataRegistrySnapshot({ - config: runtimeCompatConfig, - activationSourceConfig: rawConfig, - workspaceDir, - env: params?.env, - logger: params?.logger, - loadModules: false, - onlyPluginIds, - }); + : tracePluginLifecyclePhase( + "plugin registry snapshot", + () => + loadPluginMetadataRegistrySnapshot({ + config: runtimeCompatConfig, + activationSourceConfig: rawConfig, + workspaceDir, + env: params?.env, + logger: params?.logger, + loadModules: false, + onlyPluginIds, + }), + { surface: "status", onlyPluginCount: onlyPluginIds?.length }, + ); const importedPluginIds = new Set([ ...(loadModules ? registry.plugins