[Bug]: Tool spans record ~10ms for multi-second tools — opencode restamps time.start on repeat running updates; handler also leaks orphan spans

[afthabvp]

Summary

Tool spans and the tool.duration histogram record near-zero durations (4–43ms) for tools that actually run for many seconds. A bash: sleep 5 && echo done call is recorded as 10ms. The missing time is silently absorbed by the parent opencode.llm span, so dashboards built on this data massively overstate LLM share and understate tool time.

There are two interacting causes: an opencode behavior the plugin needs to defend against, and a plugin handler bug it triggers (which also leaks orphan spans).

Environment

• opencode 1.18.4 (opencode serve, also reproduces with opencode run)
• plugin v1.4.0
• exporter http/json to a local OTLP sink (also seen in production with http/protobuf)
• macOS (darwin arm64) and Linux (Debian, in a container) both reproduce

Root cause 1: opencode restamps state.time.start on repeat running updates

Logging raw message.part.updated events from a minimal spy plugin during the sleep 5 call:

1785152160685 part.updated tool=bash status=pending    time=null
1785152160689 part.updated tool=bash status=running    time={"start":1785152160688}   <- true start
1785152160728 part.updated tool=bash status=running    time={"start":1785152160727}   <- restamped
1785152165756 part.updated tool=bash status=running    time={"start":1785152165753}   <- restamped AFTER the 5s sleep
1785152165764 part.updated tool=bash status=completed  time={"start":1785152165753,"end":1785152165763}

opencode emits running several times for one call and rewrites time.start each time — including one final running right before completed. The completed state inherits the last restamp, so time.end - time.start ≈ 10ms regardless of how long the tool really ran.

Root cause 2: the plugin's running handler is last-write-wins

handleMessagePartUpdated treats every running update as a new execution:

• it starts a new tool span each time — the earlier spans (including the correctly-timed first one) are never ended, so they are never exported: 2 orphan spans leaked per tool call in the trace above;
• it overwrites the pendingToolSpans entry, so by completion time the stored start is the final restamp and the recorded duration collapses to ~0ms.

Reproduction

1. Project with the plugin enabled and any OTLP sink (OPENCODE_ENABLE_TELEMETRY=true, OPENCODE_OTLP_ENDPOINT=http://127.0.0.1:4318, OPENCODE_OTLP_PROTOCOL=http/json).
2. Prompt: Use the bash tool to run exactly this command: sleep 5 && echo done.
3. Observe the exported opencode.tool.bash span: ~10ms, starting after the sleep finished. The parent opencode.llm span contains the missing ~5s.

Spy plugin used to capture the event log:

export const SpyPlugin = async () => ({
  event: async ({ event }: { event: any }) => {
    const p = event.properties?.part
    if (event.type === "message.part.updated" && p?.type === "tool")
      console.error(`${Date.now()} ${p.tool} ${p.state?.status} ${JSON.stringify(p.state?.time ?? null)}`)
  },
})

Suggested fix

First observation wins: ignore repeat running updates for a call already in pendingToolSpans:

if (toolPart.state.status === "running") {
  if (ctx.pendingToolSpans.has(key)) return
  ...
}

The first running carries a genuine time.start (matches the plugin's own wall clock within ~1ms in our captures), so with this guard the completed handler computes the true duration. It also eliminates the orphan-span leak. Optionally, the completion handler can additionally prefer the plugin-observed wall-clock window when it exceeds the state.time window by a safety margin, which defends against any future stamping change.

With this change the same session exports a truthful, gapless timeline:

opencode.llm          142ms -> 2,980ms   (2,838ms)
opencode.tool.bash  2,979ms -> 8,050ms   (5,071ms)   <- the sleep 5
opencode.llm        8,063ms -> 9,247ms   (1,184ms)

We have this implemented with regression tests (including a replay of the exact 3x-restamp event sequence) and are happy to send a PR.

The restamping itself is arguably an opencode core bug worth reporting to sst/opencode separately, but the plugin needs to be robust to repeat running updates either way.