From de8314a05a451854fa6348f3b5876343c223318c Mon Sep 17 00:00:00 2001 From: Day Dreamer <87640074+HugoXK@users.noreply.github.com> Date: Thu, 5 Nov 2026 21:53:52 +0800 Subject: [PATCH] timeline: export one tool span per turn and call id, not per call id --- changelog.d/2539-otel-tool-span-key.fixed.md | 1 + docs/subsystems/timeline.md | 2 +- plugins/timeline/src/otel.js | 20 +++++---- plugins/timeline/test/otel-tool-ids.test.js | 43 ++++++++++++++++++++ 4 files changed, 58 insertions(+), 8 deletions(-) create mode 100644 changelog.d/2539-otel-tool-span-key.fixed.md create mode 100644 plugins/timeline/test/otel-tool-ids.test.js diff --git a/changelog.d/2539-otel-tool-span-key.fixed.md b/changelog.d/2539-otel-tool-span-key.fixed.md new file mode 100644 index 000000000..46ab91f29 --- /dev/null +++ b/changelog.d/2539-otel-tool-span-key.fixed.md @@ -0,0 +1 @@ +A workflow's tool calls are exported one span each even when two turns number a call the same way: the OTLP export pairs a call with its own turn, so no tool span goes missing and none hangs under another turn. diff --git a/docs/subsystems/timeline.md b/docs/subsystems/timeline.md index c38f39014..2c3392f5f 100644 --- a/docs/subsystems/timeline.md +++ b/docs/subsystems/timeline.md @@ -55,7 +55,7 @@ Everything in `plugins/timeline/`: the recorder, the trace file, the read model 8. The panel draws text only: every string is a React text child or an SVG text node, never markup, and is cleaned again in the browser (`safe`). It polls only while open (and refreshes at once when the tab or window comes back, #259, #271), shows the last good data under an error, and says in a note when the trace is shorter than the window, truncated, memory-only or looking back. Its one-line footnote repeats the honesty rules of invariant 5 (delivered is not read, busy is not idle, model time is not a measured latency). The dialog shrinks to its content and hangs from the top (switching tabs moves nothing above the body), the **Live** control is always shown (pressed while following the latest activity, a call to action when looking back), lanes name what they are under the name (`main`, `group`, `friend`, `removed`) with no icon prefix, and the map puts each name beside or under its node, clipped with the full name in a tooltip (#249). A turn bar's tooltip ends with the model the turn ran on (its model id, `· deepseek-v4-pro`); a running turn, or one recorded before #366, names none (#366). A friend's Bot is named as the sidebar names it (`UiA1415's Chief`, `Helper · UiB1415's Bot`, from the feed's `remote.name` / party `name`), so two Bots called Helper stay apart; a wait label that would run past the plot is right-aligned, and one with no room is left to the arrow's tooltip (#255). The window's range is always in view under the header (`Oct 18 · 13:20:05 – 13:35:05 (15 min)`, dates at both ends across midnight, and whether it is live), and the footnote is two short items, not one line (#279). The wait table below the map prints `–` wherever a number does not exist yet: an edge nobody answered has no median, slowest or total wait, so all three read `–` rather than a measured `0 ms` beside a `Not yet 1`. 9. Opt-in (#281): `apply` without `config.enabled === true` subscribes to nothing, writes nothing and registers no endpoint; the browser entry draws no sidebar row unless `config.sidebarSection === true` and its poller only runs while a panel is open. A test asserts the host does nothing by default. Docs and the install doctor's default commands do not present it as part of a standard install. 10. The endpoint reads only. It does not start, stop, send or change anything. -11. OTLP export (#483) is opt-in and off by default: without `config.exporter` nothing leaves the host. With `exporter: "otlp"` the plugin POSTs OTLP/HTTP JSON to `otlpUrl`; with `"json"` it appends `dir/export.jsonl` (capped at 8 MiB, then it stops and warns). `otlpUrl` must be `https`, or `http` on localhost only (the request may carry an auth header). Only CLOSED spans are exported: a turn needs its `te` and a tool call its `ke`, so an open turn is carried between flushes and exported when it ends, never as a finished success. The exporter reads only the same compact records the panel does (invariant 2 still holds: no message text, arguments or output), maps turns to `invoke_agent` spans and tool calls to `execute_tool` spans under them, and carries every id through the same deterministic hash. Bot and room NAMES are sent only with `exportNames: true`; by default a span carries ids only, so a friend's or another home's name never leaves the host (a name comes from `trace.names()`, which includes friends' Bots and face-room names). The feed has no model name and no token counts, so those GenAI attributes are absent, not guessed. A failed send keeps the cursor, so the next flush retries the same closed spans (tested). The cursor re-reads records at its last timestamp (`>=`), because a `ke` can share the millisecond of its `ks` (or a `te` the time of the last record); a span already sent is deduplicated by id, so a same-millisecond record is neither skipped nor sent twice. +11. OTLP export (#483) is opt-in and off by default: without `config.exporter` nothing leaves the host. With `exporter: "otlp"` the plugin POSTs OTLP/HTTP JSON to `otlpUrl`; with `"json"` it appends `dir/export.jsonl` (capped at 8 MiB, then it stops and warns). `otlpUrl` must be `https`, or `http` on localhost only (the request may carry an auth header). Only CLOSED spans are exported: a turn needs its `te` and a tool call its `ke`, so an open turn is carried between flushes and exported when it ends, never as a finished success. The exporter reads only the same compact records the panel does (invariant 2 still holds: no message text, arguments or output), maps turns to `invoke_agent` spans and tool calls to `execute_tool` spans under them, pairs a tool call by its turn and call id (`tid`/`id`, the pair the window folds by) so two turns that both call a tool `call_0` still export two spans, and carries every id through the same deterministic hash. Bot and room NAMES are sent only with `exportNames: true`; by default a span carries ids only, so a friend's or another home's name never leaves the host (a name comes from `trace.names()`, which includes friends' Bots and face-room names). The feed has no model name and no token counts, so those GenAI attributes are absent, not guessed. A failed send keeps the cursor, so the next flush retries the same closed spans (tested). The cursor re-reads records at its last timestamp (`>=`), because a `ke` can share the millisecond of its `ks` (or a `te` the time of the last record); a span already sent is deduplicated by id, so a same-millisecond record is neither skipped nor sent twice. 12. Durable alerts (#584) keep their state in the plugin process, not in the trace: the tracker opens one alert per condition (`errors:`, `waiting:`, `stuck:`) and resolves it when the condition clears, keeping the resolution readable for a minute so a reader polling slower than the transition still sees that it cleared. `changed` is true only when something opened or resolved; a detail that moves while the alert keeps holding is not a transition. `stuck` uses the same 20 open requests the window already carries and a 15 min default threshold (`stuckMs`), which the issue left open. A window that ends before the last one folded is answered `stale` with the state untouched, so a look-back never resolves a live alert. The state dies with the process: nothing is written, and a restart starts with no alerts rather than replaying old ones. ## Tests diff --git a/plugins/timeline/src/otel.js b/plugins/timeline/src/otel.js index 81485c7ca..75d12ffe2 100644 --- a/plugins/timeline/src/otel.js +++ b/plugins/timeline/src/otel.js @@ -30,6 +30,12 @@ const bool = value => ({ boolValue: Boolean(value) }) const nameOf = (names, group, id) => (id && names?.[group]?.[id]) || undefined +// A tool call's id is unique inside its turn, not across turns: the recorder writes `id` and `tid` +// together and the window folds the pair as `${tid}/${id}` (src/window.js). Two turns of one trace +// can both call a tool `call_0` — two Bots, or a provider that numbers its calls per request — so +// the exporter pairs the two records by that same pair, never by `id` alone. +const toolKey = record => `${record.tid ?? ''}/${record.id}` + const partyAttrs = (prefix, party) => { if (!party || typeof party !== 'object') return [] const out = [] @@ -52,8 +58,8 @@ export function spansFrom(records, { names = {} } = {}) { if (!record || typeof record !== 'object') continue if (record.r === 'ts') starts.set(record.id, record) else if (record.r === 'te') ends.set(record.id, record) - else if (record.r === 'ks') toolStarts.set(record.id, record) - else if (record.r === 'ke') toolEnds.set(record.id, record) + else if (record.r === 'ks') toolStarts.set(toolKey(record), record) + else if (record.r === 'ke') toolEnds.set(toolKey(record), record) } const spans = [] for (const [id, te] of ends) { @@ -81,12 +87,12 @@ export function spansFrom(records, { names = {} } = {}) { status: { code: te.o === 'error' || te.o === 'aborted' ? STATUS_ERROR : STATUS_OK, ...(te.ec ? { message: te.ec } : {}) }, }) } - for (const [id, ke] of toolEnds) { - const ks = toolStarts.get(id) + for (const [key, ke] of toolEnds) { + const ks = toolStarts.get(key) if (!ks) continue spans.push({ traceId: hexId(`turn:${ks.tid}`, 16), - spanId: hexId(`tool-span:${ks.id}`, 8), + spanId: hexId(`tool-span:${key}`, 8), parentSpanId: hexId(`turn-span:${ks.tid}`, 8), name: `execute_tool ${ks.nm}`, kind: KIND_INTERNAL, @@ -135,8 +141,8 @@ export function pendingRecords(records) { for (const record of records) { if (record?.r === 'ts') openTurns.set(record.id, record) else if (record?.r === 'te') openTurns.delete(record.id) - else if (record?.r === 'ks') openTools.set(record.id, record) - else if (record?.r === 'ke') openTools.delete(record.id) + else if (record?.r === 'ks') openTools.set(toolKey(record), record) + else if (record?.r === 'ke') openTools.delete(toolKey(record)) } return [...openTurns.values(), ...openTools.values()] } diff --git a/plugins/timeline/test/otel-tool-ids.test.js b/plugins/timeline/test/otel-tool-ids.test.js new file mode 100644 index 000000000..416b3dd0e --- /dev/null +++ b/plugins/timeline/test/otel-tool-ids.test.js @@ -0,0 +1,43 @@ +// A tool call's id is unique inside its turn, not across turns: the recorder writes `ks`/`ke` +// with both `id` and `tid`, and the window folds them under `${tid}/${id}` (src/window.js). Two +// turns of one trace — two Bots, or a provider that numbers its calls per request — can both call +// a tool `call_0`. The exporter keyed its tool records by `id` alone, so the later turn's start +// replaced the earlier one: one tool span left the batch, its parent was the wrong turn, and an +// open call in the earlier turn was not carried to the next push. Both halves are read here. +import assert from 'node:assert/strict' +import { test } from 'node:test' +import { pendingRecords, spansFrom } from '../src/otel.js' + +const records = [ + { r: 'ts', t: 1000, id: 'turn-a', bot: 'a', pl: 'dm' }, + { r: 'ks', t: 1001, id: 'call_0', tid: 'turn-a', nm: 'read', bot: 'a' }, + { r: 'ke', t: 1005, id: 'call_0', tid: 'turn-a', ok: true }, + { r: 'te', t: 1010, id: 'turn-a', o: 'completed' }, + { r: 'ts', t: 2000, id: 'turn-b', bot: 'b', pl: 'dm' }, + { r: 'ks', t: 2001, id: 'call_0', tid: 'turn-b', nm: 'bash', bot: 'b' }, + { r: 'ke', t: 2009, id: 'call_0', tid: 'turn-b', ok: false }, + { r: 'te', t: 2020, id: 'turn-b', o: 'completed' }, +] + +const agentOf = span => span.attributes.find(attr => attr.key === 'gen_ai.agent.id')?.value?.stringValue + +test('two turns that both call a tool with the same call id export one tool span each', () => { + const spans = spansFrom(records) + const tools = spans.filter(span => span.name.startsWith('execute_tool')) + assert.equal(tools.length, 2, `one span per tool call, saw ${tools.map(span => span.name).join(', ') || 'none'}`) + assert.deepEqual(tools.map(span => span.name).sort(), ['execute_tool bash', 'execute_tool read']) + assert.equal(new Set(tools.map(span => span.spanId)).size, 2, 'the two calls need two span ids') + // Each tool span hangs under its own turn's span, not the other turn's. + const turnSpanOf = new Map(spans.filter(span => span.name.startsWith('invoke_agent')).map(span => [agentOf(span), span.spanId])) + for (const tool of tools) assert.equal(tool.parentSpanId, turnSpanOf.get(agentOf(tool)), `${tool.name} hangs under its own turn`) +}) + +test('a tool call still open in an earlier turn is carried, not replaced by a later one', () => { + const open = pendingRecords([ + { r: 'ts', t: 1, id: 'turn-a' }, + { r: 'ks', t: 2, id: 'call_0', tid: 'turn-a', nm: 'read' }, + { r: 'ts', t: 3, id: 'turn-b' }, + { r: 'ks', t: 4, id: 'call_0', tid: 'turn-b', nm: 'bash' }, + ]) + assert.deepEqual(open.filter(record => record.r === 'ks').map(record => record.tid).sort(), ['turn-a', 'turn-b']) +})