diff --git a/changelog.d/2827-timeline-export-interval-ceiling.fixed.md b/changelog.d/2827-timeline-export-interval-ceiling.fixed.md new file mode 100644 index 000000000..7ba911427 --- /dev/null +++ b/changelog.d/2827-timeline-export-interval-ceiling.fixed.md @@ -0,0 +1 @@ +The timeline plugin's `exportMs` is capped at 2147483647 ms (about 24.8 days): a larger value was handed to `setInterval`, which silently replaced the delay with 1 ms, so an export interval meant as "effectively never" ran the exporter on every tick and each run filtered the whole trace on the host's event loop. The interval is now clamped to the ceiling with one warning naming the interval in force, so a long interval exports on the deadline it asks for. diff --git a/docs/subsystems/timeline.md b/docs/subsystems/timeline.md index d7ab12c72..cfbba268d 100644 --- a/docs/subsystems/timeline.md +++ b/docs/subsystems/timeline.md @@ -57,12 +57,12 @@ 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. 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 POST refuses a redirect (`redirect: 'error'`), as every other credentialed request in this repository does: following a collector's `307` replays `otlpHeaders` and the span payload at the `Location` origin the operator never named, and the export counts as delivered. A redirect is an export failure instead — warned, not counted, retried on the next flush (#2687). 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). `exportMs` is the export interval: capped at 2147483647 ms (Node's `setInterval` ceiling, about 24.8 days), a larger value is clamped to that ceiling with one warning naming the interval in force, because Node would otherwise shorten the delay to 1 ms and run the exporter on every tick. 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 POST refuses a redirect (`redirect: 'error'`), as every other credentialed request in this repository does: following a collector's `307` replays `otlpHeaders` and the span payload at the `Location` origin the operator never named, and the export counts as delivered. A redirect is an export failure instead — warned, not counted, retried on the next flush (#2687). 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 -`plugins/timeline/test/`: panel (geometry, a small hook renderer for open/close, tabs and poll hold, hostile-name negatives), sanitizers, trace store (rotation, retention, lock, crash-safe replace), recorder (negative tests), read model, OTLP export (`otel.test.js`: record→span mapping, payload shape, the cursor and its retry; `otlp-redirect.test.js`: two local servers, a `307` collector whose `Location` origin receives nothing and counts no export, and a `200` still delivered), durable alerts (`alerts.test.js`: one alert per condition, resolution and its grace window, the stuck threshold, the stale look-back, the endpoint and its removal on dispose), the run report (`digest.test.js`: the pure report, and `timeline/digest` through a real host, read-only and gone after dispose), and a host test on the real `ctx.flybot` with a mini agent loop on `core/dev/mock-llm.mjs`. Run `npm test` in `plugins/timeline` (CI job `plugins (timeline)`). +`plugins/timeline/test/`: panel (geometry, a small hook renderer for open/close, tabs and poll hold, hostile-name negatives), sanitizers, trace store (rotation, retention, lock, crash-safe replace), recorder (negative tests), read model, OTLP export (`otel.test.js`: record→span mapping, payload shape, the cursor and its retry; `otlp-redirect.test.js`: two local servers, a `307` collector whose `Location` origin receives nothing and counts no export, and a `200` still delivered; `export-interval-ceiling.test.js`: the delay actually handed to `setInterval`, the clamp above Node's 32-bit timer ceiling and its one warning), durable alerts (`alerts.test.js`: one alert per condition, resolution and its grace window, the stuck threshold, the stale look-back, the endpoint and its removal on dispose), the run report (`digest.test.js`: the pure report, and `timeline/digest` through a real host, read-only and gone after dispose), and a host test on the real `ctx.flybot` with a mini agent loop on `core/dev/mock-llm.mjs`. Run `npm test` in `plugins/timeline` (CI job `plugins (timeline)`). ## Common mistakes diff --git a/plugins/timeline/README.md b/plugins/timeline/README.md index a45fe902e..78262a437 100644 --- a/plugins/timeline/README.md +++ b/plugins/timeline/README.md @@ -58,7 +58,7 @@ The response (`version: 1`) has `lanes` (You, Bots, groups), `turns` (with `tool # otlpUrl: https://collector.example.com/v1/traces # https (or http on localhost only) # otlpHeaders: { authorization: "Bearer …" } # exportNames: true # default false: send Bot/room ids only, no names - # exportMs: 5000 # how often new records are exported + # exportMs: 5000 # how often new records are exported (capped at 2147483647 ms) ``` With `exporter: otlp`, the trace is sent as OpenTelemetry spans: each Bot turn becomes an `invoke_agent` span and its tool calls `execute_tool` spans beneath it. Only finished turns and tool calls are exported. It exports only the metadata the panel shows, never message text, tool arguments or output, and sends Bot and room ids only unless `exportNames: true`. diff --git a/plugins/timeline/src/timeline.js b/plugins/timeline/src/timeline.js index d44b38479..2f3e8ba53 100644 --- a/plugins/timeline/src/timeline.js +++ b/plugins/timeline/src/timeline.js @@ -13,6 +13,13 @@ export const HEALTH_ENDPOINT = 'timeline/health' export const ALERTS_ENDPOINT = 'timeline/alerts' export const DIGEST_ENDPOINT = 'timeline/digest' +const DEFAULT_EXPORT_MS = 5000 +// P-698: `setInterval` cannot hold a delay above a signed 32-bit millisecond count — it rewrites it +// to 1ms and prints `TimeoutOverflowWarning` — so an export interval meant as "effectively never" +// would run the exporter on every tick, each run mapping the whole trace. Anything above the +// ceiling is clamped to it instead. +const MAX_EXPORT_INTERVAL_MS = 2_147_483_647 + export function createTimeline(adapter, { dir, persist = true, now = Date.now, exporter, ...limits } = {}) { let trace try { @@ -34,7 +41,11 @@ export function createTimeline(adapter, { dir, persist = true, now = Date.now, e if (exporter && typeof exporter.send === 'function') { const cursor = createExporter({ send: exporter.send, serviceName: exporter.serviceName, serviceVersion: exporter.serviceVersion, exportNames: exporter.exportNames === true, warn: adapter.warn }) exportNow = async () => { try { return await cursor.push(trace.records(), trace.names()) } catch (error) { adapter.warn('flybot-timeline: export failed: %s', error?.message ?? error); return 0 } } - const intervalMs = Number.isFinite(exporter.intervalMs) && exporter.intervalMs > 0 ? exporter.intervalMs : 5000 + const configuredIntervalMs = Number.isFinite(exporter.intervalMs) && exporter.intervalMs > 0 ? exporter.intervalMs : undefined + const intervalMs = configuredIntervalMs === undefined ? DEFAULT_EXPORT_MS : Math.min(configuredIntervalMs, MAX_EXPORT_INTERVAL_MS) + if (configuredIntervalMs > MAX_EXPORT_INTERVAL_MS) { + adapter.warn(`flybot-timeline: exportMs=${configuredIntervalMs}ms is above Node's ${MAX_EXPORT_INTERVAL_MS}ms timer ceiling; using ${MAX_EXPORT_INTERVAL_MS}ms`) + } exportTimer = setInterval(() => { void exportNow() }, intervalMs) exportTimer.unref?.() } diff --git a/plugins/timeline/test/export-interval-ceiling.test.js b/plugins/timeline/test/export-interval-ceiling.test.js new file mode 100644 index 000000000..aba4e35e5 --- /dev/null +++ b/plugins/timeline/test/export-interval-ceiling.test.js @@ -0,0 +1,119 @@ +// P-698: the OTLP export interval is validated as "a finite number above 0" and handed straight to +// `setInterval`, which cannot hold a delay above 2**31 - 1 ms (2147483647, about 24.8 days): Node +// rewrites the delay to 1 ms and prints `TimeoutOverflowWarning`. A user who writes 30 days to mean +// "effectively never export" therefore got the opposite — the exporter ran on every tick, and each +// run reads and maps the whole trace (a full filter over every record) on the host's event loop. +// These cases pin the ceiling at the only place it can be seen: the delay actually given to +// `setInterval`. +import assert from 'node:assert/strict' +import { test } from 'node:test' +import { createTimeline } from '../src/timeline.js' +import { mockAdapter } from './mock-adapter.js' + +const CEILING = 2 ** 31 - 1 +const DEFAULT_EXPORT_MS = 5000 +const TOO_LONG = 30 * 24 * 60 * 60 * 1000 // 2592000000ms + +const sleep = ms => new Promise(resolve => setTimeout(resolve, ms)) + +// A stand-in for the export timer: it records the delay the plugin asked for and answers a handle +// with the one method the plugin calls on it. When `run` is set the real `setInterval` is used +// underneath, so the case can see whether the timer fires; otherwise nothing is scheduled and the +// recorded delay is the whole measurement. +function watchIntervals({ run = false } = {}) { + const realSetInterval = globalThis.setInterval + const realClearInterval = globalThis.clearInterval + const calls = [] + let fired = 0 + globalThis.setInterval = (fn, ms, ...rest) => { + calls.push(ms) + const body = () => { fired += 1; fn() } + return run ? realSetInterval(body, ms, ...rest) : { unref() {} } + } + globalThis.clearInterval = handle => (run ? realClearInterval(handle) : undefined) + return { + calls, + fired: () => fired, + restore() { + globalThis.setInterval = realSetInterval + globalThis.clearInterval = realClearInterval + }, + } +} + +// Builds one timeline over an exporter at `intervalMs` and hands it to `fn`; the timer globals are +// restored and the timeline disposed however the case ends, so a failing assertion cannot leak a +// patched `setInterval` into the next file. +async function inTimeline({ intervalMs, run = false }, fn) { + const adapter = mockAdapter() + const timers = watchIntervals({ run }) + let timeline + try { + timeline = createTimeline(adapter, { persist: false, exporter: { send: async () => {}, intervalMs } }) + return await fn({ timeline, adapter, timers }) + } finally { + timeline?.dispose() + timers.restore() + } +} + +test('P-698 a deadline above the timer ceiling does not run the exporter on the next tick', { timeout: 10_000 }, async () => { + await inTimeline({ intervalMs: TOO_LONG, run: true }, async ({ timers }) => { + await sleep(60) // 60 ticks of a 1 ms timer, and none of a 24.8-day one + const fired = timers.fired() + const delay = timers.calls[0] + assert.equal(fired, 0, `the exporter ran ${fired} time(s) within 60ms of a 30-day interval, because setInterval got ${delay}ms`) + assert.equal( + delay, + CEILING, + `setInterval was given ${delay}ms for exportMs=${TOO_LONG}ms; Node shortens anything above ${CEILING}ms to 1ms, so the deadline that was asked for is not the deadline the timer holds`, + ) + }) +}) + +test('P-698 a value above the ceiling is clamped, and the warning names the effective interval', async () => { + await inTimeline({ intervalMs: TOO_LONG }, ({ adapter, timers }) => { + const delay = timers.calls[0] + const warnings = adapter.warnings.slice() + + assert.equal(delay, CEILING, `the export timer must be clamped to ${CEILING}ms, got ${delay}ms`) + const ceilingWarnings = warnings.filter(line => line.includes('timer ceiling')) + assert.equal(ceilingWarnings.length, 1, `exactly one warning must name the effective interval; warnings: ${warnings.join(' | ') || '(none)'}`) + assert.match(ceilingWarnings[0], new RegExp(`exportMs=${TOO_LONG}ms`), 'the warning names the value the user configured') + assert.match(ceilingWarnings[0], new RegExp(`using ${CEILING}ms`), 'the warning names the interval that is in force') + }) +}) + +test('P-698 the ceiling itself is a valid interval and is not warned about', async () => { + await inTimeline({ intervalMs: CEILING }, ({ adapter, timers }) => { + const delay = timers.calls[0] + const warnings = adapter.warnings.slice() + + assert.equal(delay, CEILING, `${CEILING}ms is a delay setInterval can hold, so it must be used as given`) + assert.deepEqual(warnings, [], `no warning is due at the ceiling; warnings: ${warnings.join(' | ')}`) + }) +}) + +test('P-698 one millisecond above the ceiling is clamped and warned once', async () => { + await inTimeline({ intervalMs: CEILING + 1 }, ({ adapter, timers }) => { + const delay = timers.calls[0] + const warnings = adapter.warnings.slice() + + assert.equal(delay, CEILING, `one millisecond above the ceiling must still be clamped; got ${delay}ms`) + assert.equal(warnings.length, 1, `one warning above the ceiling; warnings: ${warnings.join(' | ') || '(none)'}`) + assert.match(warnings[0], new RegExp(`${CEILING + 1}ms`), 'the warning names the configured value') + assert.match(warnings[0], new RegExp(`using ${CEILING}ms`), 'the warning names the interval that is in force') + }) +}) + +test('P-698 values the docs already reject still fall back to five seconds', async () => { + for (const ignored of [0, -5, '30', Number.NaN, Infinity, null, undefined]) { + await inTimeline({ intervalMs: ignored }, ({ adapter, timers }) => { + const delay = timers.calls[0] + const warnings = adapter.warnings.slice() + + assert.equal(delay, DEFAULT_EXPORT_MS, `exportMs=${String(ignored)} must fall back to ${DEFAULT_EXPORT_MS}ms, got ${delay}ms`) + assert.deepEqual(warnings, [], `exportMs=${String(ignored)} falls back silently; warnings: ${warnings.join(' | ')}`) + }) + } +})