diff --git a/console/packages/console-frontend/src/api/config.ts b/console/packages/console-frontend/src/api/config.ts index 0026d3be9c..b07ab730ac 100644 --- a/console/packages/console-frontend/src/api/config.ts +++ b/console/packages/console-frontend/src/api/config.ts @@ -38,6 +38,14 @@ export function getStreamsWs(): string { return `${wsProtocol}//${host}/ws/streams` } +export function getConsoleEventsWs(): string { + const wsProtocol = + typeof window !== 'undefined' && window.location.protocol === 'https:' ? 'wss:' : 'ws:' + const c = getConfig() + const host = typeof window !== 'undefined' ? window.location.host : `localhost:${c.consolePort}` + return `${wsProtocol}//${host}/ws/console-events` +} + export function getEngineBaseUrl(): string { return '/api/engine' } diff --git a/console/packages/console-frontend/src/api/consoleEvents.ts b/console/packages/console-frontend/src/api/consoleEvents.ts new file mode 100644 index 0000000000..26aa7916c5 --- /dev/null +++ b/console/packages/console-frontend/src/api/consoleEvents.ts @@ -0,0 +1,65 @@ +import { getConsoleEventsWs } from './config' + +export interface ConsoleEventsHandlers { + /** A coalesced "these traces changed" tick. Carries ids only, never span + * data — consumers re-run their own filtered queries (notify-then-query), + * so the engine stays the single source of filter semantics. */ + onTracesChanged: (traceIds: string[]) => void + /** Fired on every (re)connect; consumers resync anything missed while + * disconnected with one refetch. */ + onConnect?: () => void +} + +/** + * Live console-event feed (`/ws/console-events`): the console worker owns a + * `trace` trigger on the engine and forwards its coalesced ticks to every + * connected browser. Replaces the old 1s blind polling of the trace list — + * an idle engine produces no traffic at all. + */ +export function createConsoleEventsSubscription(handlers: ConsoleEventsHandlers): () => void { + let socket: WebSocket | null = null + let reconnectTimer: ReturnType | null = null + let disposed = false + + const connect = () => { + if (disposed) return + socket = new WebSocket(getConsoleEventsWs()) + + socket.onopen = () => { + handlers.onConnect?.() + } + + socket.onmessage = (event) => { + try { + const message = JSON.parse(event.data) + if (message?.type === 'traces_changed') { + const ids = Array.isArray(message.trace_ids) + ? message.trace_ids.filter((id: unknown): id is string => typeof id === 'string') + : [] + handlers.onTracesChanged(ids) + } + } catch { + // Malformed frame — the next tick self-heals. + } + } + + socket.onclose = () => { + socket = null + if (!disposed) { + reconnectTimer = setTimeout(connect, 3000) + } + } + + socket.onerror = () => { + socket?.close() + } + } + + connect() + + return () => { + disposed = true + if (reconnectTimer) clearTimeout(reconnectTimer) + socket?.close() + } +} diff --git a/console/packages/console-frontend/src/hooks/useTraceData.ts b/console/packages/console-frontend/src/hooks/useTraceData.ts index ddccf2b9c0..662306791c 100644 --- a/console/packages/console-frontend/src/hooks/useTraceData.ts +++ b/console/packages/console-frontend/src/hooks/useTraceData.ts @@ -1,6 +1,7 @@ import { useQuery } from '@tanstack/react-query' import { useEffect, useRef, useState } from 'react' import { fetchTraces } from '@/api' +import { createConsoleEventsSubscription } from '@/api/consoleEvents' import type { TracesFilterParams } from '@/api/observability/traces' import { buildTraceGroups, type TraceGroup, traceGroupsFingerprint } from '@/lib/traceGroups' @@ -13,6 +14,9 @@ export interface UseTraceDataOptions { showSystem: boolean debouncedSearch: string isPaused: boolean + /** Called on every trace-change tick (even while paused) with the touched + * trace ids, so the detail view can refresh an open trace. */ + onTracesChanged?: (traceIds: string[]) => void } export interface UseTraceDataReturn { @@ -31,6 +35,7 @@ export function useTraceData({ showSystem, debouncedSearch, isPaused, + onTracesChanged, }: UseTraceDataOptions): UseTraceDataReturn { const [traceGroups, setTraceGroups] = useState([]) const [hasOtelConfigured, setHasOtelConfigured] = useState(false) @@ -58,13 +63,30 @@ export function useTraceData({ limit: DEFAULT_TRACE_LIMIT, include_internal: showSystem, }), - // Interim: poll every 1s (was 3s) so freshly emitted spans surface sooner. - // The real fix is to subscribe to the engine's reactive trace-rows feed - // over the existing streams WebSocket instead of polling at all. - refetchInterval: isPaused ? false : 1000, - staleTime: 1000, }) + // Notify-then-query: the console worker owns a `trace` trigger on the + // engine and forwards its coalesced `{trace_ids}` ticks over + // /ws/console-events; each tick re-runs the filtered query above. No + // polling — an idle engine produces zero traffic — and every (re)connect + // resyncs with one refetch, covering ticks missed while disconnected. + const isPausedRef = useRef(isPaused) + isPausedRef.current = isPaused + const refetchRef = useRef(refetch) + refetchRef.current = refetch + const onTracesChangedRef = useRef(onTracesChanged) + onTracesChangedRef.current = onTracesChanged + + useEffect(() => { + return createConsoleEventsSubscription({ + onConnect: () => refetchRef.current(), + onTracesChanged: (traceIds) => { + if (!isPausedRef.current) refetchRef.current() + onTracesChangedRef.current?.(traceIds) + }, + }) + }, []) + useEffect(() => { if (!tracesData) return diff --git a/console/packages/console-frontend/src/routes/traces.tsx b/console/packages/console-frontend/src/routes/traces.tsx index 56706a1ef5..7257c06adc 100644 --- a/console/packages/console-frontend/src/routes/traces.tsx +++ b/console/packages/console-frontend/src/routes/traces.tsx @@ -90,6 +90,35 @@ function TracesPage() { const [spansError, setSpansError] = useState(null) const [isPaused, setIsPaused] = useState(false) + // Silent refresh of the OPEN trace on a trace-change tick: no loading + // spinner (ticks arrive continuously while the trace runs), one request in + // flight at a time, and a stale response for a since-deselected trace is + // dropped. + const selectedTraceIdRef = useRef(null) + useEffect(() => { + selectedTraceIdRef.current = selectedTraceId + }, [selectedTraceId]) + const refreshInFlightRef = useRef(false) + const handleTracesChanged = useCallback((traceIds: string[]) => { + const current = selectedTraceIdRef.current + if (!current || !traceIds.includes(current) || refreshInFlightRef.current) return + refreshInFlightRef.current = true + fetchTraceTree(current) + .then((data) => { + if (selectedTraceIdRef.current !== current) return + if (data.roots && data.roots.length > 0) { + const wfData = treeToWaterfallData(data.roots) + if (wfData) setWaterfallData(wfData) + } + }) + .catch(() => { + // Keep the current waterfall; the next tick retries. + }) + .finally(() => { + refreshInFlightRef.current = false + }) + }, []) + const { filters: filterState, updateFilter, @@ -118,6 +147,7 @@ function TracesPage() { showSystem, debouncedSearch, isPaused, + onTracesChanged: handleTracesChanged, }) const loadTraceSpans = useCallback(async (traceId: string) => { diff --git a/console/packages/console-rust/src/bridge/events.rs b/console/packages/console-rust/src/bridge/events.rs new file mode 100644 index 0000000000..eb6957dee7 --- /dev/null +++ b/console/packages/console-rust/src/bridge/events.rs @@ -0,0 +1,46 @@ +use iii_sdk::protocol::RegisterTriggerInput; +use iii_sdk::{Error, IIIClient, RegisterFunction}; +use serde_json::{json, Value}; +use tracing::info; + +/// Broadcast channel carrying serialized console events (currently only +/// `traces_changed` ticks) from the engine bridge to every browser connected +/// on `/ws/console-events`. +pub type ConsoleEvents = tokio::sync::broadcast::Sender; + +/// Register the trace-trigger handler and its `trace` trigger. +/// +/// The engine coalesces span activity into one `{trace_ids}` tick per +/// window and invokes the handler fire-and-forget; the handler fans the tick +/// out to the browsers, which re-run their own filtered queries +/// (notify-then-query — the engine stays the single source of filter +/// semantics, and an idle engine produces no traffic at all). The trigger is +/// owned by this bridge connection, so the engine unregisters it when the +/// console disconnects. +pub fn register_trace_events(bridge: &IIIClient, events: ConsoleEvents) -> Result<(), Error> { + let tick = events.clone(); + bridge.register_function( + "engine::console::traces_changed", + RegisterFunction::new_async(move |input: Value| { + let events = tick.clone(); + async move { + let trace_ids = input + .get("trace_ids") + .cloned() + .unwrap_or_else(|| Value::Array(Vec::new())); + let frame = json!({ "type": "traces_changed", "trace_ids": trace_ids }).to_string(); + // No receiver just means no console tab is open right now. + let _ = events.send(frame); + Ok(json!({ "delivered": true })) + } + }), + ); + + info!("Registering trace trigger: engine::console::traces_changed"); + bridge.register_trigger(RegisterTriggerInput::new( + "trace", + "engine::console::traces_changed", + json!({}), + ))?; + Ok(()) +} diff --git a/console/packages/console-rust/src/bridge/mod.rs b/console/packages/console-rust/src/bridge/mod.rs index 52a58b3d81..d462ca83b1 100644 --- a/console/packages/console-rust/src/bridge/mod.rs +++ b/console/packages/console-rust/src/bridge/mod.rs @@ -1,6 +1,8 @@ mod error; +mod events; mod functions; mod triggers; +pub use events::{register_trace_events, ConsoleEvents}; pub use functions::register_functions; pub use triggers::register_triggers; diff --git a/console/packages/console-rust/src/main.rs b/console/packages/console-rust/src/main.rs index 7eec2adbc4..04d0a58be6 100644 --- a/console/packages/console-rust/src/main.rs +++ b/console/packages/console-rust/src/main.rs @@ -180,6 +180,13 @@ async fn main() -> Result<()> { tracing::warn!("Trigger registration failed: {}", e); } + // Trace-change ticks flow engine trigger -> bridge handler -> this + // channel -> every browser on /ws/console-events. + let (events, _) = tokio::sync::broadcast::channel::(64); + if let Err(e) = bridge::register_trace_events(&bridge, events.clone()) { + tracing::warn!("Trace trigger registration failed: {}", e); + } + let config = server::ServerConfig { port: args.port, host: args.host, @@ -187,6 +194,7 @@ async fn main() -> Result<()> { engine_port: args.engine_port, ws_port: args.ws_port, enable_flow: args.enable_flow, + events, }; // Run server with graceful shutdown diff --git a/console/packages/console-rust/src/server.rs b/console/packages/console-rust/src/server.rs index 0c6702defc..10266884bc 100644 --- a/console/packages/console-rust/src/server.rs +++ b/console/packages/console-rust/src/server.rs @@ -29,6 +29,9 @@ pub struct ServerConfig { pub engine_port: u16, pub ws_port: u16, pub enable_flow: bool, + /// Console-event broadcast (trace-change ticks) fanned out on + /// `/ws/console-events`. + pub events: crate::bridge::ConsoleEvents, } pub struct AppState { @@ -91,6 +94,40 @@ async fn serve_config( })) } +/// Fan console events (trace-change ticks) out to a browser. Send-only from +/// the browser's perspective; incoming frames are ignored except to detect +/// close. A lagged receiver just skips ticks — the client refetches on the +/// next one, and resyncs once per (re)connect anyway. +async fn console_events_handler( + axum::extract::State(state): axum::extract::State>, + ws: axum::extract::ws::WebSocketUpgrade, +) -> Response { + let mut events = state.config.events.subscribe(); + ws.on_upgrade(move |mut socket| async move { + loop { + tokio::select! { + event = events.recv() => match event { + Ok(frame) => { + if socket + .send(axum::extract::ws::Message::Text(frame.into())) + .await + .is_err() + { + break; + } + } + Err(tokio::sync::broadcast::error::RecvError::Lagged(_)) => continue, + Err(tokio::sync::broadcast::error::RecvError::Closed) => break, + }, + incoming = socket.recv() => match incoming { + Some(Ok(_)) => continue, + _ => break, + }, + } + } + }) +} + /// Serve the index.html with runtime config async fn serve_index( axum::extract::State(state): axum::extract::State>, @@ -214,7 +251,8 @@ pub async fn run_server(config: ServerConfig) -> Result<()> { let mut app = Router::new() .route("/", get(serve_index)) - .route("/api/config", get(serve_config)); + .route("/api/config", get(serve_config)) + .route("/ws/console-events", any(console_events_handler)); // IMPORTANT: Call .with_state(proxy) BEFORE merging. This converts // Router> to Router<()>, which can be merged into diff --git a/engine/src/workers/observability/README.md b/engine/src/workers/observability/README.md index 659ef0ee7f..f729d8ffa2 100644 --- a/engine/src/workers/observability/README.md +++ b/engine/src/workers/observability/README.md @@ -230,7 +230,7 @@ final span **replaces the snapshot in place** — same storage position, one ent This is what lets live trace views show in-progress work: engine-side parent spans (`trigger `, `enqueue`, builtin `call `) become visible while the work under them is still running, traces -appear in list views as soon as they start, and the trace trigger / devtools streams tick on span +appear in list views as soon as they start, and the trace triggers tick on span start as well as close. Worker (SDK) spans still arrive only when they close — they are ingested over OTLP, which has no notion of an unfinished span. @@ -239,8 +239,8 @@ Consumers of the Traces API should treat `pending: true` (or `end_time_unix_nano `engine::metrics::list` excludes them from latency statistics. The `pending` field is only serialized when true, so the wire shape of finished spans is unchanged. -**OTEL compliance:** pending snapshots exist ONLY in the in-memory store and the `iii:devtools:*` -streams fed from it. The OTLP export path (both the engine exporter and the SDK-span forwarder) is +**OTEL compliance:** pending snapshots exist ONLY in the in-memory store (and the query views and +trace-trigger ticks fed from it). The OTLP export path (both the engine exporter and the SDK-span forwarder) is untouched and only ever ships complete spans — `end_time_unix_nano` is semantically required on the OTLP wire, and nothing partial ever reaches it. Spans that never close (e.g. a leaked guard) remain pending until buffer eviction; they are a dev-store artifact, not exported data. diff --git a/engine/src/workers/observability/mod.rs b/engine/src/workers/observability/mod.rs index 16eaf0ddd0..77898d5a9e 100644 --- a/engine/src/workers/observability/mod.rs +++ b/engine/src/workers/observability/mod.rs @@ -568,20 +568,6 @@ fn is_internal_span(span: &otel::StoredSpan) -> bool { }) } -/// Engine-internal span that is NOT part of a caller's trace: no parent, so -/// it was self-generated by the engine's own machinery (`stream::send` -/// pushes, console consumer deliveries, context-free RPCs under -/// `III_OTEL_TRACE_BUILTINS`). These are the loop risk for the live span -/// feeds — the feed's own pushes must never re-enter it — and are noise as -/// trace roots. A PARENTED internal span, by contrast, is a built-in call -/// made inside a real trace (an agent turn calling `configuration::list`) -/// and belongs in the live feeds like any other span; machinery spans can -/// never be parented because the engine's own calls are made without caller -/// trace context (see `telemetry::should_suppress_invocation_span`). -fn is_context_free_internal_span(span: &otel::StoredSpan) -> bool { - span.parent_span_id.is_none() && is_internal_span(span) -} - // ============================================================================= // OpenTelemetry Module // ============================================================================= @@ -616,22 +602,6 @@ pub const TRACE_TRIGGER_TYPE: &str = "trace"; /// fan-out (and the spans its own delivery produces) to a trickle. const TRACE_COALESCE_MS: u64 = 300; -/// Live span streams the observability worker pushes onto each coalesce tick, -/// consumed by the console Traces view (and any iii client) as a real-time -/// append feed instead of refetching `engine::traces::*`. Ephemeral -/// `stream::send`: the in-memory store stays the source of truth and is -/// re-read once on (re)connect, so a dropped frame self-heals. -const TRACE_ROWS_STREAM: &str = "iii:devtools:trace-rows"; -const TRACE_SPANS_STREAM: &str = "iii:devtools:trace-spans"; -/// EVERY span of each coalesce window (engine-internal spans and trigger -/// deliveries already excluded by the subscriber loop), one global feed — -/// the console masthead's per-span live view. The rows stream above stays -/// roots-only for the trace LIST. -const TRACE_ALL_SPANS_STREAM: &str = "iii:devtools:all-spans"; -/// The single group every list subscriber joins — the list is a global -/// firehose, not per-trace. Detail subscribers join the `trace_id` group. -const TRACE_ROWS_GROUP: &str = "all"; - /// Trace (span) triggers for the OTEL module pub struct OtelTraceTriggers { pub triggers: Arc>>, @@ -750,7 +720,7 @@ fn is_trigger_wrapper(name: &str) -> bool { /// Drop NO-OP trigger fan-out wrappers from the assembled tree: a /// `state_triggers`/`stream_triggers` span with no children fanned out to a -/// handler that produced nothing traceable (e.g. the suppressed devtools stream +/// handler that produced nothing traceable (e.g. suppressed observability /// consumers) — pure noise, and a turn step emits many. Wrappers that DID invoke /// a handler are kept, so the "ran because of a state/stream write" causality /// stays visible. Iterates to a fixpoint so a wrapper left childless by pruning a @@ -880,60 +850,10 @@ fn collapse_spans( .collect() } -/// From a trace's corrected (post prune+collapse) spans and the ids that just -/// arrived in this coalesce window, select the spans to push on the detail -/// stream: each arrived survivor plus its corrected ancestor chain, walked to -/// the root. -/// -/// Including the chain is what re-attaches a span whose nearest real parent is a -/// KEPT internal wrapper (e.g. `stream_triggers`) that the raw window omitted — -/// without it the consumer treats the span's absent parent as a new depth-0 root -/// (the console/web "phantom root" bug). Walking to the root keeps every frame -/// self-contained, so it survives a dropped earlier frame the same way the feed -/// already self-heals on reconnect; the cost is re-emitting ancestors, which is -/// safe because the detail feed is upsert-by-`span_id`. Returned spans carry -/// their CORRECTED `parent_span_id`, so the consumer's `buildSpanTree` nests -/// them identically to `traces::tree` instead of re-rooting. -fn detail_stream_spans( - corrected: &[otel::StoredSpan], - arrived_ids: &HashSet, -) -> Vec { - let parent_of: HashMap<&str, Option<&str>> = corrected - .iter() - .map(|s| (s.span_id.as_str(), s.parent_span_id.as_deref())) - .collect(); - - let mut emit_ids: HashSet = HashSet::new(); - for span in corrected { - // Start only from spans that actually arrived this window AND survived - // the pipeline; a collapsed/pruned arrival simply contributes nothing. - if !arrived_ids.contains(&span.span_id) { - continue; - } - let mut cursor: Option<&str> = Some(span.span_id.as_str()); - while let Some(id) = cursor { - // Already walked this id (and therefore its ancestors) — stop. - // This also terminates parent cycles: a cycle must revisit an id. - if !emit_ids.insert(id.to_string()) { - break; - } - cursor = parent_of.get(id).copied().flatten(); - } - } - - corrected - .iter() - .filter(|s| emit_ids.contains(&s.span_id)) - .cloned() - .collect() -} - -/// Shared trace-correction pipeline: drop no-op trigger fan-out wrappers -/// (childless state_triggers/stream_triggers — wrappers that actually invoked -/// a handler are kept so trigger→handler causality stays visible), then -/// collapse user-configured pass-through spans, reparenting children to the -/// nearest survivor. Both `traces::tree` and the live detail stream go through -/// this one function so the live feed can never disagree with the REST tree. +/// One pipeline for turning a raw stored trace into its presentable span +/// set: prune trigger wrappers that produced nothing, then apply the +/// configured collapse rules. `traces::tree` goes through this one function +/// so alternate consumers cannot drift from it. fn correct_trace_spans( spans: Vec, rules: &[CompiledCollapseRule], @@ -941,23 +861,6 @@ fn correct_trace_spans( collapse_spans(prune_empty_trigger_spans(spans), rules) } -/// Build the detail-stream payload for one trace: run the same -/// [`correct_trace_spans`] pipeline `traces::tree` uses over the FULL raw -/// trace, then keep each arrived span and its corrected ancestor chain (see -/// [`detail_stream_spans`]). -/// -/// The full trace — not just the window — is required because the surviving -/// ancestor a span must reparent to may have arrived in an earlier window. -/// Pure over its inputs so the correction is unit-testable without span storage. -fn corrected_detail_spans( - full_trace: Vec, - arrived_ids: &HashSet, - rules: &[CompiledCollapseRule], -) -> Vec { - let corrected = correct_trace_spans(full_trace, rules); - detail_stream_spans(&corrected, arrived_ids) -} - fn build_span_tree(spans: Vec) -> Vec { // Span ids present in this set. A span whose parent is NOT present is a // local trace root — covers traces entering iii from an external caller via @@ -2008,19 +1911,19 @@ impl ObservabilityWorker { result = rx.recv() => { match result { Ok(span) => { - // Loop-break: drop the engine's own machinery - // spans (context-free internal — the feed's - // pushes and console deliveries must never - // re-enter the feed), any span attributed to - // an observability function (belt: emission - // already refuses those — the pipeline must - // not observe itself), and the trigger's own - // delivery spans. Other PARENTED internal - // spans are built-in calls inside a real - // trace (an agent turn calling - // `configuration::list`) and flow through - // like any other span. - if is_context_free_internal_span(&span) { + // Loop-break, aligned with the DEFAULT list view + // the tick invalidates: drop every internal span + // (machinery AND parented built-ins), spans + // attributed to observability functions (the + // pipeline must not observe itself), and the + // triggers' own delivery spans. Parented + // built-ins must not tick either: a consumer that + // reacts to a tick by querying through its bridge + // produces exactly such spans (`POST _console/*` + // → `call engine::console::*` → worker `execute`), + // and letting any of them re-arm the window is a + // self-sustaining 300ms loop. + if is_internal_span(&span) { continue; } if span_function_id(&span).is_some_and( @@ -2031,6 +1934,25 @@ impl ObservabilityWorker { if span_function_id(&span).is_some_and(|f| trigger_fns.contains(f)) { continue; } + // Worker-side execution spans (`execute `, + // exported over OTLP) carry NO function_id + // attribute, so the attribute-based exclusions + // above miss them. Derive the id from the span + // NAME and re-apply the same rules. + let named_fn = span + .name + .strip_prefix("execute ") + .or_else(|| span.name.strip_prefix("call ")); + if let Some(named_fn) = named_fn { + if trigger_fns.contains(named_fn) + || crate::workers::telemetry::is_observability_function_id( + named_fn, + ) + || named_fn.starts_with("engine::") + { + continue; + } + } window.push(span); } Err(tokio::sync::broadcast::error::RecvError::Lagged(skipped)) => { @@ -2055,7 +1977,6 @@ impl ObservabilityWorker { } let batch = std::mem::take(&mut window); ObservabilityWorker::fire_trace_triggers(&triggers, &engine, &batch).await; - ObservabilityWorker::push_trace_streams(&engine, &batch).await; } } } @@ -2116,138 +2037,6 @@ impl ObservabilityWorker { } } - /// Push the coalesce window's spans onto the live trace streams via - /// ephemeral `stream::send`: root rows (internal/plumbing excluded) to the - /// global list stream, and — per trace touched this window — tree-corrected - /// spans to that trace's detail stream. The detail payload is rebuilt from - /// the FULL trace in storage with the same prune+collapse pipeline as - /// `traces::tree` (see `corrected_detail_spans`), so the live feed is - /// directly appendable and never re-orphans a span whose real parent was an - /// internal wrapper the window filtered out. Fire-and-forget — the in-memory - /// store stays authoritative (re-read once on reconnect), so a dropped frame - /// self-heals rather than corrupting client state. - /// - /// Loop-safe by construction: spans only ENTER the feed through the - /// subscriber's post-filter window, which excludes the engine's own - /// machinery spans (`is_context_free_internal_span`) and the trigger's - /// own delivery spans. The detail payload may re-read KEPT internal - /// wrappers from storage to repair causality, but those are existing - /// stored spans, not new ones — and `stream::send` plus the - /// `iii::console::*` consumer handlers are builtins invoked WITHOUT - /// caller trace context, so their spans are either never emitted at all - /// (`telemetry::should_suppress_invocation_span`) or, under - /// `III_OTEL_TRACE_BUILTINS`, parentless and dropped by the loop-break. - /// Parented internal spans (built-in calls inside a real trace) do flow - /// through — they are caused by user work, not by the feed itself. - async fn push_trace_streams(engine: &Arc, batch: &[otel::StoredSpan]) { - fn send(engine: &Arc, stream_name: &str, group_id: String, spans: Value) { - let payload = serde_json::json!({ - "stream_name": stream_name, - "group_id": group_id, - "type": "spans", - "data": { "spans": spans }, - }); - let engine = engine.clone(); - tokio::spawn(async move { - let _ = engine.call("stream::send", payload).await; - }); - } - - // List: one row per root span, internal/plumbing excluded (the same - // view `traces::list` shows), to the single group every list view joins. - let rows: Vec<&otel::StoredSpan> = batch - .iter() - .filter(|s| s.parent_span_id.is_none() && !is_internal_span(s)) - .collect(); - if !rows.is_empty() - && let Ok(spans) = serde_json::to_value(&rows) - { - send( - engine, - TRACE_ROWS_STREAM, - TRACE_ROWS_GROUP.to_string(), - spans, - ); - } - - // All spans: the whole window as-is to the global per-span feed (the - // console masthead renders one bar per span across all traces). Loop- - // safe for the same reason the window itself is: the engine's own - // machinery spans (context-free internal) and the triggers' own - // delivery spans never entered the batch. Parented built-in spans - // (e.g. a turn's `call configuration::list`) are part of the feed by - // design — the funnel/trace_hidden layer owns hiding them. - if let Ok(spans) = serde_json::to_value(batch) { - send( - engine, - TRACE_ALL_SPANS_STREAM, - TRACE_ROWS_GROUP.to_string(), - spans, - ); - } - - // Detail: tree-corrected spans grouped by trace_id, to that trace's - // group. The raw window is structurally lossy — its spans' parents point - // at engine-internal wrappers (`stream_triggers` etc.) the subscriber - // already filtered out, so a naive push re-orphans every span whose real - // parent was such a wrapper. Instead, per touched trace, recompute - // structure from the FULL trace in storage with the SAME pipeline as - // `traces::tree`, then push each arrived span with its corrected ancestor - // chain. Only a subscriber that joined this `trace_id` receives it - // (engine-side fan-out filter), so a trace nobody is viewing costs just - // the no-match early-out in `stream::invoke_triggers`. - // - // Cost: one in-memory `get_spans_by_trace_id` + prune/collapse per - // distinct trace per coalesce tick (bounded by the 300ms window and the - // set of traces actively streaming). Acceptable; a future optimization - // could memoize the corrected parent map per trace. - let Some(_storage) = otel::get_span_storage() else { - return; // No in-memory store → nothing to correct against. - }; - let collapse_rules = cached_collapse_rules(); - - let mut arrived_by_trace: HashMap> = HashMap::new(); - for span in batch { - arrived_by_trace - .entry(span.trace_id.clone()) - .or_default() - .insert(span.span_id.clone()); - } - - // The trace re-reads may hit the durable archive; run them off the - // async executor so the coalesce tick never stalls the broadcast - // receiver into `Lagged` drops. Fire-and-forget on task failure — the - // store stays authoritative and clients self-heal on reconnect. - let corrected = tokio::task::spawn_blocking(move || { - let collapse_rules = collapse_rules.as_slice(); - let mut corrected: Vec<(String, Value)> = Vec::new(); - for (trace_id, arrived_ids) in arrived_by_trace { - let full_trace = otel::get_query_spans_by_trace_id(&trace_id); - let to_send = corrected_detail_spans(full_trace, &arrived_ids, collapse_rules); - if !to_send.is_empty() - && let Ok(spans) = serde_json::to_value(&to_send) - { - corrected.push((trace_id, spans)); - } - } - corrected - }) - .await; - match corrected { - Ok(corrected) => { - for (trace_id, spans) in corrected { - send(engine, TRACE_SPANS_STREAM, trace_id, spans); - } - } - Err(join_error) => { - tracing::warn!( - error = %join_error, - "iii-observability: deferred trace-detail correction task failed" - ); - } - } - } - // ========================================================================= // Traces Functions // ========================================================================= @@ -4605,62 +4394,6 @@ mod tests { } } - #[test] - fn context_free_internal_spans_are_machinery_parented_ones_are_not() { - // Parentless internal span: the engine's own machinery (a - // `stream::send` push under III_OTEL_TRACE_BUILTINS, a context-free - // console RPC) — must stay out of the live feeds (loop-break). - let machinery = make_span( - "t1", - "s1", - None, - "call stream::send", - "iii", - 1, - 2, - "OK", - vec![ - ("iii.function.kind", "internal"), - ("function_id", "stream::send"), - ], - ); - assert!(is_context_free_internal_span(&machinery)); - - // Parented internal span: a built-in called INSIDE a real trace (an - // agent turn calling `configuration::list`) — belongs in the live - // feeds so the trace UI can show it (and its failure). - let builtin_in_turn = make_span( - "t1", - "s2", - Some("step-span"), - "call configuration::list", - "iii", - 1, - 2, - "ERROR", - vec![ - ("iii.function.kind", "internal"), - ("function_id", "configuration::list"), - ], - ); - assert!(!is_context_free_internal_span(&builtin_in_turn)); - assert!(is_internal_span(&builtin_in_turn)); - - // Ordinary parentless user root: not internal, not machinery. - let user_root = make_span( - "t2", - "s3", - None, - "execute harness::send", - "harness", - 1, - 2, - "OK", - vec![], - ); - assert!(!is_context_free_internal_span(&user_root)); - } - fn make_log( trace_id: Option<&str>, span_id: Option<&str>, @@ -4868,191 +4601,6 @@ mod tests { assert_eq!(tree[0].children[0].span.span_id, "leaf"); } - // ========================================================================= - // detail stream correction tests (corrected_detail_spans) - // ========================================================================= - - #[test] - fn test_corrected_detail_spans_reattaches_under_kept_wrapper() { - // turn -> steering_check -> stream_triggers (internal wrapper) -> leaf. - // Only `leaf` arrives this window — the wrapper is internal, so the span - // subscriber filtered it out of the batch. The OLD feed pushed just - // `leaf` pointing at the absent wrapper → phantom depth-0 root. The - // corrected payload must KEEP the wrapper (it has a child) and emit the - // whole chain so `leaf` nests under it, matching `traces::tree`. - let turn = make_span("t", "turn", None, "turn", "harness", 100, 900, "ok", vec![]); - let steering = make_span( - "t", - "steer", - Some("turn"), - "steering_check", - "harness", - 110, - 880, - "ok", - vec![], - ); - let wrapper = make_span( - "t", - "wrap", - Some("steer"), - "stream_triggers", - "harness", - 120, - 870, - "ok", - vec![("iii.function.kind", "internal")], - ); - let leaf = make_span( - "t", - "leaf", - Some("wrap"), - "context-compaction::on_agent_event", - "ctx", - 130, - 860, - "ok", - vec![], - ); - - let full = vec![turn, steering, wrapper, leaf]; - let arrived: HashSet = ["leaf".to_string()].into_iter().collect(); - - let sent = corrected_detail_spans(full, &arrived, &[]); - let ids: HashSet<&str> = sent.iter().map(|s| s.span_id.as_str()).collect(); - - // Kept internal wrapper + the spine are emitted so nothing re-roots. - assert!( - ids.contains("wrap"), - "kept internal wrapper must be streamed so the leaf has a present parent" - ); - assert!(ids.contains("leaf")); - assert!(ids.contains("steer")); - assert!(ids.contains("turn")); - - // The leaf still parents to the wrapper, not to a phantom root. - let leaf = sent.iter().find(|s| s.span_id == "leaf").unwrap(); - assert_eq!(leaf.parent_span_id.as_deref(), Some("wrap")); - - // The chain is intact: building the tree yields a single root. - let tree = build_span_tree(sent); - assert_eq!(tree.len(), 1); - assert_eq!(tree[0].span.span_id, "turn"); - } - - #[test] - fn test_corrected_detail_spans_drops_childless_wrapper() { - // steering_check has a childless `stream_triggers` (no-op fan-out) plus a - // real `leaf`. The childless wrapper is pruned and never streamed; the - // leaf streams under the surviving `steering_check`. - let steering = make_span( - "t", - "steer", - None, - "steering_check", - "harness", - 100, - 500, - "ok", - vec![], - ); - let empty_wrapper = make_span( - "t", - "wrap", - Some("steer"), - "stream_triggers", - "harness", - 110, - 200, - "ok", - vec![("iii.function.kind", "internal")], - ); - let leaf = make_span( - "t", - "leaf", - Some("steer"), - "models::get", - "models", - 120, - 480, - "ok", - vec![], - ); - - let full = vec![steering, empty_wrapper, leaf]; - let arrived: HashSet = ["leaf".to_string()].into_iter().collect(); - - let sent = corrected_detail_spans(full, &arrived, &[]); - let ids: HashSet<&str> = sent.iter().map(|s| s.span_id.as_str()).collect(); - - assert!( - !ids.contains("wrap"), - "childless trigger wrapper must be pruned, not streamed" - ); - assert!(ids.contains("leaf")); - assert!(ids.contains("steer")); - let leaf = sent.iter().find(|s| s.span_id == "leaf").unwrap(); - assert_eq!(leaf.parent_span_id.as_deref(), Some("steer")); - } - - #[test] - fn test_corrected_detail_spans_applies_collapse_reparent() { - // call -> trigger (collapse rule) -> leaf. The collapsed wrapper is - // removed and the leaf reparents to `call` on the stream, just as in - // `traces::tree`. - let call = make_span( - "t", - "call", - None, - "call h::trigger", - "iii-test", - 100, - 500, - "ok", - vec![], - ); - let wrapper = make_span( - "t", - "trig", - Some("call"), - "trigger h::trigger", - "harness", - 110, - 480, - "ok", - vec![], - ); - let leaf = make_span( - "t", - "leaf", - Some("trig"), - "harness.h::trigger", - "harness", - 120, - 470, - "ok", - vec![], - ); - - let rules = compile_collapse_rules(&[config::SpanCollapseRule { - name: "trigger *".to_string(), - service: Some("harness".to_string()), - }]); - let full = vec![call, wrapper, leaf]; - let arrived: HashSet = ["leaf".to_string()].into_iter().collect(); - - let sent = corrected_detail_spans(full, &arrived, &rules); - let ids: HashSet<&str> = sent.iter().map(|s| s.span_id.as_str()).collect(); - - assert!( - !ids.contains("trig"), - "collapsed wrapper must not be streamed" - ); - assert!(ids.contains("call")); - let leaf = sent.iter().find(|s| s.span_id == "leaf").unwrap(); - assert_eq!(leaf.parent_span_id.as_deref(), Some("call")); - } - #[test] fn test_prune_empty_trigger_wrappers() { // writer -> state_triggers -> turn::on_approval: a trigger that RAN a fn. @@ -5349,7 +4897,11 @@ mod tests { assert!(t3_spans.is_empty()); } + // Serial: eviction protects dirty spans whenever the GLOBAL archive is + // attached (`evict_to_capacity` consults it), so this must not overlap + // the `#[serial]` archive tests. #[test] + #[serial] fn test_span_storage_eviction() { let storage = otel::InMemorySpanStorage::new(3); let span1 = make_span("t1", "s1", None, "first", "svc", 100, 200, "ok", vec![]); @@ -6279,7 +5831,11 @@ mod tests { // Span storage: eviction updates secondary index correctly // ========================================================================= + // Serial: eviction protects dirty spans whenever the GLOBAL archive is + // attached (`evict_to_capacity` consults it), so this must not overlap + // the `#[serial]` archive tests. #[test] + #[serial] fn test_span_storage_eviction_index_integrity() { let storage = otel::InMemorySpanStorage::new(2); diff --git a/engine/src/workers/observability/otel.rs b/engine/src/workers/observability/otel.rs index 77141fcb41..d6b91a1c3e 100644 --- a/engine/src/workers/observability/otel.rs +++ b/engine/src/workers/observability/otel.rs @@ -404,7 +404,7 @@ pub struct StoredSpan { /// True while the span is in progress — a live snapshot taken by /// `LiveSpanProcessor::on_start`, replaced in place by the final span when /// it closes (`InMemorySpanStorage::add_spans`). Pending spans exist ONLY - /// in the in-memory store and the `iii:devtools:*` streams; they are never + /// in the in-memory store (and the query views over it); they are never /// exported via OTLP, where `end_time_unix_nano` is semantically required. /// By convention `end_time_unix_nano == 0` while pending. #[serde(default, skip_serializing_if = "std::ops::Not::not")] diff --git a/engine/src/workers/rest_api/views.rs b/engine/src/workers/rest_api/views.rs index 3c895f804b..19e21ef697 100644 --- a/engine/src/workers/rest_api/views.rs +++ b/engine/src/workers/rest_api/views.rs @@ -342,6 +342,23 @@ pub async fn dynamic_handler( .and_then(|v| v.to_str().ok()) .map(|s| s.to_string()); + // Resolve the route BEFORE creating the span: the function kind must be + // on the span from its first (pending) snapshot — live views and the + // trace-trigger subscriber see spans on START, and a kind recorded only + // later inside the handler leaves the pending snapshot classified as + // user work (an engine-internal `POST _console/*` would list as a user + // trace and re-arm the trace tick it was caused by). + let function_kind = api_handler + .get_router(method.as_str(), ®istered_path) + .map(|m| { + if m.function_id.starts_with("engine::") { + "internal" + } else { + "user" + } + }) + .unwrap_or("user"); + let span = tracing::info_span!( "HTTP", otel.name = %format!("{} {}", method, registered_path), @@ -358,7 +375,7 @@ pub async fn dynamic_handler( "http.request.header.content_type" = %content_type, "http.request.body.size" = %request_body_size, "http.response.status_code" = tracing::field::Empty, - "iii.function.kind" = tracing::field::Empty, + "iii.function.kind" = function_kind, ) .with_parent_headers(tp.as_deref(), ts.as_deref(), bg.as_deref()); @@ -386,12 +403,6 @@ pub async fn dynamic_handler( namespace, } = router_match; - let function_kind = if function_id.starts_with("engine::") { - "internal" - } else { - "user" - }; - tracing::Span::current().record("iii.function.kind", function_kind); // Global middleware (from rest_api_config, sorted by priority at config load time) // These run before channel creation, so on short-circuit we return directly. diff --git a/engine/src/workers/stream/stream.rs b/engine/src/workers/stream/stream.rs index 4c966d63f7..548db61c75 100644 --- a/engine/src/workers/stream/stream.rs +++ b/engine/src/workers/stream/stream.rs @@ -862,14 +862,15 @@ impl StreamWorker { return; } - // The observability pipeline must never observe itself: deliveries of - // the devtools span/log feeds (`iii:devtools:*` — the console's live - // trace streams) get NO eval span and NO trace context. A traced - // delivery re-enters the very feed it delivers — span stored → next - // coalesce window pushes it → new delivery spans → stored → … — an - // endless loop that floods the span store (seen live: `stream_triggers` - // + `call iii::console::all_spans::*` dominating storage). With an - // empty ambient context, `Engine::call_with_metadata` injects no + // The observability pipeline must never observe itself: deliveries on + // devtools streams (`iii:devtools:*`, e.g. the console's state feed) + // get NO eval span and NO trace context. A traced delivery of + // observability-derived data re-enters the span store it was derived + // from — span stored → next push → new delivery spans → stored → … — + // an endless loop that floods storage (seen live with the since- + // removed trace feeds: `stream_triggers` + `call + // iii::console::all_spans::*` dominating storage). With an empty + // ambient context, `Engine::call_with_metadata` injects no // traceparent, so the consumer-callback invocations emit no spans // either (`telemetry::should_suppress_invocation_span`). let observability_feed = event_stream_name.starts_with("iii:devtools:");