From d2c23ca108aec3ae978be712bbffe3658ecf8bc2 Mon Sep 17 00:00:00 2001 From: Danyang Chen Date: Sat, 7 Nov 2026 21:37:04 +0800 Subject: [PATCH] fix(timeline): skip untimed records instead of failing the OTLP export A trace keeps a record whose time cannot be read (src/store.js keeps it, src/window.js skips it), and the export mapped both ends of a turn or tool call through nanos() without a finiteness check, so one such record threw RangeError and dropped every span of the batch. Build no span for a pair whose timestamps are not both finite. Refs #2442 --- changelog.d/2442.fixed.md | 1 + docs/subsystems/timeline.md | 2 +- plugins/timeline/src/otel.js | 4 +++ plugins/timeline/test/otel.test.js | 47 ++++++++++++++++++++++++++++++ 4 files changed, 53 insertions(+), 1 deletion(-) create mode 100644 changelog.d/2442.fixed.md diff --git a/changelog.d/2442.fixed.md b/changelog.d/2442.fixed.md new file mode 100644 index 000000000..c8305ab50 --- /dev/null +++ b/changelog.d/2442.fixed.md @@ -0,0 +1 @@ +The timeline's on-demand OTLP export no longer fails as a whole when the trace holds an old or hand-edited record without a usable time: a turn or tool call whose timestamps cannot be read is skipped, and the complete spans in the same trace are still exported ([#2442](https://github.com/ThinkFlowLab/FlyBot/issues/2442)). diff --git a/docs/subsystems/timeline.md b/docs/subsystems/timeline.md index ded78890f..fa898ec6b 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, 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. +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. A turn or tool call whose pair of timestamps cannot both be read as finite numbers — an old or hand-edited record the trace still keeps — builds no span, the way the window view already skips it, instead of failing the whole export (#2442). 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 75d12ffe2..61c6bc0df 100644 --- a/plugins/timeline/src/otel.js +++ b/plugins/timeline/src/otel.js @@ -65,6 +65,9 @@ export function spansFrom(records, { names = {} } = {}) { for (const [id, te] of ends) { const ts = starts.get(id) if (!ts) continue + // An old or hand-edited record can lack a time (src/store.js keeps it, src/window.js skips it): + // build no span for a turn whose clock cannot be read, rather than failing the whole export. + if (!Number.isFinite(ts.t) || !Number.isFinite(te.t)) continue const attrs = [ { key: 'gen_ai.operation.name', value: str('invoke_agent') }, { key: 'gen_ai.system', value: str('flybot') }, @@ -90,6 +93,7 @@ export function spansFrom(records, { names = {} } = {}) { for (const [key, ke] of toolEnds) { const ks = toolStarts.get(key) if (!ks) continue + if (!Number.isFinite(ks.t) || !Number.isFinite(ke.t)) continue spans.push({ traceId: hexId(`turn:${ks.tid}`, 16), spanId: hexId(`tool-span:${key}`, 8), diff --git a/plugins/timeline/test/otel.test.js b/plugins/timeline/test/otel.test.js index ea2643585..9d1fec294 100644 --- a/plugins/timeline/test/otel.test.js +++ b/plugins/timeline/test/otel.test.js @@ -29,6 +29,53 @@ test('spansFrom builds only closed spans; an open turn or tool call yields nothi assert.deepEqual(Object.fromEntries(tool.attributes.map(a => [a.key, a.value]))['flybot.tool.ok'], { boolValue: true }) }) +// #2442: an old or hand-edited record may carry no usable time. It builds no span, and it must +// not take the spans of the same batch down with it. +test('an untimed turn is skipped, and a complete turn in the same batch still exports', () => { + const untimed = [ + { r: 'ts', id: 'old#1', pl: 'chat', bot: 'a' }, + { r: 'te', id: 'old#1', t: '2026-11-04T10:00:00.000Z', o: 'completed' }, + ] + assert.deepEqual(spansFrom(untimed, { names }), [], 'the untimed turn builds no span') + const complete = [ + { r: 'ts', t: 1_000, id: 'a#1', pl: 'chat', bot: 'a' }, + { r: 'te', t: 1_600, id: 'a#1', o: 'completed' }, + ] + const spans = spansFrom([...untimed, ...complete], { names }) + assert.deepEqual(spans.map(span => span.name), ['invoke_agent Chief'], 'the complete turn still exports') + assert.equal(spans[0].startTimeUnixNano, '1000000000') + assert.equal(spans[0].endTimeUnixNano, '1600000000') +}) + +test('an untimed tool call is skipped, and a complete one in the same batch still exports', () => { + const spans = spansFrom([ + { r: 'ts', t: 1_000, id: 'a#1', pl: 'chat', bot: 'a' }, + { r: 'ks', id: 'c1', tid: 'a#1', nm: 'web_search', bot: 'a' }, + { r: 'ke', t: 1_400, id: 'c1', tid: 'a#1', ok: true }, + { r: 'ks', t: 1_100, id: 'c2', tid: 'a#1', nm: 'read', bot: 'a' }, + { r: 'ke', t: 1_450, id: 'c2', tid: 'a#1', ok: true }, + { r: 'te', t: 1_600, id: 'a#1', o: 'completed' }, + ]) + assert.deepEqual(spans.map(span => span.name).sort(), ['execute_tool read', 'invoke_agent']) + const tool = spans.find(span => span.name === 'execute_tool read') + assert.equal(tool.startTimeUnixNano, '1100000000') + assert.equal(tool.endTimeUnixNano, '1450000000') +}) + +test('the on-demand export skips an untimed record instead of failing the whole trace (#2442)', () => { + const adapter = mockAdapter() + const timeline = createTimeline(adapter, { persist: false, now: () => 5_000 }) + timeline.trace.append({ r: 'ts', id: 'old#1', pl: 'chat', bot: 'a' }) + timeline.trace.append({ r: 'te', id: 'old#1', t: '2026-11-04T10:00:00.000Z', o: 'completed' }) + timeline.trace.append({ r: 'ts', t: 4_100, id: 'a#1', pl: 'chat', bot: 'a' }) + timeline.trace.append({ r: 'te', t: 4_900, id: 'a#1', o: 'completed' }) + const spans = timeline.exportWindow().resourceSpans[0].scopeSpans[0].spans + assert.equal(spans.length, 1, 'the complete turn is exported and the untimed one is not') + assert.equal(spans[0].name, 'invoke_agent') + assert.equal(spans[0].startTimeUnixNano, '4100000000') + timeline.dispose() +}) + test('pendingRecords returns the records whose span is not closed yet', () => { const open = pendingRecords([ { r: 'ts', t: 1, id: 'a#1' }, { r: 'te', t: 2, id: 'a#1' },