chore(tui): log stalled plugin startup

packages/tui/src/plugin/context.tsx

@@ -34,6 +34,7 @@ import { discoverPluginTargets, localSource } from "./discovery"
 import { createPluginSources } from "./source"
 import { isMissingPath } from "../util/config-directories"
 import { createMarkdownRenderer } from "./markdown"
+import { useLog, type LogTags } from "../context/log"
 
 export interface PackageSource {
   readonly prepare: (spec: string, install?: boolean) => Promise<Host.Target>
@@ -81,11 +82,13 @@ type Registration = {
 
 // One entry of the desired plugin generation produced by the resolve phase.
 type Desired = Pick<Registration, "plugin" | "source" | "target" | "version" | "options"> & { enabled: boolean }
+type Trace = <T>(stage: string, tags: LogTags, task: () => Promise<T>) => Promise<T>
 
 const PluginContext = createContext<Value>()
 
 export function PluginProvider(props: ParentProps<{ packages: PackageSource; directories: string[] }>) {
   const host = usePluginHost()
+  const log = useLog({ component: "plugin" })
   const config = useConfig()
   const lifecycle = useTuiLifecycle()
   const client = useClient()
@@ -108,6 +111,34 @@ export function PluginProvider(props: ParentProps<{ packages: PackageSource; dir
   // One save can emit several watch events. Remember setup failures so those
   // events do not repeatedly tear down and restore the last good generation.
   const setupFailures = new Map<string, { version: string; options: Registration["options"]; error: string }>()
+  let operationID = 0
+  const trace: Trace = (stage, tags, task) => {
+    const id = ++operationID
+    const started = Date.now()
+    log.debug("plugin operation started", { id, stage, ...tags })
+    const stalled = setTimeout(
+      () => log.warn("plugin operation stalled", { id, stage, elapsedMs: Date.now() - started, ...tags }),
+      5_000,
+    )
+    return task()
+      .then(
+        (value) => {
+          log.debug("plugin operation completed", { id, stage, durationMs: Date.now() - started, ...tags })
+          return value
+        },
+        (error) => {
+          log.warn("plugin operation failed", {
+            id,
+            stage,
+            durationMs: Date.now() - started,
+            error: errorMessage(error),
+            ...tags,
+          })
+          throw error
+        },
+      )
+      .finally(() => clearTimeout(stalled))
+  }
   const markdown = createMarkdownRenderer(() =>
     Object.values(store.registrations).flatMap((registration) => (registration.active ? [registration.markdown] : [])),
   )
@@ -149,7 +180,9 @@ export function PluginProvider(props: ParentProps<{ packages: PackageSource; dir
         active: () => Boolean(store.registrations[id]?.active),
       },
     })
-    const cleanup = await setup(item.plugin, context, owned).catch((error) => {
+    const cleanup = await trace("setup", { plugin: id, target: item.target }, () =>
+      setup(item.plugin, context, owned),
+    ).catch((error) => {
       clearContributions(id)
       if (item.target)
         setupFailures.set(item.target, {
@@ -181,7 +214,9 @@ export function PluginProvider(props: ParentProps<{ packages: PackageSource; dir
       setStore("registrations", id, "active", false)
       setStore("registrations", id, "cleanups", [])
     })
-    await disposeAll(cleanups).finally(() =>
+    await trace("cleanup", { plugin: id, target: item.target, cleanups: cleanups.length }, () =>
+      disposeAll(cleanups),
+    ).finally(() =>
       batch(() => {
         if (store.registrations[id]) {
           clearContributions(id)
@@ -243,10 +278,20 @@ export function PluginProvider(props: ParentProps<{ packages: PackageSource; dir
   // Package resolution failures would otherwise retry a full npm install on
   // every watch event; remember them until the configuration changes.
   const npmFailures = new Map<string, string>()
+  let reconciliationID = 0
   const reconcile = async () => {
-    await Promise.all(props.directories.map(watcher.wait))
+    const id = ++reconciliationID
+    const started = Date.now()
+    log.info("plugin reconciliation started", { id })
+    await trace("watch", { reconciliation: id, directories: props.directories }, () =>
+      Promise.all(props.directories.map(watcher.wait)).then(() => undefined),
+    )
     const entries = [
-      ...(await discoverPluginTargets(props.directories)).map((entry) => ({
+      ...(
+        await trace("discover", { reconciliation: id, directories: props.directories }, () =>
+          discoverPluginTargets(props.directories),
+        )
+      ).map((entry) => ({
         entry,
         install: true,
         optional: true,
@@ -295,12 +340,20 @@ export function PluginProvider(props: ParentProps<{ packages: PackageSource; dir
       const memo = local ? undefined : npmFailures.get(target)
       const resolved = memo
         ? { status: "failed" as const, error: memo }
-        : await resolvePlugin(target, local, options, previous, props.packages, source.install, sources.read).catch(
-            (error) => ({
-              status: "failed" as const,
-              error: errorMessage(error),
-            }),
-          )
+        : await resolvePlugin(
+            target,
+            local,
+            options,
+            previous,
+            props.packages,
+            source.install,
+            sources.read,
+            trace,
+            id,
+          ).catch((error) => ({
+            status: "failed" as const,
+            error: errorMessage(error),
+          }))
       if (resolved.status === "unsupported") {
         if (source.optional) continue
         failures.push({ target, status: "unsupported" })
@@ -426,6 +479,7 @@ export function PluginProvider(props: ParentProps<{ packages: PackageSource; dir
           action: { label: "Open plugins", run: () => host.keymap.dispatch("plugins.list") },
         })
     setStore("states", reconcileStore(states))
+    log.info("plugin reconciliation completed", { id, durationMs: Date.now() - started, plugins: desired.size })
   }
   const slotItems = new WeakMap<SlotRender, Claim<SlotRender>>()
   // The mounted slot tree: path -> live <Slot> instance count. Reference
@@ -598,17 +652,26 @@ async function resolvePlugin(
   packages: PackageSource,
   install: boolean,
   readSource: ReturnType<typeof createPluginSources>["read"],
+  trace: Trace,
+  reconciliation: number,
 ) {
   // Package entrypoints never change within a session, so a loaded previous
   // version needs no re-resolution (which could otherwise hit npm).
   if (!local && previous && sameOptions(previous.options, options))
     return { status: "unchanged" as const, plugin: previous.plugin, version: previous.version }
-  const target = local ? { directory: fileURLToPath(local) } : await packages.prepare(spec, install)
+  const target = local
+    ? { directory: fileURLToPath(local) }
+    : await trace("prepare", { reconciliation, target: spec, install }, () => packages.prepare(spec, install))
   const entrypoint = Host.resolve(target).tui
   if (!entrypoint) return { status: "unsupported" as const }
   // Content remains stable across the several mtimes one save may expose to
   // filesystem watchers, while the generation keeps reverted modules fresh.
-  let source = local ? await readSource(entrypoint) : { version: entrypoint, module: await Host.load(entrypoint) }
+  let source = local
+    ? await trace("read", { reconciliation, target: spec, entrypoint }, () => readSource(entrypoint))
+    : {
+        version: entrypoint,
+        module: await trace("load", { reconciliation, target: spec, entrypoint }, () => Host.load(entrypoint)),
+      }
   while (true) {
     const version = source.version
     if (previous && previous.version === version && sameOptions(previous.options, options))