diff --git a/.github/workflows/rust.yml b/.github/workflows/rust.yml index e71c3e67..ec70cad7 100644 --- a/.github/workflows/rust.yml +++ b/.github/workflows/rust.yml @@ -84,6 +84,14 @@ jobs: - name: Test agentic CLI end to end run: python3 scripts/tests/agentic-cli-e2e-test.py + - name: Test the telemetry smoke checker + run: python3 -m unittest discover -s scripts/tests -p test_otel_fixtures.py + + - name: Smoke-test telemetry through the local Collector + run: | + docker compose -f deploy/otel/docker-compose.yaml up -d + scripts/tests/otel-smoke.sh + embedded-code-interpreter: name: Embedded code interpreter runs-on: ubuntu-latest diff --git a/.rust-file-sizes.json b/.rust-file-sizes.json index f65f7df8..8d0f517c 100644 --- a/.rust-file-sizes.json +++ b/.rust-file-sizes.json @@ -28,6 +28,10 @@ "limit": 518, "reason": "Code-interpreter done-only ID backfill remains in the shared output-item slot validation path." }, + "crates/agentic-server-core/src/executor/engine/multi_agent_tests.rs": { + "limit": 501, + "reason": "Declares the multi-agent execution-metrics test module (multi_agent_tests/metrics.rs). The module tree reached the 500-line limit with #432; the tests themselves live in the child file." + }, "crates/agentic-server-core/src/tool/registry.rs": { "limit": 545, "reason": "The web_fetch executor binds through the existing registry validation and executor registration flow, like the code interpreter." diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index 6a88863b..104d2d05 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -828,6 +828,18 @@ The boundary contract is one owner and one path per concern: - Delivery consumes translated frames and provides ordered, awaited client emission across inference rounds. +Telemetry follows the same owners (`executor/telemetry/`; see +[Observability](docs/deploying/observability.md)). The `ExecutionSpan` guard finalizes +the `agentic.execute` span and the execution metrics together, exactly once, from `Drop`. +Instruments come from `ExecutorMetrics` on `ExecutionContext`. The first-data timings +share an `ExecutionClock`. The pipeline entry marks the first upstream line; multi-agent +rounds run on their own pipelines, which share the execution's clock. The client-facing +stream marks the first event and first output-text delta it yields to the transport, and +its `InstrumentedStream` wrapper measures delivery wait. For retained (WebSocket) +responses that stream is the event stream `ResponseEventSink::stream` returns. Stage timers wrap +the code that owns each stage. A refactor that moves one of these boundaries must move its +mark with it rather than add a second one. + #### `accumulator/` — typed response assembly `ResponseAccumulator` owns validation, response lifecycle, typed output slots, delta diff --git a/crates/agentic-server-core/src/executor/compaction.rs b/crates/agentic-server-core/src/executor/compaction.rs index 8f189756..c715edd9 100644 --- a/crates/agentic-server-core/src/executor/compaction.rs +++ b/crates/agentic-server-core/src/executor/compaction.rs @@ -4,6 +4,8 @@ pub(crate) use estimate::{estimate_history_tokens, estimate_input_tokens}; mod context; mod summary; +use super::telemetry::FailureCategory; +use super::telemetry::metrics::Stage; use super::telemetry::stages::CompactionTrigger; use context::item_has_meaningful_context; use summary::completed_summary_text; @@ -122,6 +124,18 @@ async fn compact_items_with_trigger( exec_ctx: &ExecutionContext, auth: Option<&str>, trigger: CompactionTrigger, +) -> ExecutorResult<(Vec, ResponseUsage, Option)> { + let timer = exec_ctx.metrics.stage(Stage::Compaction); + let summarized = summarize_items(request, input, exec_ctx, auth).await; + timer.finish_result(&summarized); + summarized +} + +async fn summarize_items( + request: &RequestPayload, + input: ResponsesInput, + exec_ctx: &ExecutionContext, + auth: Option<&str>, ) -> ExecutorResult<(Vec, ResponseUsage, Option)> { let original_items = Vec::from(input); if !original_items.iter().any(item_has_meaningful_context) { @@ -167,6 +181,7 @@ async fn compact_items_with_trigger( let mut agent = AgentPipeline::new(ctx, None, StreamRelay::detached()); let response = fetch_blocking_payload(&mut agent, exec_ctx, auth, &crate::tool::ToolRegistry::default(), None).await?; + exec_ctx.metrics.record_response_usage(response.usage.as_ref()); let summary = completed_summary_text(&response)?; Ok(( @@ -293,6 +308,7 @@ pub async fn compact_response( let response_id = ctx.response_id.clone(); ctx.new_input_items.clone_from(&output); + let timer = exec_ctx.metrics.stage(Stage::Persist); match persist_prepared_turn( ctx, tool_search_metadata, @@ -303,8 +319,13 @@ pub async fn compact_response( ) .await { - Ok(()) | Err(ExecutorError::Storage(crate::StorageError::NotConfigured)) => {} - Err(error) => return Err(error), + Ok(()) => timer.finish(None), + // Without storage nothing was written, so there is no stage to time. + Err(ExecutorError::Storage(crate::StorageError::NotConfigured)) => timer.discard(), + Err(error) => { + timer.finish(Some(FailureCategory::from(&error))); + return Err(error); + } } Ok(CompactedResponse { diff --git a/crates/agentic-server-core/src/executor/engine.rs b/crates/agentic-server-core/src/executor/engine.rs index 3e48d50d..11c945ae 100644 --- a/crates/agentic-server-core/src/executor/engine.rs +++ b/crates/agentic-server-core/src/executor/engine.rs @@ -32,6 +32,8 @@ use crate::executor::request::{ExecutionContext, RequestContext}; use crate::executor::response_budget::ExecutorResponseBudget; #[cfg(test)] use crate::executor::response_budget::MAX_EXECUTOR_RESPONSE_BYTES; +use crate::executor::telemetry::Api; +use crate::executor::telemetry::metrics::RoundCounter; use crate::tool::{ToolSearchMetadata, ToolSearchState}; use crate::types::io::{InputItem, OutputItem, ResponseUsage, ResponsesInput}; #[cfg(test)] @@ -127,6 +129,7 @@ struct SingleAgentRun<'a> { response_budget: ExecutorResponseBudget, output: Vec, usage: Option, + rounds: RoundCounter, } impl<'a> SingleAgentRun<'a> { @@ -139,6 +142,7 @@ impl<'a> SingleAgentRun<'a> { response_budget, output, usage: None, + rounds: exec_ctx.metrics.rounds(Api::Responses), }) } @@ -148,6 +152,7 @@ impl<'a> SingleAgentRun<'a> { stream_upstream: bool, ) -> ExecutorResult<(ResponsePayload, Option)> { loop { + self.rounds.begin_round(); let RoundResult { mut payload, decision } = self .root .run_round(self.output.len(), auth, stream_upstream, &self.response_budget) @@ -249,7 +254,15 @@ async fn run_blocking( let ch = exec_ctx.conv_handler.clone(); let rh = exec_ctx.resp_handler.clone(); - Box::pin(persist_if_needed(payload.clone(), ctx, tool_search_metadata, ch, rh)).await?; + Box::pin(persist_if_needed( + payload.clone(), + ctx, + tool_search_metadata, + ch, + rh, + &exec_ctx.metrics, + )) + .await?; Ok(payload) } diff --git a/crates/agentic-server-core/src/executor/engine/agent_turn.rs b/crates/agentic-server-core/src/executor/engine/agent_turn.rs index 64f2ed7b..68405b27 100644 --- a/crates/agentic-server-core/src/executor/engine/agent_turn.rs +++ b/crates/agentic-server-core/src/executor/engine/agent_turn.rs @@ -23,6 +23,7 @@ use crate::executor::rehydrate::prepare_reasoning_for_vllm; use crate::executor::relay::Release; use crate::executor::request::{ExecutionContext, RequestContext}; use crate::executor::response_budget::ExecutorResponseBudget; +use crate::executor::telemetry::metrics::Stage; use crate::executor::upstream::{fetch_blocking_payload, fetch_stream_payload}; use crate::tool::{ToolRegistry, mcp, record_discovered_mcp_tools, responses_declarations}; use crate::types::io::{InputItem, OutputItem, ResponsesInput, ToolChoice}; @@ -287,8 +288,9 @@ impl<'a> AgentTurn<'a> { compaction_usage.is_some(), )?; let round_span = crate::executor::telemetry::stages::inference_round(round); - let mut payload = if stream_upstream { - let payload = fetch_stream_payload( + let timer = self.exec_ctx.metrics.stage(Stage::Inference); + let fetched = if stream_upstream { + fetch_stream_payload( self.pipeline, self.exec_ctx, auth, @@ -297,11 +299,7 @@ impl<'a> AgentTurn<'a> { response_budget, ) .instrument(round_span) - .await?; - if round == 0 { - self.registry.clear_mcp_list_tool_items(); - } - payload + .await } else { fetch_blocking_payload( self.pipeline, @@ -311,8 +309,16 @@ impl<'a> AgentTurn<'a> { Some(response_budget), ) .instrument(round_span) - .await? + .await }; + timer.finish_result(&fetched); + let mut payload = fetched?; + if stream_upstream && round == 0 { + self.registry.clear_mcp_list_tool_items(); + } + // Only what this round's upstream response reported; an absent + // `usage` records nothing. + self.exec_ctx.metrics.record_response_usage(payload.usage.as_ref()); let mut round_usage = compaction_usage; accumulate_usage(&mut round_usage, payload.usage.take()); payload.usage = round_usage; @@ -404,14 +410,13 @@ impl<'a> AgentTurn<'a> { output_offset: usize, response_budget: &ExecutorResponseBudget, ) -> ExecutorResult> { - let policy = self.exec_ctx.gateway_scheduler_policy.clone(); let (ctx, relay) = self.pipeline.parts_mut(); if !relay.has_deferred() { return execute_and_emit_output_calls( output_items, &self.registry, output_offset, - policy, + self.exec_ctx, response_budget, &mut self.tool_call_budget, relay, @@ -423,9 +428,10 @@ impl<'a> AgentTurn<'a> { output_items, &self.registry, output_offset, - policy, + self.exec_ctx.gateway_scheduler_policy.clone(), &mut self.tool_call_budget, - ); + ) + .with_metrics(&self.exec_ctx.metrics); let initial_event_run_len = scheduler.initial_event_run_len(output_items, &self.registry); emit_gateway_start_events(scheduler.event_plans().take(initial_event_run_len), relay).await?; diff --git a/crates/agentic-server-core/src/executor/engine/execute.rs b/crates/agentic-server-core/src/executor/engine/execute.rs index 422a5b3c..1462c79f 100644 --- a/crates/agentic-server-core/src/executor/engine/execute.rs +++ b/crates/agentic-server-core/src/executor/engine/execute.rs @@ -119,7 +119,7 @@ impl ExecuteRequest { let mut execution = self .execution .take() - .unwrap_or_else(|| ExecutionSpan::start(Api::Responses, Route::Executor, true)); + .unwrap_or_else(|| ExecutionSpan::start(Api::Responses, Route::Executor, true, &self.exec_ctx.metrics)); let limit = self.effective_max_stream_event_bytes(); let prepared = if self.control.is_some() { Err(ExecutorError::InvalidRequest( @@ -155,10 +155,14 @@ impl ExecuteRequest { /// # Errors /// Returns [`ExecutorError`] if rehydration or (non-streaming) LLM inference fails. pub async fn run(mut self) -> ExecutorResult> { - let execution = self - .execution - .take() - .unwrap_or_else(|| ExecutionSpan::start(Api::Responses, Route::Executor, self.payload.stream)); + let execution = self.execution.take().unwrap_or_else(|| { + ExecutionSpan::start( + Api::Responses, + Route::Executor, + self.payload.stream, + &self.exec_ctx.metrics, + ) + }); let span = execution.span().clone(); Box::pin(self.run_traced(execution)).instrument(span).await } diff --git a/crates/agentic-server-core/src/executor/engine/multi_agent.rs b/crates/agentic-server-core/src/executor/engine/multi_agent.rs index 3cb22d80..cd14b81d 100644 --- a/crates/agentic-server-core/src/executor/engine/multi_agent.rs +++ b/crates/agentic-server-core/src/executor/engine/multi_agent.rs @@ -32,6 +32,10 @@ use crate::executor::{ relay::{AgentFrame, AgentRoundId}, request::ExecutionContext, response_budget::ExecutorResponseBudget, + telemetry::{ + Api, + metrics::{ExecutionClock, RoundCounter}, + }, }; use crate::tool::ToolSearchState; use crate::types::{ @@ -89,6 +93,10 @@ pub(super) struct MultiAgentRun { sealer: TranscriptSealer, payload: ResponsePayload, rounds: usize, + /// Every agent's upstream rounds, recorded once for the execution. + round_counter: RoundCounter, + /// The execution's timing state, shared with each round's pipeline. + clock: Option, max_retained_bytes: usize, frame_sender: mpsc::Sender, frames: mpsc::Receiver, @@ -173,6 +181,8 @@ impl MultiAgentRun { sealer: TranscriptSealer::new()?, payload, rounds: 0, + round_counter: exec.metrics.rounds(Api::Responses), + clock: pipeline.execution_clock().cloned(), max_retained_bytes: exec.responses_config.max_retained_bytes, }) } diff --git a/crates/agentic-server-core/src/executor/engine/multi_agent/rounds.rs b/crates/agentic-server-core/src/executor/engine/multi_agent/rounds.rs index a293c34d..77e990a9 100644 --- a/crates/agentic-server-core/src/executor/engine/multi_agent/rounds.rs +++ b/crates/agentic-server-core/src/executor/engine/multi_agent/rounds.rs @@ -149,6 +149,9 @@ impl MultiAgentRun { StreamRelay::detached() }; let mut agent = AgentPipeline::new(ctx, tool_search, relay); + if let Some(clock) = &self.clock { + agent.set_execution_clock(clock.clone()); + } agent.set_agent_guidance(self.round_guidance(turn)); let mut execution = context.execution.clone(); let source = AgentRoundId { @@ -181,6 +184,7 @@ impl MultiAgentRun { .set_phase(turn, AgentPhase::Inferring) .map_err(registry_error)?; self.rounds += 1; + self.round_counter.begin_round(); Ok(()) } diff --git a/crates/agentic-server-core/src/executor/engine/multi_agent_tests.rs b/crates/agentic-server-core/src/executor/engine/multi_agent_tests.rs index d696a291..380976f7 100644 --- a/crates/agentic-server-core/src/executor/engine/multi_agent_tests.rs +++ b/crates/agentic-server-core/src/executor/engine/multi_agent_tests.rs @@ -6,6 +6,8 @@ mod client_tools; mod explicit_compaction; #[path = "multi_agent_tests/live_control.rs"] mod live_control; +#[path = "multi_agent_tests/metrics.rs"] +mod metrics; #[path = "multi_agent_tests/root_completion.rs"] mod root_completion; #[path = "multi_agent_tests/service_tier.rs"] diff --git a/crates/agentic-server-core/src/executor/engine/multi_agent_tests/metrics.rs b/crates/agentic-server-core/src/executor/engine/multi_agent_tests/metrics.rs new file mode 100644 index 00000000..9e452ab8 --- /dev/null +++ b/crates/agentic-server-core/src/executor/engine/multi_agent_tests/metrics.rs @@ -0,0 +1,97 @@ +//! Execution metrics across a multi-agent response. +use super::*; +use opentelemetry::KeyValue; +use opentelemetry::metrics::MeterProvider as _; +use opentelemetry_sdk::metrics::data::{ + AggregatedMetrics, HistogramDataPoint, MetricData, ResourceMetrics, ScopeMetrics, +}; +use opentelemetry_sdk::metrics::{InMemoryMetricExporter, PeriodicReader, SdkMeterProvider}; + +fn has_attribute<'a>(mut attributes: impl Iterator, filter: Option<(&str, &str)>) -> bool { + filter.is_none_or(|(key, value)| attributes.any(|kv| kv.key.as_str() == key && kv.value.to_string() == value)) +} + +/// Number of samples a histogram recorded, optionally filtered by one attribute. +fn samples(export: &ResourceMetrics, name: &str, filter: Option<(&str, &str)>) -> u64 { + let mut count = 0; + for metric in export.scope_metrics().flat_map(ScopeMetrics::metrics) { + if metric.name() != name { + continue; + } + count += match metric.data() { + AggregatedMetrics::U64(MetricData::Histogram(data)) => data + .data_points() + .filter(|point| has_attribute(point.attributes(), filter)) + .map(HistogramDataPoint::count) + .sum::(), + AggregatedMetrics::F64(MetricData::Histogram(data)) => data + .data_points() + .filter(|point| has_attribute(point.attributes(), filter)) + .map(HistogramDataPoint::count) + .sum::(), + other => panic!("{name}: unexpected aggregation {other:?}"), + }; + } + count +} + +/// Sum of an integer histogram's samples. +fn int_sum(export: &ResourceMetrics, name: &str) -> u64 { + export + .scope_metrics() + .flat_map(ScopeMetrics::metrics) + .filter(|metric| metric.name() == name) + .map(|metric| match metric.data() { + AggregatedMetrics::U64(MetricData::Histogram(data)) => { + data.data_points().map(HistogramDataPoint::sum).sum::() + } + other => panic!("{name}: unexpected aggregation {other:?}"), + }) + .sum() +} + +/// One multi-agent execution records one `agentic.inference.rounds` sample +/// covering every agent's rounds, and times its first upstream data even +/// though each round runs on its own pipeline. +#[tokio::test] +async fn multi_agent_execution_records_rounds_and_first_data_once() { + let exporter = InMemoryMetricExporter::default(); + let provider = SdkMeterProvider::builder() + .with_reader(PeriodicReader::builder(exporter.clone()).build()) + .build(); + let (exec, server) = setup().await; + let metrics = crate::executor::telemetry::ExecutorMetrics::new(&provider.meter("agentic_core")); + let exec = Arc::new(ExecutionContext::clone(&exec).with_metrics(metrics)); + let request = RequestPayload { + model: "test".into(), + store: true, + stream: true, + input: ResponsesInput::Text("Compare proposals".into()), + multi_agent: Some(MultiAgentConfig { + enabled: true, + max_concurrent_subagents: Some(2), + }), + ..Default::default() + }; + let result = tokio::time::timeout(Duration::from_secs(15), response(request, exec)).await; + server.abort(); + assert_eq!(result.unwrap().status, "completed"); + + provider.force_flush().unwrap(); + let exports = exporter.get_finished_metrics().unwrap(); + let export = exports.last().expect("an export"); + let rounds = int_sum(export, "agentic.inference.rounds"); + assert_eq!( + samples(export, "agentic.inference.rounds", None), + 1, + "one rounds sample for the whole execution" + ); + assert_eq!( + rounds, + samples(export, "agentic.stage.duration", Some(("agentic.stage", "inference"))), + "every agent's rounds are counted" + ); + assert!(rounds >= 3, "the root and both children ran: {rounds}"); + assert_eq!(samples(export, "agentic.time_to_first_upstream_data", None), 1); + let _ = provider.shutdown(); +} diff --git a/crates/agentic-server-core/src/executor/engine/retained.rs b/crates/agentic-server-core/src/executor/engine/retained.rs index 122c04b8..e969a757 100644 --- a/crates/agentic-server-core/src/executor/engine/retained.rs +++ b/crates/agentic-server-core/src/executor/engine/retained.rs @@ -11,7 +11,7 @@ use crate::executor::{ relay::{RelayLimits, StreamRelay}, request::{ExecutionContext, RequestContext}, response_events::{ResponseCommitState, ResponseEventSink}, - telemetry::ExecutionSpan, + telemetry::{ExecutionSpan, InstrumentedStream}, }; use crate::tool::ToolSearchState; use std::{num::NonZeroUsize, sync::Arc}; @@ -90,6 +90,8 @@ pub(super) fn start( let sink = ResponseEventSink::new(sender, max_bytes); let relay = StreamRelay::response(sink.clone(), RelayLimits::with_event_bytes(max_bytes)); let mut pipeline = AgentPipeline::new(ctx, tools, relay); + let clock = execution.clock().clone(); + pipeline.set_execution_clock(clock.clone()); let control = if pipeline .request .enriched_request @@ -110,6 +112,7 @@ pub(super) fn start( let worker_cancel = cancellation.clone(); let worker_sink = sink.clone(); let span = execution.span().clone(); + let events_span = span.clone(); let task = tokio::spawn(async move { let result = Box::pin(async { // The multi-agent coordinator handles cancellation by joining its children. @@ -128,7 +131,7 @@ pub(super) fn start( tokio::select! { biased; () = worker_cancel.cancelled() => return Err(ExecutorError::StreamError("response cancelled before commit".into())), - result = persist_if_needed(payload, ctx, metadata, exec.conv_handler.clone(), exec.resp_handler.clone()) => result?, + result = persist_if_needed(payload, ctx, metadata, exec.conv_handler.clone(), exec.resp_handler.clone(), &exec.metrics) => result?, } tokio::select! { () = worker_cancel.cancelled() => return Err(ExecutorError::StreamError("response delivery cancelled".into())), @@ -168,7 +171,11 @@ pub(super) fn start( } result }.instrument(span)); - let events = ResponseEventSink::stream(receiver); + let events = Box::pin(InstrumentedStream::delivering( + ResponseEventSink::stream(receiver, Some(clock.clone())), + events_span, + clock, + )); let owner_sink = sink.clone(); RunningResponse { response_id, diff --git a/crates/agentic-server-core/src/executor/engine/streaming.rs b/crates/agentic-server-core/src/executor/engine/streaming.rs index a87c3e84..8a1a91fd 100644 --- a/crates/agentic-server-core/src/executor/engine/streaming.rs +++ b/crates/agentic-server-core/src/executor/engine/streaming.rs @@ -11,6 +11,7 @@ use crate::executor::persist::persist_if_needed; use crate::executor::pipeline::AgentPipeline; use crate::executor::relay::{RelayLimits, StreamRelay}; use crate::executor::request::{ExecutionContext, RequestContext}; +use crate::executor::telemetry::metrics::ExecutionClock; use crate::executor::telemetry::{ExecutionSpan, InstrumentedStream}; use crate::tool::{ToolSearchMetadata, ToolSearchState}; use crate::types::request_response::ResponsePayload; @@ -32,6 +33,10 @@ use tokio::sync::mpsc; /// into the stream so the span stays open, and is entered on every poll, /// until the terminal frame has been yielded or the stream is dropped. The /// stream owns and polls orchestration, so its stages run inside that span. +/// +/// The loop below is the client relay: every semantic event is handed to the +/// transport here, so this is where the first-event and first-text timings +/// are taken. The pipeline takes the first-upstream-data timing. /// Dropping the stream drops orchestration. For a multi-agent response that /// includes its `RunOwner`, which aborts round tasks without joining them. pub(super) fn run_stream( @@ -44,6 +49,8 @@ pub(super) fn run_stream( control: Option, ) -> BoxStream { let span = execution.span().clone(); + let clock = execution.clock().clone(); + let relay_clock = clock.clone(); let frames: BoxStream = Box::pin(stream! { let failure_context = StreamFailureContext::from(&ctx); let (event_tx, event_rx) = mpsc::channel(STREAM_EVENT_BUFFER); @@ -51,6 +58,7 @@ pub(super) fn run_stream( let relay = StreamRelay::client(event_tx, RelayLimits::with_event_bytes(max_stream_event_bytes)); let mut agent = AgentPipeline::new(ctx, tool_search_state, relay); agent.control = control; + agent.set_execution_clock(clock.clone()); let run = async move { let result = Box::pin(run_until_gateway_tools_complete( &mut agent, @@ -69,7 +77,7 @@ pub(super) fn run_stream( while let Some(event) = events.next().await { match event { ProducerEvent::Event(event) => { - if let Some(content) = consume_stream_event(event, &mut next_sequence_number) { + if let Some(content) = consume_stream_event(event, &mut next_sequence_number, &clock) { yield content; } } @@ -109,7 +117,7 @@ pub(super) fn run_stream( } } }); - Box::pin(InstrumentedStream::new(frames, span)) + Box::pin(InstrumentedStream::delivering(frames, span, relay_clock)) } fn failed_stream_chunk( @@ -154,7 +162,16 @@ async fn completed_stream_chunk( let status = payload.status.clone(); let ch = exec_ctx.conv_handler.clone(); let rh = exec_ctx.resp_handler.clone(); - match Box::pin(persist_if_needed(payload, ctx, tool_search_metadata, ch, rh)).await { + match Box::pin(persist_if_needed( + payload, + ctx, + tool_search_metadata, + ch, + rh, + &exec_ctx.metrics, + )) + .await + { Ok(()) => { execution.completed_with_status(&status); chunk @@ -222,9 +239,15 @@ impl StreamFailureContext { } } -pub(super) fn consume_stream_event(event: StreamEvent, next_sequence_number: &mut u64) -> Option { +/// Hand one relayed event to the transport. +pub(super) fn consume_stream_event( + event: StreamEvent, + next_sequence_number: &mut u64, + clock: &ExecutionClock, +) -> Option { match event { StreamEvent::Frame(frame) => { + clock.client_event(frame.text); *next_sequence_number = frame.sequence_number.saturating_add(1); Some(frame.content) } diff --git a/crates/agentic-server-core/src/executor/engine/streaming/producer/tests.rs b/crates/agentic-server-core/src/executor/engine/streaming/producer/tests.rs index ccdd3fc5..d6c0a835 100644 --- a/crates/agentic-server-core/src/executor/engine/streaming/producer/tests.rs +++ b/crates/agentic-server-core/src/executor/engine/streaming/producer/tests.rs @@ -18,6 +18,7 @@ fn event(sequence_number: u64) -> StreamEvent { StreamEvent::Frame(StreamFrame { content: "event".into(), sequence_number, + text: false, }) } diff --git a/crates/agentic-server-core/src/executor/gateway.rs b/crates/agentic-server-core/src/executor/gateway.rs index ca08b539..ebf56ec3 100644 --- a/crates/agentic-server-core/src/executor/gateway.rs +++ b/crates/agentic-server-core/src/executor/gateway.rs @@ -5,6 +5,7 @@ mod admission_tests; pub(super) mod history; mod lifecycle; mod policy; +mod timing; pub(crate) use admission::BuiltInToolCallBudget; pub(super) use history::{append_gateway_calls_to_new_input, append_output_items_to_input, append_tool_outputs}; @@ -23,7 +24,9 @@ use tokio::sync::Semaphore; use crate::executor::error::{ExecutorError, ExecutorResult}; use crate::executor::relay::StreamRelay; +use crate::executor::request::ExecutionContext; use crate::executor::response_budget::ExecutorResponseBudget; +use crate::executor::telemetry::metrics::ExecutorMetrics; use crate::tool::handler::MAX_GATEWAY_TOOL_OUTPUT_BYTES; use crate::tool::{GatewayBinding, ToolError, ToolOutput, ToolOwnership, ToolRegistry}; use crate::types::io::output::{FunctionToolCall, GatewayCallStatus}; @@ -107,6 +110,8 @@ pub(super) struct GatewayScheduler { omitted_items: Vec, policy: GatewaySchedulerPolicy, timeout: Duration, + /// Times each executed call as an `agentic.stage.duration` sample. + metrics: Option, } impl GatewayScheduler { @@ -206,6 +211,7 @@ impl GatewayScheduler { omitted_items, policy, timeout, + metrics: None, } } @@ -307,7 +313,7 @@ impl GatewayScheduler { response_budget: &ExecutorResponseBudget, ) -> ExecutorResult { let Some(limit) = plan.refused else { - return self.run_one(plan, execution_slots, response_budget).await; + return self.timed_run(plan, execution_slots, response_budget).await; }; let message = admission::limit_reached_message(limit); let omitted = plan.events.completed_output.is_none(); @@ -330,7 +336,7 @@ impl GatewayScheduler { plan: GatewayCallPlan, execution_slots: &Semaphore, response_budget: &ExecutorResponseBudget, - ) -> ExecutorResult { + ) -> ExecutorResult<(GatewayCallResult, GatewayCallStatus)> { let GatewayCallPlan { item_index, call, @@ -339,7 +345,8 @@ impl GatewayScheduler { } = plan; let GatewayExecutionPlan::Bound(binding) = execution else { let message = format!("gateway tool '{}' has no registered handler", call.name); - return unexecuted_result(item_index, &call, &message, None, false, response_budget); + return unexecuted_result(item_index, &call, &message, None, false, response_budget) + .map(|result| (result, GatewayCallStatus::Failed)); }; let _permit = match &binding.self_exclusion { @@ -379,12 +386,13 @@ impl GatewayScheduler { enforce_gateway_tool_output_size(output.output.len())?; response_budget.consume(output.output.len())?; let public_output = binding.public_output(&call, &output, status); - Ok(GatewayCallResult { + let result = GatewayCallResult { item_index, input_item: InputItem::FunctionCallOutput(output.into()), public_output, omitted: false, - }) + }; + Ok((result, status)) } } @@ -505,17 +513,21 @@ fn complete_gateway_event_plans(plans: &mut [Gatew } } +/// Plan, execute and relay one round's gateway calls under the execution +/// context's scheduler policy, timing each call with its metrics. pub(super) async fn execute_and_emit_output_calls( output_items: &[OutputItem], registry: &ToolRegistry, output_offset: usize, - policy: GatewaySchedulerPolicy, + exec_ctx: &ExecutionContext, response_budget: &ExecutorResponseBudget, tool_call_budget: &mut BuiltInToolCallBudget, relay: &mut StreamRelay, ) -> ExecutorResult> { + let policy = exec_ctx.gateway_scheduler_policy.clone(); let mut scheduler = - GatewayScheduler::plan_with_budget(output_items, registry, output_offset, policy, tool_call_budget); + GatewayScheduler::plan_with_budget(output_items, registry, output_offset, policy, tool_call_budget) + .with_metrics(&exec_ctx.metrics); emit_gateway_start_events(scheduler.event_plans(), relay).await?; let gateway_results = scheduler.execute_with_budget(response_budget).await?; emit_gateway_completed_events(&gateway_results, scheduler.event_plans(), relay).await?; @@ -1351,6 +1363,7 @@ mod tests { omitted_items: Vec::new(), policy: GatewaySchedulerPolicy::new(NonZeroUsize::new(2).expect("nonzero test limit")), timeout: std::time::Duration::ZERO, + metrics: None, }; let execution = tokio::spawn(async move { scheduler.execute().await }); @@ -1396,6 +1409,7 @@ mod tests { omitted_items: Vec::new(), policy: GatewaySchedulerPolicy::new(NonZeroUsize::new(2).expect("nonzero test limit")), timeout: std::time::Duration::ZERO, + metrics: None, }; let execution = tokio::spawn(async move { scheduler.execute().await }); diff --git a/crates/agentic-server-core/src/executor/gateway/timing.rs b/crates/agentic-server-core/src/executor/gateway/timing.rs new file mode 100644 index 00000000..eae2bf7a --- /dev/null +++ b/crates/agentic-server-core/src/executor/gateway/timing.rs @@ -0,0 +1,41 @@ +//! Stage timing for gateway-executed calls. + +use tokio::sync::Semaphore; + +use super::{GatewayCallPlan, GatewayCallResult, GatewayScheduler}; +use crate::executor::error::ExecutorResult; +use crate::executor::response_budget::ExecutorResponseBudget; +use crate::executor::telemetry::FailureCategory; +use crate::executor::telemetry::metrics::{ExecutorMetrics, Stage}; +use crate::types::io::output::GatewayCallStatus; + +impl GatewayScheduler { + /// Time each executed call as an `agentic.stage.duration` sample. + pub(in crate::executor) fn with_metrics(mut self, metrics: &ExecutorMetrics) -> Self { + self.metrics = Some(metrics.clone()); + self + } + + /// Time one executed call as a `tool` stage; a call that reports a failed + /// status is a failed stage even though the round continues. + pub(super) async fn timed_run( + &self, + plan: GatewayCallPlan, + execution_slots: &Semaphore, + response_budget: &ExecutorResponseBudget, + ) -> ExecutorResult { + let timer = self + .metrics + .as_ref() + .map(|metrics| metrics.stage(Stage::Tool(plan.tool_type))); + let result = self.run_one(plan, execution_slots, response_budget).await; + if let Some(timer) = timer { + timer.finish(match &result { + Ok((_, GatewayCallStatus::Failed)) => Some(FailureCategory::Tool), + Ok(_) => None, + Err(error) => Some(FailureCategory::from(error)), + }); + } + result.map(|(result, _)| result) + } +} diff --git a/crates/agentic-server-core/src/executor/gateway_accumulator.rs b/crates/agentic-server-core/src/executor/gateway_accumulator.rs index 685fa9d1..482ee524 100644 --- a/crates/agentic-server-core/src/executor/gateway_accumulator.rs +++ b/crates/agentic-server-core/src/executor/gateway_accumulator.rs @@ -24,6 +24,8 @@ pub(super) enum StreamEvent { pub(super) struct StreamFrame { pub(super) content: String, pub(super) sequence_number: u64, + /// An output-text delta, for the relay's first-text timing. + pub(super) text: bool, } #[cfg(test)] @@ -226,6 +228,7 @@ pub(super) async fn emit_sse_frame_limited( .send(StreamEvent::Frame(StreamFrame { content, sequence_number, + text: frame.event_type == SSEEventType::OutputTextDelta, })) .await .map_err(|_| ExecutorError::StreamError("stream receiver closed while emitting gateway event".to_owned())) diff --git a/crates/agentic-server-core/src/executor/messages_loop.rs b/crates/agentic-server-core/src/executor/messages_loop.rs index 85543a6b..da80c803 100644 --- a/crates/agentic-server-core/src/executor/messages_loop.rs +++ b/crates/agentic-server-core/src/executor/messages_loop.rs @@ -23,6 +23,7 @@ use crate::executor::messages_context::MessagesRequestContext; use crate::executor::messages_tools::{GatewayToolUse, execute_gateway_calls, request_gateway_map}; use crate::executor::messages_usage::MessagesUsageTotals; use crate::executor::request::ExecutionContext; +use crate::executor::telemetry::metrics::{ExecutorMetrics, Stage}; use crate::executor::telemetry::{Api, ExecutionSpan, FailureCategory, Route}; use crate::tool::ToolRegistry; use crate::types::messages::tool_seam; @@ -85,7 +86,7 @@ pub async fn run_messages_loop( exec_ctx: &ExecutionContext, upstream: &MessagesUpstream, ) -> ExecutorResult> { - let mut execution = ExecutionSpan::start(Api::Messages, Route::Executor, false); + let mut execution = ExecutionSpan::start(Api::Messages, Route::Executor, false, &exec_ctx.metrics); let span = execution.span().clone(); let result = run_messages_loop_traced(ctx, registry, exec_ctx, upstream, &mut execution) .instrument(span) @@ -117,10 +118,13 @@ async fn run_messages_loop_traced( // Gateway ownership is request-scoped: the operator aliases plus the // gateway tools this request's registry resolved. let gateway_map = request_gateway_map(&exec_ctx.messages_gateway_tools, registry); + let mut rounds = exec_ctx.metrics.rounds(Api::Messages); for round in 0..MAX_GATEWAY_TOOL_ROUNDS { let body = ctx.upstream_body()?; - let (resp_text, response_headers) = fetch_response_json_with_headers( + rounds.begin_round(); + let timer = exec_ctx.metrics.stage(Stage::Inference); + let fetched = fetch_response_json_with_headers( body, &upstream.url, &exec_ctx.client, @@ -128,8 +132,11 @@ async fn run_messages_loop_traced( exec_ctx.responses_config.max_upstream_json_bytes, ) .instrument(super::telemetry::stages::inference_round(round)) - .await?; + .await; + timer.finish_result(&fetched); + let (resp_text, response_headers) = fetched?; let message: Value = deserialize_from_str(&resp_text).map_err(ExecutorError::JsonError)?; + record_message_usage(&exec_ctx.metrics, message.get("usage")); // Any error body from upstream is surfaced verbatim (handler maps it to // the Anthropic error envelope). @@ -211,6 +218,15 @@ async fn run_messages_loop_traced( }) } +/// Record one upstream response's own `usage`, before any turn totals are +/// folded into it. +fn record_message_usage(metrics: &ExecutorMetrics, usage: Option<&Value>) { + let mut round = MessagesUsageTotals::default(); + round.observe(usage); + let (input, output) = round.round_tokens(); + metrics.record_token_usage(Api::Messages, input, output); +} + /// Return the terminal assistant message with the turn's complete `usage` and /// no gateway-owned `tool_use`. /// diff --git a/crates/agentic-server-core/src/executor/messages_stream.rs b/crates/agentic-server-core/src/executor/messages_stream.rs index 518fd4b5..c8e8f2bc 100644 --- a/crates/agentic-server-core/src/executor/messages_stream.rs +++ b/crates/agentic-server-core/src/executor/messages_stream.rs @@ -36,6 +36,7 @@ use crate::executor::messages_context::MessagesRequestContext; use crate::executor::messages_tools::request_gateway_map; use crate::executor::messages_usage::MessagesUsageTotals; use crate::executor::request::ExecutionContext; +use crate::executor::telemetry::metrics::{Stage, StageTimer}; use crate::executor::telemetry::{Api, ExecutionSpan, FailureCategory, InstrumentedStream, Route}; use crate::proxy::processed_response_headers; use crate::tool::ToolRegistry; @@ -58,52 +59,69 @@ pub async fn run_messages_stream( upstream: MessagesUpstream, ) -> ExecutorResult> { ctx.force_stream(true); - let mut execution = ExecutionSpan::start(Api::Messages, Route::Executor, true); + let mut execution = ExecutionSpan::start(Api::Messages, Route::Executor, true, &exec_ctx.metrics); let span = execution.span().clone(); - let first_round = span.in_scope(|| super::telemetry::stages::inference_round(0)); - let primed = prime_messages_stream(&ctx, &exec_ctx, &upstream) - .instrument(first_round.clone()) - .await; - let first_response = match primed { - Ok(first_response) => first_response, + // Send the first upstream request before the handler commits an HTTP 200, + // so initial vLLM errors retain their original status and body. + let opened = open_round(&ctx, &exec_ctx, &upstream, 0).instrument(span.clone()).await; + let first_round = match opened { + Ok(first_round) => first_round, Err(error) => { execution.failed(&error); execution.not_delivered(); return Err(error); } }; - let response_headers = processed_response_headers(first_response.headers()); - let body = messages_stream_body( - ctx, - registry, - exec_ctx, - upstream, - (first_response, first_round), - execution, - ); + let response_headers = processed_response_headers(first_round.response.headers()); + let clock = execution.clock().clone(); + let body = messages_stream_body(ctx, registry, exec_ctx, upstream, first_round, execution); Ok(MessagesResponse { - body: Box::pin(InstrumentedStream::new(body, span)), + body: Box::pin(InstrumentedStream::delivering(body, span, clock)), headers: response_headers, }) } /// Send the first upstream request before the handler commits an HTTP 200, so /// initial vLLM errors retain their original status and body. -async fn prime_messages_stream( +/// One upstream round whose response headers have arrived. +struct OpenRound { + response: reqwest::Response, + span: tracing::Span, + stage: StageTimer, +} + +/// Build and send one round's upstream request inside its +/// `agentic.inference_round` span; the round's stage timer keeps running +/// until its body has been read. +async fn open_round( ctx: &MessagesRequestContext, exec_ctx: &ExecutionContext, upstream: &MessagesUpstream, -) -> ExecutorResult { - let first_body = ctx.upstream_body()?; - send_request( - &exec_ctx.client, - upstream.url(), - first_body, - None, - Some(upstream.headers()), - exec_ctx.streaming_timeout, - ) - .await + round: usize, +) -> ExecutorResult { + let span = super::telemetry::stages::inference_round(round); + let stage = exec_ctx.metrics.stage(Stage::Inference); + let sent = async { + let body = ctx.upstream_body()?; + send_request( + &exec_ctx.client, + upstream.url(), + body, + None, + Some(upstream.headers()), + exec_ctx.streaming_timeout, + ) + .await + } + .instrument(span.clone()) + .await; + match sent { + Ok(response) => Ok(OpenRound { response, span, stage }), + Err(error) => { + stage.finish(Some(FailureCategory::from(&error))); + Err(error) + } + } } /// The client-facing frame stream. `execution` lives inside it: every exit @@ -114,7 +132,7 @@ fn messages_stream_body( registry: Arc, exec_ctx: Arc, upstream: MessagesUpstream, - first_response: (reqwest::Response, tracing::Span), + first_round: OpenRound, mut execution: ExecutionSpan, ) -> BoxStream { Box::pin(stream! { @@ -122,40 +140,23 @@ fn messages_stream_body( gateway_map: request_gateway_map(&exec_ctx.messages_gateway_tools, ®istry), ..Default::default() }; - let mut prepared_response = Some(first_response); + let mut prepared_response = Some(first_round); + let clock = execution.clock().clone(); + let mut rounds = exec_ctx.metrics.rounds(Api::Messages); for round in 0..MAX_GATEWAY_TOOL_ROUNDS { - let (response, round_span) = if let Some(response) = prepared_response.take() { - response - } else { - let round_span = super::telemetry::stages::inference_round(round); - let body = match ctx.upstream_body() { - Ok(b) => b, - Err(e) => { - execution.failed(&e); - execution.delivered(); - yield executor_error_sse(&e); - return; - } - }; - match send_request( - &exec_ctx.client, - upstream.url(), - body, - None, - Some(upstream.headers()), - exec_ctx.streaming_timeout, - ) - .instrument(round_span.clone()) - .await - { - Ok(response) => (response, round_span), - Err(e) => { - execution.failed(&e); - execution.delivered(); - yield executor_error_sse(&e); - return; - } + rounds.begin_round(); + let opened = match prepared_response.take() { + Some(opened) => Ok(opened), + None => open_round(&ctx, &exec_ctx, &upstream, round).await, + }; + let OpenRound { response, span: round_span, stage } = match opened { + Ok(opened) => opened, + Err(e) => { + execution.failed(&e); + execution.delivered(); + yield executor_error_sse(&e); + return; } }; let mut response_stream = InstrumentedStream::new(Box::pin(response_lines( @@ -169,16 +170,22 @@ fn messages_stream_body( let line = match line { Ok(l) => l, Err(e) => { + stage.finish(Some(FailureCategory::from(&e))); execution.failed(&e); execution.delivered(); yield error_sse(&e.to_string()); return; } }; - for out in acc.push(&line) { + clock.upstream_data(); + let frames = acc.push(&line); + let text = acc.pushed_text; + for out in frames { + clock.client_event(text); yield out; } if acc.has_error() { + stage.finish(Some(acc.failure_category())); execution.failed_with(acc.failure_category()); execution.delivered(); return; @@ -190,6 +197,9 @@ fn messages_stream_body( // Release an upstream body that can remain open after its terminal, // including before awaiting gateway tool execution for the next round. drop(response_stream); + stage.finish(None); + let (input_tokens, output_tokens) = acc.usage.round_tokens(); + exec_ctx.metrics.record_token_usage(Api::Messages, input_tokens, output_tokens); // Round finished. Continue only for a pure gateway-tool round; a // client-executed function tool makes the round terminal. @@ -239,6 +249,8 @@ enum RoundState { /// State machine that turns per-round Anthropic SSE into one client-visible /// message. Fed line-by-line via [`Self::push`]. +// Each flag is independent per-round or per-push state, not a mode. +#[allow(clippy::struct_excessive_bools)] #[derive(Default)] struct MessagesStreamAccumulator { message_started: bool, @@ -267,6 +279,8 @@ struct MessagesStreamAccumulator { round_state: RoundState, /// Every consumed round's terminal `usage`, reported once in the final `message_delta`. usage: MessagesUsageTotals, + /// The last pushed line was forwarded as an output-text delta. + pushed_text: bool, /// Operator-configured client-tool → gateway-executor aliases, so a client /// tool like Claude Code's `WebSearch` is classified gateway-owned (and /// suppressed) the same way the built-in `web_search` is. diff --git a/crates/agentic-server-core/src/executor/messages_stream/ingestion.rs b/crates/agentic-server-core/src/executor/messages_stream/ingestion.rs index 4c810c6c..910bba11 100644 --- a/crates/agentic-server-core/src/executor/messages_stream/ingestion.rs +++ b/crates/agentic-server-core/src/executor/messages_stream/ingestion.rs @@ -9,6 +9,7 @@ use crate::utils::common::deserialize_from_str; impl MessagesStreamAccumulator { /// Translate one upstream SSE line into zero or more client SSE lines. pub(super) fn push(&mut self, line: &str) -> Vec { + self.pushed_text = false; let ClassifiedSseLine::Data(data) = SseLine::parse(line) else { return Vec::new(); }; @@ -189,6 +190,7 @@ impl MessagesStreamAccumulator { return Vec::new(); }; event["index"] = Value::from(client_index); + self.pushed_text = event["delta"]["type"] == "text_delta"; vec![sse("content_block_delta", event)] } diff --git a/crates/agentic-server-core/src/executor/messages_usage.rs b/crates/agentic-server-core/src/executor/messages_usage.rs index 28086422..7d088ab3 100644 --- a/crates/agentic-server-core/src/executor/messages_usage.rs +++ b/crates/agentic-server-core/src/executor/messages_usage.rs @@ -55,6 +55,18 @@ impl MessagesUsageTotals { } } + /// The current round's prompt and completion token counts, for metrics. + /// The prompt count includes cache reads and writes, which Anthropic + /// reports apart from `input_tokens`; a count no counter reported is `None`. + pub(super) fn round_tokens(&self) -> (Option, Option) { + let [input, output, cache_creation, cache_read] = self.round; + let prompt = [input, cache_creation, cache_read] + .into_iter() + .flatten() + .reduce(u64::saturating_add); + (prompt, output) + } + /// Add the current round to the totals and start the next one. pub(super) fn commit(&mut self) { for (total, value) in self.committed.iter_mut().zip(std::mem::take(&mut self.round)) { diff --git a/crates/agentic-server-core/src/executor/persist.rs b/crates/agentic-server-core/src/executor/persist.rs index d5f30cbb..1067d9a1 100644 --- a/crates/agentic-server-core/src/executor/persist.rs +++ b/crates/agentic-server-core/src/executor/persist.rs @@ -9,6 +9,7 @@ use crate::executor::error::{ExecutorError, ExecutorResult}; use crate::executor::modes::{ConversationHandler, ResponseHandler}; use crate::executor::prepare::prepare_request_tools; use crate::executor::request::{ExecutionContext, RequestContext}; +use crate::executor::telemetry::metrics::{ExecutorMetrics, Stage}; use crate::storage::{InOutItem, ResponseMetadata}; use crate::tool::{ToolSearchMetadata, ToolSearchState}; use crate::types::event::ResponseStatus; @@ -28,24 +29,29 @@ pub(crate) fn should_persist(ctx: &RequestContext) -> bool { ctx.continuation.is_some() || ctx.original_request.store || ctx.original_request.conversation.is_some() } +/// Persist when the request asked for it; only an attempted write is timed +/// as a `persist` stage. pub(crate) async fn persist_if_needed( payload: ResponsePayload, ctx: RequestContext, tool_search_metadata: Option, conv_handler: ConversationHandler, resp_handler: ResponseHandler, + metrics: &ExecutorMetrics, ) -> ExecutorResult<()> { - if should_persist(&ctx) { - match persist_prepared_response(payload, ctx, tool_search_metadata, conv_handler, resp_handler).await { - Err(error @ (ExecutorError::Conflict(_) | ExecutorError::PayloadTooLarge(_))) => Err(error), - Err(source) => { - error!(error = ?source, "failed to persist response"); - Err(ExecutorError::Persistence(Box::new(source))) - } - Ok(()) => Ok(()), + if !should_persist(&ctx) { + return Ok(()); + } + let timer = metrics.stage(Stage::Persist); + let persisted = persist_prepared_response(payload, ctx, tool_search_metadata, conv_handler, resp_handler).await; + timer.finish_result(&persisted); + match persisted { + Err(error @ (ExecutorError::Conflict(_) | ExecutorError::PayloadTooLarge(_))) => Err(error), + Err(source) => { + error!(error = ?source, "failed to persist response"); + Err(ExecutorError::Persistence(Box::new(source))) } - } else { - Ok(()) + Ok(()) => Ok(()), } } @@ -222,6 +228,7 @@ pub async fn commit( None, exec_ctx.conv_handler.clone(), exec_ctx.resp_handler.clone(), + &exec_ctx.metrics, )) .await?; Ok(payload) diff --git a/crates/agentic-server-core/src/executor/pipeline.rs b/crates/agentic-server-core/src/executor/pipeline.rs index 5eb36857..a2bb376f 100644 --- a/crates/agentic-server-core/src/executor/pipeline.rs +++ b/crates/agentic-server-core/src/executor/pipeline.rs @@ -11,6 +11,7 @@ use crate::executor::multi_agent::RunControlReceiver; use crate::executor::relay::{AgentRoundId, StreamRelay}; use crate::executor::request::RequestContext; use crate::executor::response_budget::ExecutorResponseBudget; +use crate::executor::telemetry::metrics::ExecutionClock; use crate::executor::translate::{Translation, TranslationContext}; use crate::tool::{ToolRegistry, ToolSearchMetadata, ToolSearchState}; use crate::types::agent::AgentIdentity; @@ -30,9 +31,20 @@ pub(super) struct AgentPipeline { agent_guidance: Option, /// Set after a `max_tool_calls` refusal; later rounds omit gateway-executed tools. builtin_tools_withheld: bool, + /// Timing state of the execution this pipeline serves, when it streams. + clock: Option, } impl AgentPipeline { + /// Report the first upstream line of the execution's streamed bodies to `clock`. + pub(super) fn set_execution_clock(&mut self, clock: ExecutionClock) { + self.clock = Some(clock); + } + + pub(super) fn execution_clock(&self) -> Option<&ExecutionClock> { + self.clock.as_ref() + } + pub(super) fn set_agent_guidance(&mut self, guidance: InputMessage) { self.agent_guidance = Some(guidance); } @@ -84,6 +96,7 @@ impl AgentPipeline { agent_guidance: None, control: None, builtin_tools_withheld: false, + clock: None, } } @@ -171,7 +184,11 @@ impl AgentPipeline { self.begin_round(validation, context, budget)?; futures::pin_mut!(body); while let Some(line) = body.next().await { - let translation = self.push(SseLine::parse(&line?))?; + let line = line?; + if let Some(clock) = &self.clock { + clock.upstream_data(); + } + let translation = self.push(SseLine::parse(&line))?; self.relay.accept(translation, &self.request, registry).await?; } // Frames still deferred stay with the relay until the engine releases them diff --git a/crates/agentic-server-core/src/executor/rehydrate.rs b/crates/agentic-server-core/src/executor/rehydrate.rs index e424494e..6206b223 100644 --- a/crates/agentic-server-core/src/executor/rehydrate.rs +++ b/crates/agentic-server-core/src/executor/rehydrate.rs @@ -8,6 +8,7 @@ use crate::executor::error::{ExecutorError, ExecutorResult}; use crate::executor::multi_agent::{CheckpointLimits, ValidatedTreeCheckpoint}; use crate::executor::pending_calls::pending_calls; use crate::executor::request::{ExecutionContext, RequestContext}; +use crate::executor::telemetry::metrics::Stage; use crate::storage::{InOutItem, ResponseMetadata}; use crate::tool::ToolError; use crate::types::io::{ @@ -167,6 +168,18 @@ pub(crate) async fn rehydrate_with_continuation( request: RequestPayload, exec_ctx: &ExecutionContext, continuation: Option, +) -> ExecutorResult { + let timer = exec_ctx.metrics.stage(Stage::Rehydrate); + // Boxed so this wrapper does not hold the request payload twice. + let rehydrated = Box::pin(rehydrate_request(request, exec_ctx, continuation)).await; + timer.finish_result(&rehydrated); + rehydrated +} + +async fn rehydrate_request( + request: RequestPayload, + exec_ctx: &ExecutionContext, + continuation: Option, ) -> ExecutorResult { validate_multi_agent_request(&request)?; // Stored turns never supply `max_tool_calls`, so the request value is final here. diff --git a/crates/agentic-server-core/src/executor/request.rs b/crates/agentic-server-core/src/executor/request.rs index 8896d284..73f2c33b 100644 --- a/crates/agentic-server-core/src/executor/request.rs +++ b/crates/agentic-server-core/src/executor/request.rs @@ -7,6 +7,7 @@ use crate::error::Error; use crate::executor::gateway::GatewaySchedulerPolicy; use crate::executor::modes::{ConversationHandler, ResponseHandler}; use crate::executor::multi_agent::ValidatedTreeCheckpoint; +use crate::executor::telemetry::ExecutorMetrics; use crate::storage::backend::redact_database_urls; use crate::storage::{ ConversationStore, ConversationVersion, DatabaseBackend, ResponseStore, create_pool_with_schema_and_configs, @@ -92,6 +93,9 @@ pub struct ExecutionContext { /// Bounded-concurrency policy applied to gateway-owned calls in each round. pub(crate) gateway_scheduler_policy: GatewaySchedulerPolicy, pub responses_config: ResponsesConfig, + /// Execution, stage, token, and timing instruments. Defaults to the + /// globally registered meter provider at construction time. + pub metrics: ExecutorMetrics, storage_pool: Option>, } @@ -126,10 +130,19 @@ impl ExecutionContext { streaming_timeout: streaming_timeout_from_env(), gateway_scheduler_policy: GatewaySchedulerPolicy::default(), responses_config: ResponsesConfig::default(), + metrics: ExecutorMetrics::from_global(), storage_pool: None, } } + /// Record executor metrics with instruments from the embedding + /// application's meter instead of the global provider. + #[must_use] + pub fn with_metrics(mut self, metrics: ExecutorMetrics) -> Self { + self.metrics = metrics; + self + } + #[must_use] pub fn with_responses_config(mut self, responses_config: ResponsesConfig) -> Self { self.responses_config = responses_config; @@ -204,6 +217,7 @@ impl ExecutionContext { streaming_timeout: streaming_timeout_from_env(), gateway_scheduler_policy: GatewaySchedulerPolicy::new(cfg.tools.max_concurrent_gateway_calls), responses_config: cfg.responses, + metrics: ExecutorMetrics::from_global(), storage_pool: Some(pool), }) } diff --git a/crates/agentic-server-core/src/executor/response_events.rs b/crates/agentic-server-core/src/executor/response_events.rs index ac7fb3e3..1233440c 100644 --- a/crates/agentic-server-core/src/executor/response_events.rs +++ b/crates/agentic-server-core/src/executor/response_events.rs @@ -10,6 +10,7 @@ use crate::executor::gateway_accumulator::{ GatewayStreamAccumulator, StreamEvent, StreamFrame, checked_stream_event_limited, executor_error_frame, terminal_response_frame, }; +use crate::executor::telemetry::metrics::ExecutionClock; use crate::types::{injection::InjectionEvent, request_response::ResponsePayload}; use crate::utils::common::serialize_to_value; @@ -38,15 +39,22 @@ impl ResponseEventSink { pub fn channel(max_bytes: usize) -> (Self, BoxStream) { let (sender, receiver) = mpsc::channel(1); let sink = Self::new(sender, max_bytes); - let stream = Self::stream(receiver); + let stream = Self::stream(receiver, None); (sink, stream) } - pub(super) fn stream(receiver: mpsc::Receiver) -> BoxStream { - futures::stream::unfold(receiver, |mut receiver| async move { + /// Hand each frame to the adapter; with an execution `clock`, this is where + /// the first-event and first-text timings are taken. + pub(super) fn stream(receiver: mpsc::Receiver, clock: Option) -> BoxStream { + futures::stream::unfold((receiver, clock), |(mut receiver, clock)| async move { while let Some(event) = receiver.recv().await { match event { - StreamEvent::Frame(frame) => return Some((frame.content, receiver)), + StreamEvent::Frame(frame) => { + if let Some(clock) = &clock { + clock.client_event(frame.text); + } + return Some((frame.content, (receiver, clock))); + } StreamEvent::Flush(flushed) => { // A cancelled flush waiter does not cancel event delivery. let _ = flushed.send(()); @@ -137,6 +145,7 @@ impl ResponseEventSink { permit.send(StreamEvent::Frame(StreamFrame { content, sequence_number, + text: frame.event_type == SSEEventType::OutputTextDelta, })); *state = published; Ok(true) diff --git a/crates/agentic-server-core/src/executor/telemetry.rs b/crates/agentic-server-core/src/executor/telemetry.rs index b1117a8a..8111b755 100644 --- a/crates/agentic-server-core/src/executor/telemetry.rs +++ b/crates/agentic-server-core/src/executor/telemetry.rs @@ -18,24 +18,30 @@ //! Every attribute value is bounded: outcomes and failure categories are //! closed enums, and no request identifier, model name, prompt, or error //! message is recorded. +//! +//! The same guard records the execution metrics (see [`metrics`]), so they +//! are finalized exactly once on the same paths and do not depend on whether +//! the trace was sampled. use std::pin::Pin; use std::task::{Context, Poll}; +use std::time::Instant; use futures::Stream; use tracing::{Span, field, info_span}; use tracing_opentelemetry::OpenTelemetrySpanExt as _; use super::error::ExecutorError; +use metrics::{ATTR_DELIVERY_OUTCOME, ATTR_ERROR_TYPE, ATTR_EXECUTION_OUTCOME, ExecutionClock}; +pub mod metrics; pub(crate) mod stages; +pub use metrics::ExecutorMetrics; + /// Span name shared by every API and transport. pub const EXECUTE_SPAN_NAME: &str = "agentic.execute"; -const ATTR_EXECUTION_OUTCOME: &str = "agentic.execution.outcome"; -const ATTR_DELIVERY_OUTCOME: &str = "agentic.delivery.outcome"; -const ATTR_ERROR_TYPE: &str = "error.type"; const ATTR_OTEL_STATUS: &str = "otel.status_code"; /// Which public API the request arrived on. @@ -205,36 +211,53 @@ impl From<&ExecutorError> for FailureCategory { } } -/// The `agentic.execute` span plus the guard that finalizes its outcome. +/// The `agentic.execute` span plus the guard that finalizes its outcome and +/// records the execution metrics. /// /// Create it with [`ExecutionSpan::start`], run the request inside /// [`ExecutionSpan::span`] (via `Instrument`), state the outcome on the -/// paths that know it, and let `Drop` finalize the rest. +/// paths that know it, and let `Drop` finalize the rest. Creating the guard +/// counts the execution as active; dropping it records its count, duration, +/// and delivery outcome and releases the active count. #[derive(Debug)] pub struct ExecutionSpan { span: Span, execution: Option, + failure: Option, delivery: Option, + clock: ExecutionClock, } impl ExecutionSpan { /// Open the span as a child of whatever span is current. #[must_use] - pub fn start(api: Api, route: Route, stream: bool) -> Self { - Self::with_parent(api, route, stream, Span::current().id()) + pub fn start(api: Api, route: Route, stream: bool, metrics: &ExecutorMetrics) -> Self { + Self::with_parent(api, route, stream, metrics, Span::current().id()) } /// Start an independent execution trace linked to a long-lived session. #[must_use] - pub fn start_linked(api: Api, route: Route, stream: bool, link: opentelemetry::trace::SpanContext) -> Self { - let execution = Self::with_parent(api, route, stream, None); + pub fn start_linked( + api: Api, + route: Route, + stream: bool, + metrics: &ExecutorMetrics, + link: opentelemetry::trace::SpanContext, + ) -> Self { + let execution = Self::with_parent(api, route, stream, metrics, None); if link.is_valid() { execution.span.add_link(link); } execution } - fn with_parent(api: Api, route: Route, stream: bool, parent: Option) -> Self { + fn with_parent( + api: Api, + route: Route, + stream: bool, + metrics: &ExecutorMetrics, + parent: Option, + ) -> Self { // Field names must be literal here; the `ATTR_*` constants name the // same fields for `record` calls. let span = info_span!( @@ -252,7 +275,9 @@ impl ExecutionSpan { Self { span, execution: None, + failure: None, delivery: None, + clock: ExecutionClock::start(metrics.clone(), api, route, stream), } } @@ -262,6 +287,11 @@ impl ExecutionSpan { &self.span } + /// Timing state shared with the upstream reader and the client relay. + pub(crate) fn clock(&self) -> &ExecutionClock { + &self.clock + } + /// The execution reached a terminal state. pub fn completed(&mut self) { self.set_execution(ExecutionOutcome::Completed); @@ -301,6 +331,7 @@ impl ExecutionSpan { /// The execution failed for a reason that is not an [`ExecutorError`]. pub fn failed_with(&mut self, category: FailureCategory) { if self.set_execution(ExecutionOutcome::Failed) { + self.failure = Some(category); self.span.record(ATTR_ERROR_TYPE, category.as_str()); self.span.record(ATTR_OTEL_STATUS, "ERROR"); } @@ -351,14 +382,55 @@ impl ExecutionSpan { /// persistence after the last inference round, the outcome guard's `Drop` — /// is attributed to the request. `tracing`'s `Instrument` covers futures /// only; this is the stream equivalent. +/// +/// Built with [`InstrumentedStream::delivering`] it is also the client-facing +/// relay boundary: it measures how long the transport takes to ask for the +/// next frame after taking one, which is where a slow client's backpressure +/// shows up. pub struct InstrumentedStream { inner: S, span: Span, + delivery: Option, +} + +struct DeliveryTimer { + clock: ExecutionClock, + handed_at: Option, +} + +impl DeliveryTimer { + /// The transport asked for the next frame: add the wait since it took + /// the previous one. + fn resumed(&mut self) { + if let Some(handed_at) = self.handed_at.take() { + self.clock.transport_waited(handed_at.elapsed()); + } + } + + /// The transport took a frame. + fn handed(&mut self) { + self.clock.frame_handed(); + self.handed_at = Some(Instant::now()); + } } impl InstrumentedStream { pub fn new(inner: S, span: Span) -> Self { - Self { inner, span } + Self { + inner, + span, + delivery: None, + } + } + + /// The execution's client-facing frame stream, polled inside the + /// execution span. + pub(crate) fn delivering(inner: S, span: Span, clock: ExecutionClock) -> Self { + Self { + inner, + span, + delivery: Some(DeliveryTimer { clock, handed_at: None }), + } } } @@ -367,8 +439,17 @@ impl Stream for InstrumentedStream { fn poll_next(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll> { let this = self.get_mut(); + // Before polling: the outcome guard inside `inner` may finalize on + // this poll and must see the wait that led up to it. + if let Some(delivery) = &mut this.delivery { + delivery.resumed(); + } let _entered = this.span.enter(); - Pin::new(&mut this.inner).poll_next(cx) + let polled = Pin::new(&mut this.inner).poll_next(cx); + if let (Some(delivery), Poll::Ready(Some(_))) = (&mut this.delivery, &polled) { + delivery.handed(); + } + polled } fn size_hint(&self) -> (usize, Option) { @@ -392,6 +473,9 @@ impl Drop for ExecutionSpan { }; self.set_delivery(delivery); } + if let (Some(execution), Some(delivery)) = (self.execution, self.delivery) { + self.clock.finalize(execution, self.failure, delivery); + } } } @@ -476,7 +560,8 @@ mod tests { #[test] fn first_execution_outcome_wins() { - let mut execution = ExecutionSpan::start(Api::Responses, Route::Executor, true); + let mut execution = + ExecutionSpan::start(Api::Responses, Route::Executor, true, &ExecutorMetrics::from_global()); execution.failed_with(FailureCategory::Stream); execution.completed(); assert_eq!(execution.execution, Some(ExecutionOutcome::Failed)); @@ -484,7 +569,8 @@ mod tests { #[test] fn drop_defaults_to_cancelled_and_disconnected() { - let mut execution = ExecutionSpan::start(Api::Responses, Route::Executor, true); + let mut execution = + ExecutionSpan::start(Api::Responses, Route::Executor, true, &ExecutorMetrics::from_global()); assert_eq!(execution.execution, None); // Simulate `Drop` bookkeeping without consuming the value. execution.cancelled(); @@ -493,15 +579,18 @@ mod tests { #[test] fn incomplete_status_is_its_own_outcome() { - let mut execution = ExecutionSpan::start(Api::Responses, Route::Executor, false); + let mut execution = + ExecutionSpan::start(Api::Responses, Route::Executor, false, &ExecutorMetrics::from_global()); execution.completed_with_status("incomplete"); assert_eq!(execution.execution, Some(ExecutionOutcome::Incomplete)); - let mut execution = ExecutionSpan::start(Api::Messages, Route::Executor, false); + let mut execution = + ExecutionSpan::start(Api::Messages, Route::Executor, false, &ExecutorMetrics::from_global()); execution.completed_with_stop_reason(Some("max_tokens")); assert_eq!(execution.execution, Some(ExecutionOutcome::Incomplete)); - let mut execution = ExecutionSpan::start(Api::Messages, Route::Executor, false); + let mut execution = + ExecutionSpan::start(Api::Messages, Route::Executor, false, &ExecutorMetrics::from_global()); execution.completed_with_stop_reason(Some("end_turn")); assert_eq!(execution.execution, Some(ExecutionOutcome::Completed)); } diff --git a/crates/agentic-server-core/src/executor/telemetry/metrics.rs b/crates/agentic-server-core/src/executor/telemetry/metrics.rs new file mode 100644 index 00000000..7113c8ef --- /dev/null +++ b/crates/agentic-server-core/src/executor/telemetry/metrics.rs @@ -0,0 +1,483 @@ +//! Execution, stage, token, and timing metrics. +//! +//! Every instrument is created once, from a [`Meter`], and shared through +//! [`ExecutorMetrics`], which the [`ExecutionContext`] carries. The gateway +//! binary builds it from the globally registered meter provider after +//! telemetry is initialized; embedding applications pass their own meter with +//! [`ExecutionContext::with_metrics`], and without a provider every +//! instrument is a no-op. +//! +//! Metrics never depend on the trace sampling decision: they are recorded by +//! the same guards that finalize spans, not derived from exported spans. +//! Every attribute is a closed enum or a boolean; no request, response, +//! conversation, tool, model, or URL identifier becomes a metric dimension. +//! +//! [`ExecutionContext`]: crate::executor::ExecutionContext +//! [`ExecutionContext::with_metrics`]: crate::executor::ExecutionContext::with_metrics + +use std::sync::Arc; +use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; +use std::time::{Duration, Instant}; + +use opentelemetry::KeyValue; +use opentelemetry::global; +use opentelemetry::metrics::{Counter, Histogram, Meter, UpDownCounter}; + +use super::{Api, DeliveryOutcome, ExecutionOutcome, FailureCategory, Route}; +use crate::executor::error::ExecutorError; +use crate::tool::ToolType; +use crate::types::io::ResponseUsage; + +/// Instrumentation scope for every instrument this crate creates. +pub const INSTRUMENTATION_SCOPE: &str = "agentic_core"; + +pub(crate) const ATTR_API: &str = "agentic.api"; +pub(crate) const ATTR_ROUTE: &str = "agentic.route"; +pub(crate) const ATTR_STREAM: &str = "agentic.stream"; +pub(crate) const ATTR_EXECUTION_OUTCOME: &str = "agentic.execution.outcome"; +pub(crate) const ATTR_DELIVERY_OUTCOME: &str = "agentic.delivery.outcome"; +pub(crate) const ATTR_ERROR_TYPE: &str = "error.type"; +const ATTR_STAGE: &str = "agentic.stage"; +const ATTR_TOOL_TYPE: &str = "agentic.tool.type"; +const ATTR_OPERATION: &str = "gen_ai.operation.name"; +const ATTR_TOKEN_TYPE: &str = "gen_ai.token.type"; + +/// Every upstream call the executor makes is a chat-style inference. +const OPERATION_CHAT: &str = "chat"; +/// `error.type` for a stage whose future was dropped before it finished. +const ERROR_TYPE_CANCELLED: &str = "cancelled"; + +/// Execution, stage, and delivery durations: powers of two from 10 ms to +/// about 5.5 minutes, covering multi-round tool loops on slow models. +const DURATION_BOUNDARIES: &[f64] = &[ + 0.01, 0.02, 0.04, 0.08, 0.16, 0.32, 0.64, 1.28, 2.56, 5.12, 10.24, 20.48, 40.96, 81.92, 163.84, 327.68, +]; + +/// The `gen_ai.server.time_to_first_token` semantic-convention boundaries, +/// extended to 20 s for queued or cold upstreams. +const FIRST_DATA_BOUNDARIES: &[f64] = &[ + 0.001, 0.005, 0.01, 0.02, 0.04, 0.06, 0.08, 0.1, 0.25, 0.5, 0.75, 1.0, 2.5, 5.0, 7.5, 10.0, 20.0, +]; + +/// Total time a streamed execution waited on its transport. +const DELIVERY_WAIT_BOUNDARIES: &[f64] = &[ + 0.001, 0.0025, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0, 10.0, 30.0, 60.0, +]; + +/// The `gen_ai.client.token.usage` semantic-convention boundaries. +const TOKEN_BOUNDARIES: &[f64] = &[ + 1.0, + 4.0, + 16.0, + 64.0, + 256.0, + 1024.0, + 4096.0, + 16384.0, + 65536.0, + 262_144.0, + 1_048_576.0, + 4_194_304.0, + 16_777_216.0, + 67_108_864.0, +]; + +/// One bucket per round up to the gateway's ten-round cap. +const ROUND_BOUNDARIES: &[f64] = &[1.0, 2.0, 3.0, 4.0, 5.0, 6.0, 7.0, 8.0, 9.0, 10.0]; + +/// A timed executor stage. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub(crate) enum Stage { + Rehydrate, + Inference, + Tool(ToolType), + Compaction, + Persist, +} + +impl Stage { + const fn as_str(self) -> &'static str { + match self { + Self::Rehydrate => "rehydrate", + Self::Inference => "inference", + Self::Tool(_) => "tool", + Self::Compaction => "compaction", + Self::Persist => "persist", + } + } +} + +/// The instruments the executor records, shared by every request. +/// +/// Cheap to clone. Build it once per [`Meter`]; creating instruments per +/// request would defeat the SDK's instrument cache. +#[derive(Debug, Clone)] +pub struct ExecutorMetrics { + instruments: Arc, +} + +#[derive(Debug)] +struct Instruments { + execution_count: Counter, + execution_active: UpDownCounter, + execution_duration: Histogram, + delivery_count: Counter, + delivery_wait: Histogram, + stage_duration: Histogram, + inference_rounds: Histogram, + token_usage: Histogram, + first_upstream_data: Histogram, + first_client_event: Histogram, + first_text: Histogram, +} + +impl ExecutorMetrics { + /// Create every instrument from `meter`. + #[must_use] + pub fn new(meter: &Meter) -> Self { + let seconds = |name: &'static str, description: &'static str, boundaries: &[f64]| { + meter + .f64_histogram(name) + .with_unit("s") + .with_description(description) + .with_boundaries(boundaries.to_vec()) + .build() + }; + let instruments = Instruments { + execution_count: meter + .u64_counter("agentic.execution.count") + .with_unit("{execution}") + .with_description("Finalized executions by API, route, and execution outcome.") + .build(), + execution_active: meter + .i64_up_down_counter("agentic.execution.active") + .with_unit("{execution}") + .with_description("Executions accepted and not yet finalized.") + .build(), + execution_duration: seconds( + "agentic.execution.duration", + "Time from accepting an execution until it is finalized.", + DURATION_BOUNDARIES, + ), + delivery_count: meter + .u64_counter("agentic.delivery.count") + .with_unit("{execution}") + .with_description("Finalized executions by delivery outcome.") + .build(), + delivery_wait: seconds( + "agentic.delivery.wait.duration", + "Total time a streamed execution waited for its transport to take the next frame.", + DELIVERY_WAIT_BOUNDARIES, + ), + stage_duration: seconds( + "agentic.stage.duration", + "Duration of one executor stage: rehydration, an inference round, a gateway-executed tool \ + call, compaction, or persistence.", + DURATION_BOUNDARIES, + ), + inference_rounds: meter + .u64_histogram("agentic.inference.rounds") + .with_unit("{round}") + .with_description("Upstream inference rounds per execution.") + .with_boundaries(ROUND_BOUNDARIES.to_vec()) + .build(), + token_usage: meter + .u64_histogram("gen_ai.client.token.usage") + .with_unit("{token}") + .with_description("Tokens reported by the upstream per inference call.") + .with_boundaries(TOKEN_BOUNDARIES.to_vec()) + .build(), + first_upstream_data: seconds( + "agentic.time_to_first_upstream_data", + "Time from accepting a streamed execution until its first upstream SSE line.", + FIRST_DATA_BOUNDARIES, + ), + first_client_event: seconds( + "agentic.time_to_first_client_event", + "Time from accepting a streamed execution until its first semantic event is handed to the \ + transport.", + FIRST_DATA_BOUNDARIES, + ), + first_text: seconds( + "agentic.time_to_first_text", + "Time from accepting a streamed execution until its first output-text delta is handed to the \ + transport.", + FIRST_DATA_BOUNDARIES, + ), + }; + Self { + instruments: Arc::new(instruments), + } + } + + /// Instruments bound to the globally registered meter provider. + /// + /// With no provider registered the instruments are no-ops, and they stay + /// no-ops: build this after the provider is installed. + #[must_use] + pub fn from_global() -> Self { + Self::new(&global::meter(INSTRUMENTATION_SCOPE)) + } + + /// Record the tokens one upstream inference call reported. Nothing is + /// recorded for a count the upstream did not send. + pub(crate) fn record_token_usage(&self, api: Api, input: Option, output: Option) { + for (token_type, count) in [("input", input), ("output", output)] { + if let Some(count) = count { + self.instruments.token_usage.record( + count, + &[ + KeyValue::new(ATTR_OPERATION, OPERATION_CHAT), + KeyValue::new(ATTR_TOKEN_TYPE, token_type), + KeyValue::new(ATTR_API, api.as_str()), + ], + ); + } + } + } + + /// Record the usage one Responses upstream call reported; `None` records + /// nothing. + pub(crate) fn record_response_usage(&self, usage: Option<&ResponseUsage>) { + if let Some(usage) = usage { + self.record_token_usage( + Api::Responses, + u64::try_from(usage.input_tokens).ok(), + u64::try_from(usage.output_tokens).ok(), + ); + } + } + + /// Start timing one stage; the returned timer records when it is + /// finished or dropped. + pub(crate) fn stage(&self, stage: Stage) -> StageTimer { + StageTimer { + metrics: self.clone(), + stage, + started: Instant::now(), + finished: false, + } + } + + /// Count the inference rounds of one execution; the count is recorded + /// when the returned counter is dropped. + pub(crate) fn rounds(&self, api: Api) -> RoundCounter { + RoundCounter { + metrics: self.clone(), + api, + rounds: 0, + } + } + + fn record_stage(&self, stage: Stage, elapsed: Duration, error_type: Option<&'static str>) { + let mut attributes = Vec::with_capacity(3); + attributes.push(KeyValue::new(ATTR_STAGE, stage.as_str())); + if let Stage::Tool(kind) = stage { + attributes.push(KeyValue::new(ATTR_TOOL_TYPE, super::stages::tool_type(kind))); + } + if let Some(error_type) = error_type { + attributes.push(KeyValue::new(ATTR_ERROR_TYPE, error_type)); + } + self.instruments + .stage_duration + .record(elapsed.as_secs_f64(), &attributes); + } +} + +/// Records one `agentic.stage.duration` sample exactly once: on +/// [`StageTimer::finish`], or as `cancelled` when dropped unfinished. +pub(crate) struct StageTimer { + metrics: ExecutorMetrics, + stage: Stage, + started: Instant, + finished: bool, +} + +impl StageTimer { + /// Record the stage, labelled with the error category when it failed. + pub(crate) fn finish_result(self, result: &Result) { + self.finish(result.as_ref().err().map(FailureCategory::from)); + } + + /// The stage turned out not to run; record nothing. + pub(crate) fn discard(mut self) { + self.finished = true; + } + + pub(crate) fn finish(mut self, failure: Option) { + self.finished = true; + self.metrics + .record_stage(self.stage, self.started.elapsed(), failure.map(FailureCategory::as_str)); + } +} + +impl Drop for StageTimer { + fn drop(&mut self) { + if !self.finished { + self.metrics + .record_stage(self.stage, self.started.elapsed(), Some(ERROR_TYPE_CANCELLED)); + } + } +} + +/// Counts one execution's upstream inference rounds and records the total +/// once, when dropped, however the loop ended. +pub(crate) struct RoundCounter { + metrics: ExecutorMetrics, + api: Api, + rounds: u64, +} + +impl RoundCounter { + pub(crate) fn begin_round(&mut self) { + self.rounds = self.rounds.saturating_add(1); + } +} + +impl Drop for RoundCounter { + fn drop(&mut self) { + if self.rounds > 0 { + self.metrics + .instruments + .inference_rounds + .record(self.rounds, &[KeyValue::new(ATTR_API, self.api.as_str())]); + } + } +} + +/// Per-execution timing state shared by the execution guard, the upstream +/// reader, and the client relay, which may run on different tasks. +/// +/// Each first-* timing is measured from the moment the execution was +/// accepted and recorded at most once. +#[derive(Debug, Clone)] +pub(crate) struct ExecutionClock { + inner: Arc, +} + +#[derive(Debug)] +struct ClockState { + metrics: ExecutorMetrics, + api: Api, + route: Route, + stream: bool, + started: Instant, + first_upstream_data: AtomicBool, + first_client_event: AtomicBool, + first_text: AtomicBool, + handed_frames: AtomicBool, + delivery_wait_nanos: AtomicU64, +} + +impl ExecutionClock { + /// Start the clock and count the execution as active. + pub(super) fn start(metrics: ExecutorMetrics, api: Api, route: Route, stream: bool) -> Self { + let clock = Self { + inner: Arc::new(ClockState { + metrics, + api, + route, + stream, + started: Instant::now(), + first_upstream_data: AtomicBool::new(false), + first_client_event: AtomicBool::new(false), + first_text: AtomicBool::new(false), + handed_frames: AtomicBool::new(false), + delivery_wait_nanos: AtomicU64::new(0), + }), + }; + clock + .inner + .metrics + .instruments + .execution_active + .add(1, &clock.base_attributes()); + clock + } + + fn base_attributes(&self) -> [KeyValue; 3] { + [ + KeyValue::new(ATTR_API, self.inner.api.as_str()), + KeyValue::new(ATTR_ROUTE, self.inner.route.as_str()), + KeyValue::new(ATTR_STREAM, self.inner.stream), + ] + } + + /// The first upstream SSE line reached the pipeline. + pub(crate) fn upstream_data(&self) { + self.first(&self.inner.first_upstream_data, |instruments| { + &instruments.first_upstream_data + }); + } + + /// A semantic event of the response is being handed to the transport. + /// `text` marks an output-text delta. + pub(crate) fn client_event(&self, text: bool) { + self.first(&self.inner.first_client_event, |instruments| { + &instruments.first_client_event + }); + if text { + self.first(&self.inner.first_text, |instruments| &instruments.first_text); + } + } + + fn first(&self, seen: &AtomicBool, histogram: impl FnOnce(&Instruments) -> &Histogram) { + // Every later event takes the load alone, without writing the flag. + if !seen.load(Ordering::Relaxed) && !seen.swap(true, Ordering::Relaxed) { + histogram(&self.inner.metrics.instruments).record( + self.inner.started.elapsed().as_secs_f64(), + &[KeyValue::new(ATTR_API, self.inner.api.as_str())], + ); + } + } + + /// A frame was handed to the transport. + pub(super) fn frame_handed(&self) { + if !self.inner.handed_frames.load(Ordering::Relaxed) { + self.inner.handed_frames.store(true, Ordering::Relaxed); + } + } + + /// The transport asked for the next frame `waited` after taking the + /// previous one. + pub(super) fn transport_waited(&self, waited: Duration) { + let nanos = u64::try_from(waited.as_nanos()).unwrap_or(u64::MAX); + self.inner.delivery_wait_nanos.fetch_add(nanos, Ordering::Relaxed); + } + + /// Record the execution's terminal metrics and release its active count. + /// The execution guard calls this exactly once, from `Drop`. + pub(super) fn finalize( + &self, + execution: ExecutionOutcome, + failure: Option, + delivery: DeliveryOutcome, + ) { + let instruments = &self.inner.metrics.instruments; + let base = self.base_attributes(); + instruments.execution_active.add(-1, &base); + + let mut attributes = Vec::with_capacity(5); + attributes.extend_from_slice(&base); + attributes.push(KeyValue::new(ATTR_EXECUTION_OUTCOME, execution.as_str())); + if let Some(failure) = failure { + attributes.push(KeyValue::new(ATTR_ERROR_TYPE, failure.as_str())); + } + instruments.execution_count.add(1, &attributes); + instruments + .execution_duration + .record(self.inner.started.elapsed().as_secs_f64(), &attributes); + + let mut attributes = base.to_vec(); + attributes.push(KeyValue::new(ATTR_DELIVERY_OUTCOME, delivery.as_str())); + instruments.delivery_count.add(1, &attributes); + + if self.inner.handed_frames.load(Ordering::Relaxed) { + let waited = Duration::from_nanos(self.inner.delivery_wait_nanos.load(Ordering::Relaxed)); + instruments.delivery_wait.record( + waited.as_secs_f64(), + &[KeyValue::new(ATTR_API, self.inner.api.as_str())], + ); + } + } +} diff --git a/crates/agentic-server-core/tests/execution_metrics/harness.rs b/crates/agentic-server-core/tests/execution_metrics/harness.rs new file mode 100644 index 00000000..14b19c2c --- /dev/null +++ b/crates/agentic-server-core/tests/execution_metrics/harness.rs @@ -0,0 +1,363 @@ +//! Metric capture and the metric cardinality contract, shared by the core +//! and server metric tests. +//! +//! Every test builds its own meter provider with an in-memory exporter, so +//! tests run in parallel without sharing instruments. [`assert_allowed`] is the +//! build-failing cardinality check: an instrument, attribute key, or attribute +//! value outside the tables below fails the test that recorded it. The tables +//! mirror `docs/deploying/observability.md`; change both together. + +#![allow(dead_code)] + +use std::collections::BTreeMap; +use std::time::Duration; + +use agentic_core::executor::telemetry::ExecutorMetrics; +use opentelemetry::metrics::{Meter, MeterProvider as _}; +use opentelemetry_sdk::metrics::data::{AggregatedMetrics, MetricData, ResourceMetrics, ScopeMetrics}; +use opentelemetry_sdk::metrics::{InMemoryMetricExporter, PeriodicReader, SdkMeterProvider}; + +/// Attribute keys each instrument may carry. +const INSTRUMENT_KEYS: &[(&str, &[&str])] = &[ + ( + "agentic.execution.count", + &[ + "agentic.api", + "agentic.route", + "agentic.stream", + "agentic.execution.outcome", + "error.type", + ], + ), + ( + "agentic.execution.active", + &["agentic.api", "agentic.route", "agentic.stream"], + ), + ( + "agentic.execution.duration", + &[ + "agentic.api", + "agentic.route", + "agentic.stream", + "agentic.execution.outcome", + "error.type", + ], + ), + ( + "agentic.delivery.count", + &[ + "agentic.api", + "agentic.route", + "agentic.stream", + "agentic.delivery.outcome", + ], + ), + ("agentic.delivery.wait.duration", &["agentic.api"]), + ( + "agentic.stage.duration", + &["agentic.stage", "agentic.tool.type", "error.type"], + ), + ("agentic.inference.rounds", &["agentic.api"]), + ( + "gen_ai.client.token.usage", + &["gen_ai.operation.name", "gen_ai.token.type", "agentic.api"], + ), + ("agentic.time_to_first_upstream_data", &["agentic.api"]), + ("agentic.time_to_first_client_event", &["agentic.api"]), + ("agentic.time_to_first_text", &["agentic.api"]), + ("agentic.websocket.connections.active", &[]), + ("agentic.websocket.queue.wait.duration", &[]), + ( + "http.server.request.duration", + &[ + "http.request.method", + "url.scheme", + "http.route", + "http.response.status_code", + ], + ), + ("http.server.active_requests", &["http.request.method", "url.scheme"]), +]; + +/// Values each attribute key may take. Keys absent here are checked by +/// [`value_allowed`]. +const KEY_VALUES: &[(&str, &[&str])] = &[ + ("agentic.api", &["responses", "messages"]), + ("agentic.route", &["executor", "proxy"]), + ("agentic.stream", &["true", "false"]), + ( + "agentic.execution.outcome", + &["completed", "incomplete", "failed", "cancelled"], + ), + ( + "agentic.delivery.outcome", + &["delivered", "disconnected", "not_started"], + ), + ( + "error.type", + &[ + "storage", + "persistence", + "conversation_locked", + "upstream_status", + "upstream_transport", + "network", + "parse", + "stream", + "not_found", + "invalid_request", + "payload_too_large", + "resource_limit", + "conflict", + "compaction", + "tool", + "upstream_error", + "round_budget", + "panic", + "cancelled", + ], + ), + ( + "agentic.stage", + &["rehydrate", "inference", "tool", "compaction", "persist"], + ), + ( + "agentic.tool.type", + &[ + "function", + "tool_search", + "custom", + "shell", + "codex_namespace", + "mcp", + "web_search", + "file_search", + "code_interpreter", + ], + ), + ("gen_ai.operation.name", &["chat"]), + ("gen_ai.token.type", &["input", "output"]), + ( + "http.request.method", + &[ + "CONNECT", "DELETE", "GET", "HEAD", "OPTIONS", "PATCH", "POST", "PUT", "TRACE", "_OTHER", + ], + ), + ("url.scheme", &["http"]), +]; + +/// One exported data point, flattened. +#[derive(Debug, Clone)] +pub struct Point { + pub name: String, + pub attributes: BTreeMap, + pub value: PointValue, +} + +#[derive(Debug, Clone, Copy)] +pub enum PointValue { + /// A counter or up-down counter value. + Sum(i64), + /// A histogram of seconds. + Histogram { count: u64, sum: f64 }, + /// A histogram of integers: tokens or rounds. + IntHistogram { count: u64, sum: u64 }, +} + +impl Point { + fn matches(&self, name: &str, filters: &[(&str, &str)]) -> bool { + self.name == name + && filters + .iter() + .all(|(key, value)| self.attributes.get(*key).is_some_and(|actual| actual == value)) + } +} + +/// A meter provider whose exports stay in memory for one test. +pub struct Metrics { + provider: SdkMeterProvider, + exporter: InMemoryMetricExporter, +} + +impl Metrics { + pub fn new() -> Self { + let exporter = InMemoryMetricExporter::default(); + let provider = SdkMeterProvider::builder() + .with_reader(PeriodicReader::builder(exporter.clone()).build()) + .build(); + Self { provider, exporter } + } + + pub fn meter(&self, scope: &'static str) -> Meter { + self.provider.meter(scope) + } + + /// Executor instruments bound to this provider. + pub fn executor(&self) -> ExecutorMetrics { + ExecutorMetrics::new(&self.meter("agentic_core")) + } + + /// Every data point of the latest (cumulative) export. + pub fn points(&self) -> Vec { + self.provider.force_flush().unwrap(); + let exports = self.exporter.get_finished_metrics().unwrap(); + exports.last().map(sdk_points).unwrap_or_default() + } + + /// Poll until `ready` holds, then check the cardinality contract. + /// + /// Executions finalize when their guard drops, which can land a few + /// milliseconds after the request future returns (a stream reaped on a + /// later tick, a `sqlx` worker releasing a span). + pub async fn wait_for(&self, what: &str, ready: impl Fn(&[Point]) -> bool) -> Vec { + let deadline = tokio::time::Instant::now() + Duration::from_secs(5); + loop { + let points = self.points(); + if ready(&points) { + assert_allowed(&points); + return points; + } + assert!( + tokio::time::Instant::now() < deadline, + "timed out waiting for {what}: {points:#?}" + ); + tokio::time::sleep(Duration::from_millis(5)).await; + } + } +} + +impl Drop for Metrics { + fn drop(&mut self) { + let _ = self.provider.shutdown(); + } +} + +fn sdk_points(export: &ResourceMetrics) -> Vec { + let mut points = Vec::new(); + for metric in export.scope_metrics().flat_map(ScopeMetrics::metrics) { + let name = metric.name().to_owned(); + let mut push = |attributes: BTreeMap, value| { + points.push(Point { + name: name.clone(), + attributes, + value, + }); + }; + match metric.data() { + AggregatedMetrics::U64(MetricData::Sum(sum)) => { + for p in sum.data_points() { + let value = PointValue::Sum(i64::try_from(p.value()).unwrap()); + push(attributes(p.attributes()), value); + } + } + AggregatedMetrics::I64(MetricData::Sum(sum)) => { + for p in sum.data_points() { + push(attributes(p.attributes()), PointValue::Sum(p.value())); + } + } + AggregatedMetrics::F64(MetricData::Histogram(histogram)) => { + for p in histogram.data_points() { + let value = PointValue::Histogram { + count: p.count(), + sum: p.sum(), + }; + push(attributes(p.attributes()), value); + } + } + AggregatedMetrics::U64(MetricData::Histogram(histogram)) => { + for p in histogram.data_points() { + let value = PointValue::IntHistogram { + count: p.count(), + sum: p.sum(), + }; + push(attributes(p.attributes()), value); + } + } + other => panic!("{name}: unexpected aggregation {other:?}"), + } + } + points +} + +fn attributes<'a>(kvs: impl Iterator) -> BTreeMap { + kvs.map(|kv| (kv.key.to_string(), kv.value.to_string())).collect() +} + +/// Sum of matching counter values, or number of matching histogram samples. +pub fn total(points: &[Point], name: &str, filters: &[(&str, &str)]) -> i64 { + points + .iter() + .filter(|point| point.matches(name, filters)) + .map(|point| match point.value { + PointValue::Sum(value) => value, + PointValue::Histogram { count, .. } | PointValue::IntHistogram { count, .. } => { + i64::try_from(count).unwrap() + } + }) + .sum() +} + +/// Sum of the seconds recorded into matching histogram points. +pub fn histogram_sum(points: &[Point], name: &str, filters: &[(&str, &str)]) -> f64 { + points + .iter() + .filter(|point| point.matches(name, filters)) + .map(|point| match point.value { + PointValue::Histogram { sum, .. } => sum, + _ => panic!("{name} is not a histogram of seconds"), + }) + .sum() +} + +/// Sum of the integers recorded into matching histogram points. +pub fn int_histogram_sum(points: &[Point], name: &str, filters: &[(&str, &str)]) -> u64 { + points + .iter() + .filter(|point| point.matches(name, filters)) + .map(|point| match point.value { + PointValue::IntHistogram { sum, .. } => sum, + _ => panic!("{name} is not an integer histogram"), + }) + .sum() +} + +/// Whether any point of `name` exists at all. +pub fn recorded(points: &[Point], name: &str) -> bool { + points.iter().any(|point| point.name == name) +} + +/// Fail on any instrument, attribute key, or attribute value outside the +/// cardinality contract. +pub fn assert_allowed(points: &[Point]) { + for point in points { + let keys = INSTRUMENT_KEYS + .iter() + .find(|(name, _)| *name == point.name) + .unwrap_or_else(|| panic!("instrument {} is not in the metric allow-list", point.name)) + .1; + for (key, value) in &point.attributes { + assert!( + keys.contains(&key.as_str()), + "{}: attribute {key} is not allowed on this instrument", + point.name + ); + assert!( + value_allowed(key, value), + "{}: {key}={value:?} is outside the allowed values", + point.name + ); + } + } +} + +fn value_allowed(key: &str, value: &str) -> bool { + if let Some((_, values)) = KEY_VALUES.iter().find(|(allowed, _)| *allowed == key) { + return values.contains(&value); + } + match key { + // Route templates come from the router, never the request target. + "http.route" => value.starts_with('/') && !value.contains('?'), + "http.response.status_code" => value.parse::().is_ok_and(|status| (100..=599).contains(&status)), + _ => false, + } +} diff --git a/crates/agentic-server-core/tests/execution_metrics_test.rs b/crates/agentic-server-core/tests/execution_metrics_test.rs new file mode 100644 index 00000000..0b80c0fa --- /dev/null +++ b/crates/agentic-server-core/tests/execution_metrics_test.rs @@ -0,0 +1,605 @@ +//! Execution metrics through the real executor against mock and recorded +//! upstreams, captured by a per-test in-memory meter provider. +//! +//! No `tracing` subscriber is installed in this binary: every assertion +//! here holds without a tracer, which is what makes the metrics independent +//! of the trace sampling decision. + +use std::fmt::Write as _; +use std::sync::Arc; + +use agentic_core::executor::{ + BoxStream, ExecuteRequest, ExecutionContext, ExecutorResult, MessagesRequestContext, MessagesUpstream, + run_messages_loop, run_messages_stream, +}; +use agentic_core::storage::{ConversationStore, ResponseStore}; +use agentic_core::tool::ToolRegistry; +use agentic_core::types::request_response::{RequestPayload, ResponsePayload}; +use either::Either; +use futures::StreamExt as _; +use serde_json::json; + +#[path = "execution_metrics/harness.rs"] +mod harness; +mod support; +use harness::{Metrics, histogram_sum, int_histogram_sum, recorded, total}; +use support::{MockResponse, MockServer, TestFixture, text_response}; + +const RESPONSES_EXECUTOR: &[(&str, &str)] = &[("agentic.api", "responses"), ("agentic.route", "executor")]; + +fn request(stream: bool) -> RequestPayload { + support::make_request("say one word", true, stream, None, None) +} + +/// The fixture's context, recording into `metrics`. +fn measured(exec_ctx: &Arc, metrics: &Metrics) -> Arc { + Arc::new(ExecutionContext::clone(exec_ctx).with_metrics(metrics.executor())) +} + +#[allow(clippy::result_large_err)] +async fn execute( + exec_ctx: Arc, + payload: RequestPayload, +) -> ExecutorResult> { + Box::pin(ExecuteRequest::new(payload, exec_ctx).run()).await +} + +async fn stream_of(exec_ctx: Arc, payload: RequestPayload) -> BoxStream { + match execute(exec_ctx, payload).await.unwrap() { + Either::Right(stream) => stream, + Either::Left(_) => panic!("streaming request returns a stream"), + } +} + +/// A minimal upstream stream: created, one text delta, completed without usage. +fn streaming_text_response(text: &str) -> MockResponse { + let message = json!({ + "id": "msg_upstream", "type": "message", "role": "assistant", "status": "completed", + "content": [{"type": "output_text", "text": text, "annotations": []}] + }); + let events = [ + json!({"type": "response.created", "sequence_number": 0, + "response": {"id": "resp_upstream", "status": "in_progress"}}), + json!({"type": "response.output_item.added", "sequence_number": 1, "output_index": 0, + "item": {"id": "msg_upstream", "type": "message", "role": "assistant", + "status": "in_progress", "content": []}}), + json!({"type": "response.output_text.delta", "sequence_number": 2, "output_index": 0, + "content_index": 0, "delta": text}), + json!({"type": "response.output_item.done", "sequence_number": 3, "output_index": 0, "item": message}), + json!({"type": "response.completed", "sequence_number": 4, + "response": {"id": "resp_upstream", "status": "completed", "usage": null, "output": [message]}}), + ]; + let mut body = String::new(); + for event in events { + writeln!(body, "data: {event}\n").unwrap(); + } + body.push_str("data: [DONE]\n\n"); + MockResponse::Sse(body) +} + +fn upstream_502() -> MockResponse { + MockResponse::Status( + 502, + r#"{"error":{"message":"upstream secret detail","type":"server_error"}}"#.to_owned(), + ) +} + +/// The execution was counted exactly once with `outcome`, and its active +/// count was released. +fn assert_finalized_once(points: &[harness::Point], stream: &str, outcome: &str, delivery: &str) { + let filters = [RESPONSES_EXECUTOR, &[("agentic.stream", stream)]].concat(); + assert_eq!( + total(points, "agentic.execution.count", &[]), + 1, + "one execution in total" + ); + let outcome_filter = [filters.as_slice(), &[("agentic.execution.outcome", outcome)]].concat(); + assert_eq!(total(points, "agentic.execution.count", &outcome_filter), 1); + assert_eq!(total(points, "agentic.execution.duration", &outcome_filter), 1); + let delivery_filter = [filters.as_slice(), &[("agentic.delivery.outcome", delivery)]].concat(); + assert_eq!(total(points, "agentic.delivery.count", &[]), 1); + assert_eq!(total(points, "agentic.delivery.count", &delivery_filter), 1); + assert!( + recorded(points, "agentic.execution.active"), + "the active count was taken" + ); + assert_eq!(total(points, "agentic.execution.active", &[]), 0, "and released"); +} + +fn finalized(points: &[harness::Point]) -> bool { + total(points, "agentic.execution.count", &[]) >= 1 +} + +#[tokio::test] +async fn blocking_completion_records_each_instrument_once() { + let metrics = Metrics::new(); + let fixture = TestFixture::new_with_responses(vec![text_response("hello")]).await; + + let result = execute(measured(&fixture.exec_ctx, &metrics), request(false)).await; + assert!(matches!(result, Ok(Either::Left(_)))); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_finalized_once(&points, "false", "completed", "delivered"); + assert_eq!( + total(&points, "agentic.execution.count", &[("error.type", "storage")]), + 0 + ); + for stage in ["rehydrate", "inference", "persist"] { + assert_eq!( + total(&points, "agentic.stage.duration", &[("agentic.stage", stage)]), + 1, + "{stage}" + ); + } + assert!( + points + .iter() + .filter(|point| point.name == "agentic.stage.duration") + .all(|point| !point.attributes.contains_key("error.type")), + "no stage failed" + ); + assert_eq!(total(&points, "agentic.inference.rounds", &[]), 1); + assert_eq!(int_histogram_sum(&points, "agentic.inference.rounds", &[]), 1); + assert!( + !recorded(&points, "gen_ai.client.token.usage"), + "the upstream sent `usage: null`; nothing is fabricated" + ); + for timing in [ + "agentic.time_to_first_upstream_data", + "agentic.time_to_first_client_event", + "agentic.time_to_first_text", + "agentic.delivery.wait.duration", + ] { + assert!(!recorded(&points, timing), "{timing} is only for streamed executions"); + } +} + +#[tokio::test] +async fn recorded_stream_orders_first_timings_and_reports_upstream_usage() { + let metrics = Metrics::new(); + let cassette = support::load_cassette(concat!( + env!("CARGO_MANIFEST_DIR"), + "/tests/cassettes/text_only/responses/resp-single-gpt-4o-streaming.yaml" + )); + let fixture = TestFixture::new(&support::responses_turns(&cassette)).await; + + let frames: Vec = stream_of(measured(&fixture.exec_ctx, &metrics), request(true)) + .await + .collect() + .await; + assert!(frames.iter().any(|frame| frame.contains("response.output_text.delta"))); + assert!(frames.iter().any(|frame| frame.contains("response.completed"))); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_finalized_once(&points, "true", "completed", "delivered"); + let api = [("agentic.api", "responses")]; + let first_upstream = histogram_sum(&points, "agentic.time_to_first_upstream_data", &api); + let first_event = histogram_sum(&points, "agentic.time_to_first_client_event", &api); + let first_text = histogram_sum(&points, "agentic.time_to_first_text", &api); + for timing in [ + "agentic.time_to_first_upstream_data", + "agentic.time_to_first_client_event", + "agentic.time_to_first_text", + ] { + assert_eq!(total(&points, timing, &api), 1, "{timing} is recorded once"); + } + assert!( + 0.0 < first_upstream && first_upstream <= first_event && first_event <= first_text, + "upstream {first_upstream} <= client event {first_event} <= text {first_text}" + ); + assert_eq!(total(&points, "agentic.delivery.wait.duration", &api), 1); + + // The cassette's `response.completed` reports 14 input and 4 output tokens. + let input = [("gen_ai.token.type", "input"), ("gen_ai.operation.name", "chat")]; + let output = [("gen_ai.token.type", "output"), ("gen_ai.operation.name", "chat")]; + assert_eq!(total(&points, "gen_ai.client.token.usage", &input), 1); + assert_eq!(int_histogram_sum(&points, "gen_ai.client.token.usage", &input), 14); + assert_eq!(int_histogram_sum(&points, "gen_ai.client.token.usage", &output), 4); +} + +#[tokio::test] +async fn upstream_failure_in_a_stream_is_one_delivered_failure() { + let metrics = Metrics::new(); + let fixture = TestFixture::new_with_responses(vec![upstream_502()]).await; + + let frames: Vec = stream_of(measured(&fixture.exec_ctx, &metrics), request(true)) + .await + .collect() + .await; + assert!( + frames.iter().any(|frame| frame.starts_with("event: error")), + "{frames:?}" + ); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_finalized_once(&points, "true", "failed", "delivered"); + assert_eq!( + total(&points, "agentic.execution.count", &[("error.type", "upstream_status")]), + 1 + ); + assert_eq!( + total( + &points, + "agentic.stage.duration", + &[("agentic.stage", "inference"), ("error.type", "upstream_status")] + ), + 1 + ); + assert!(!recorded(&points, "gen_ai.client.token.usage")); + // No upstream line arrived and an executor error frame is not a response + // event, so no first-* timing describes this execution. + for timing in [ + "agentic.time_to_first_upstream_data", + "agentic.time_to_first_client_event", + "agentic.time_to_first_text", + ] { + assert!(!recorded(&points, timing), "{timing}"); + } +} + +#[tokio::test] +async fn upstream_failure_without_a_stream_is_never_delivered() { + let metrics = Metrics::new(); + let fixture = TestFixture::new_with_responses(vec![upstream_502()]).await; + + assert!( + execute(measured(&fixture.exec_ctx, &metrics), request(false)) + .await + .is_err() + ); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_finalized_once(&points, "false", "failed", "not_started"); + assert_eq!(total(&points, "agentic.inference.rounds", &[]), 1); +} + +#[tokio::test] +async fn dropped_stream_is_one_cancelled_and_disconnected_execution() { + let metrics = Metrics::new(); + let fixture = TestFixture::new_with_responses(vec![streaming_text_response("hello")]).await; + + let mut stream = stream_of(measured(&fixture.exec_ctx, &metrics), request(true)).await; + let first = stream.next().await.expect("at least one frame"); + assert!(first.contains("response.created"), "{first}"); + // The client goes away before the terminal frame. + drop(stream); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_finalized_once(&points, "true", "cancelled", "disconnected"); + assert!( + points + .iter() + .filter(|point| point.name == "agentic.execution.count") + .all(|point| !point.attributes.contains_key("error.type")), + "cancellation is not a failure" + ); + assert_eq!( + total(&points, "agentic.time_to_first_client_event", &[]), + 1, + "the first event reached the transport" + ); +} + +#[tokio::test] +async fn gateway_tool_round_counts_rounds_and_times_the_tool() { + let metrics = Metrics::new(); + let cassette = support::load_cassette(concat!( + env!("CARGO_MANIFEST_DIR"), + "/tests/cassettes/codex/codex-openai-web-search-then-namespace-gpt-4o-streaming.yaml" + )); + let fixture = TestFixture::new(&support::responses_turns(&cassette)).await; + let search = search_server().await; + let exec_ctx = ExecutionContext::clone(&fixture.exec_ctx) + .with_gateway_executor(Arc::new(agentic_core::tool::WebSearchHandler::with_api_key( + Arc::new(reqwest::Client::new()), + "private-search-key".into(), + &search.0, + ))) + .with_metrics(metrics.executor()); + let mut payload = request(true); + payload.tools = Some( + serde_json::from_value(json!([ + {"type":"web_search_preview"}, + {"type":"namespace","name":"mcp__shell","tools":[{"type":"function","name":"run","parameters":{"type":"object"}}]} + ])) + .unwrap(), + ); + + let frames: Vec = stream_of(Arc::new(exec_ctx), payload).await.collect().await; + search.1.abort(); + assert!(frames.iter().any(|frame| frame.contains("response.completed"))); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_finalized_once(&points, "true", "completed", "delivered"); + assert_eq!(total(&points, "agentic.inference.rounds", &[]), 1); + assert_eq!(int_histogram_sum(&points, "agentic.inference.rounds", &[]), 2); + assert_eq!( + total(&points, "agentic.stage.duration", &[("agentic.stage", "inference")]), + 2 + ); + assert_eq!( + total( + &points, + "agentic.stage.duration", + &[("agentic.stage", "tool"), ("agentic.tool.type", "web_search")] + ), + 1 + ); + assert_eq!( + total(&points, "gen_ai.client.token.usage", &[("gen_ai.token.type", "input")]), + 2, + "one sample per upstream call, not per turn" + ); +} + +#[tokio::test] +async fn explicit_compaction_times_its_stages_and_usage_without_an_execution() { + let metrics = Metrics::new(); + let summary = MockResponse::Json( + json!({ + "id": "resp_upstream", "object": "response", "created_at": 0, "model": "test-model", + "status": "completed", + "output": [{"id": "msg_upstream", "type": "message", "role": "assistant", "status": "completed", + "content": [{"type": "output_text", "text": "summary", "annotations": []}]}], + "usage": {"input_tokens": 11, "input_tokens_details": {"cached_tokens": 0}, "output_tokens": 3, + "output_tokens_details": {"reasoning_tokens": 0}, "total_tokens": 14} + }) + .to_string(), + ); + let fixture = TestFixture::new_with_responses(vec![summary]).await; + let payload = serde_json::from_value(json!({"model": "test-model", "input": "compact me"})).unwrap(); + + Box::pin(agentic_core::executor::compact_response( + payload, + &measured(&fixture.exec_ctx, &metrics), + None, + )) + .await + .unwrap(); + + let points = metrics + .wait_for("persist stage", |points| { + total(points, "agentic.stage.duration", &[("agentic.stage", "persist")]) == 1 + }) + .await; + for stage in ["rehydrate", "compaction", "persist"] { + assert_eq!( + total(&points, "agentic.stage.duration", &[("agentic.stage", stage)]), + 1, + "{stage}" + ); + } + assert_eq!( + int_histogram_sum(&points, "gen_ai.client.token.usage", &[("gen_ai.token.type", "input")]), + 11 + ); + assert!( + !recorded(&points, "agentic.execution.count"), + "compaction has no agentic.execute span" + ); +} + +async fn search_server() -> (String, tokio::task::JoinHandle<()>) { + let listener = tokio::net::TcpListener::bind("127.0.0.1:0").await.unwrap(); + let url = format!("http://{}", listener.local_addr().unwrap()); + let router = axum::Router::new().route( + "/v1/search", + axum::routing::get(|| async { + axum::Json(json!({"results":{"web":[{"url":"https://example.com","title":"result"}],"news":[]}})) + }), + ); + let task = tokio::spawn(async move { axum::serve(listener, router).await.unwrap() }); + (url, task) +} + +struct MessagesFixture { + exec_ctx: Arc, + upstream: MessagesUpstream, + _server: MockServer, +} + +async fn messages_fixture(metrics: &Metrics, responses: Vec) -> MessagesFixture { + let server = MockServer::start_deque_on("/v1/messages", responses).await; + let pool = support::setup_pool().await; + let exec_ctx = ExecutionContext::new( + agentic_core::executor::ConversationHandler::new(ConversationStore::new(Arc::clone(&pool))), + agentic_core::executor::ResponseHandler::new(ResponseStore::new(pool)), + Arc::new(reqwest::Client::new()), + server.url().to_owned(), + ) + .with_metrics(metrics.executor()); + let upstream = MessagesUpstream::new(server.url(), None, reqwest::header::HeaderMap::new()); + MessagesFixture { + exec_ctx: Arc::new(exec_ctx), + upstream, + _server: server, + } +} + +fn messages_request(stream: bool) -> MessagesRequestContext { + MessagesRequestContext::from_value(json!({ + "model": "test-model", "max_tokens": 64, "stream": stream, + "messages": [{"role": "user", "content": "say one word"}] + })) + .unwrap() +} + +fn messages_sse_response() -> MockResponse { + let events = [ + json!({"type": "message_start", "message": { + "id": "msg_upstream", "type": "message", "role": "assistant", "model": "test-model", + "content": [], "stop_reason": null, "stop_sequence": null, + "usage": {"input_tokens": 3, "output_tokens": 0, "cache_read_input_tokens": 5}}}), + json!({"type": "content_block_start", "index": 0, "content_block": {"type": "text", "text": ""}}), + json!({"type": "content_block_delta", "index": 0, "delta": {"type": "text_delta", "text": "hello"}}), + json!({"type": "content_block_stop", "index": 0}), + json!({"type": "message_delta", "delta": {"stop_reason": "end_turn", "stop_sequence": null}, + "usage": {"output_tokens": 2}}), + json!({"type": "message_stop"}), + ]; + let mut body = String::new(); + for event in events { + writeln!(body, "event: {}\ndata: {event}\n", event["type"].as_str().unwrap()).unwrap(); + } + MockResponse::Sse(body) +} + +fn assert_messages_finalized_once(points: &[harness::Point], stream: &str, outcome: &str, delivery: &str) { + let filters = [ + ("agentic.api", "messages"), + ("agentic.route", "executor"), + ("agentic.stream", stream), + ]; + let outcome_filter = [filters.as_slice(), &[("agentic.execution.outcome", outcome)]].concat(); + let delivery_filter = [filters.as_slice(), &[("agentic.delivery.outcome", delivery)]].concat(); + assert_eq!(total(points, "agentic.execution.count", &[]), 1); + assert_eq!(total(points, "agentic.execution.count", &outcome_filter), 1); + assert_eq!(total(points, "agentic.delivery.count", &delivery_filter), 1); + assert_eq!(total(points, "agentic.execution.active", &[]), 0); +} + +#[tokio::test] +async fn messages_loop_reports_prompt_tokens_including_cache_reads() { + let metrics = Metrics::new(); + let response = MockResponse::Json( + json!({ + "id": "msg_upstream", "type": "message", "role": "assistant", "model": "test-model", + "content": [{"type": "text", "text": "hello"}], "stop_reason": "end_turn", "stop_sequence": null, + "usage": {"input_tokens": 3, "output_tokens": 1, "cache_read_input_tokens": 5} + }) + .to_string(), + ); + let fixture = messages_fixture(&metrics, vec![response]).await; + + run_messages_loop( + messages_request(false), + &ToolRegistry::default(), + &fixture.exec_ctx, + &fixture.upstream, + ) + .await + .unwrap(); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_messages_finalized_once(&points, "false", "completed", "delivered"); + let api = ("agentic.api", "messages"); + assert_eq!( + int_histogram_sum( + &points, + "gen_ai.client.token.usage", + &[api, ("gen_ai.token.type", "input")] + ), + 8, + "input_tokens plus cache reads" + ); + assert_eq!( + int_histogram_sum( + &points, + "gen_ai.client.token.usage", + &[api, ("gen_ai.token.type", "output")] + ), + 1 + ); + assert_eq!( + total(&points, "agentic.stage.duration", &[("agentic.stage", "inference")]), + 1 + ); + assert_eq!(total(&points, "agentic.inference.rounds", &[api]), 1); +} + +#[tokio::test] +async fn messages_stream_orders_first_timings_and_reports_final_round_usage() { + let metrics = Metrics::new(); + let fixture = messages_fixture(&metrics, vec![messages_sse_response()]).await; + + let response = run_messages_stream( + messages_request(true), + Arc::new(ToolRegistry::default()), + Arc::clone(&fixture.exec_ctx), + fixture.upstream.clone(), + ) + .await + .unwrap(); + let frames: Vec = response.body.collect().await; + assert!(frames.iter().any(|frame| frame.contains("text_delta")), "{frames:?}"); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_messages_finalized_once(&points, "true", "completed", "delivered"); + let api = [("agentic.api", "messages")]; + let first_upstream = histogram_sum(&points, "agentic.time_to_first_upstream_data", &api); + let first_event = histogram_sum(&points, "agentic.time_to_first_client_event", &api); + let first_text = histogram_sum(&points, "agentic.time_to_first_text", &api); + assert!( + 0.0 < first_upstream && first_upstream <= first_event && first_event <= first_text, + "upstream {first_upstream} <= client event {first_event} <= text {first_text}" + ); + // `message_start.usage` overlaid by the final `message_delta.usage`. + assert_eq!( + int_histogram_sum( + &points, + "gen_ai.client.token.usage", + &[api[0], ("gen_ai.token.type", "input")] + ), + 8 + ); + assert_eq!( + int_histogram_sum( + &points, + "gen_ai.client.token.usage", + &[api[0], ("gen_ai.token.type", "output")] + ), + 2 + ); + assert_eq!(total(&points, "agentic.delivery.wait.duration", &api), 1); +} + +#[tokio::test] +async fn messages_stream_rejected_before_headers_is_never_delivered() { + let metrics = Metrics::new(); + let fixture = messages_fixture(&metrics, vec![upstream_502()]).await; + + let rejected = run_messages_stream( + messages_request(true), + Arc::new(ToolRegistry::default()), + Arc::clone(&fixture.exec_ctx), + fixture.upstream.clone(), + ) + .await; + assert!(rejected.is_err()); + + let points = metrics.wait_for("finalized execution", finalized).await; + assert_messages_finalized_once(&points, "true", "failed", "not_started"); + assert_eq!( + total( + &points, + "agentic.stage.duration", + &[("agentic.stage", "inference"), ("error.type", "upstream_status")] + ), + 1 + ); +} + +/// The cardinality check is what fails the build on a new dimension, so it +/// must reject each kind of violation. +#[test] +fn cardinality_contract_rejects_unlisted_instruments_keys_and_values() { + fn violation(name: &str, key: &str, value: &str) -> bool { + let point = harness::Point { + name: name.to_owned(), + attributes: [(key.to_owned(), value.to_owned())].into(), + value: harness::PointValue::Sum(1), + }; + std::panic::catch_unwind(|| harness::assert_allowed(&[point])).is_err() + } + assert!(!violation("agentic.execution.count", "agentic.api", "responses")); + assert!(violation("agentic.execution.count", "response.id", "resp_123")); + assert!(violation("agentic.execution.count", "agentic.api", "gpt-4o")); + assert!(violation("agentic.stage.duration", "agentic.tool.name", "my_tool")); + assert!(violation("gen_ai.client.token.usage", "gen_ai.request.model", "gpt-4o")); + assert!(violation("agentic.unlisted.metric", "agentic.api", "responses")); + assert!(violation( + "http.server.request.duration", + "http.route", + "/v1/responses?x=1" + )); +} diff --git a/crates/agentic-server/src/app.rs b/crates/agentic-server/src/app.rs index 90aca07a..cdc1a37b 100644 --- a/crates/agentic-server/src/app.rs +++ b/crates/agentic-server/src/app.rs @@ -28,6 +28,7 @@ use crate::handler::{ }; use crate::model_capabilities::ModelCapabilities; use crate::telemetry::http::{HttpMetrics, track_request}; +use crate::telemetry::websocket::WebSocketMetrics; /// Default ceiling on serialized inbound request bytes for HTTP bodies and /// WebSocket messages. @@ -39,10 +40,10 @@ pub struct WebSocketTracker { inner: Arc, } -#[derive(Default)] struct WebSocketTrackerInner { active: AtomicUsize, idle: Notify, + metrics: WebSocketMetrics, #[cfg(debug_assertions)] local_completion_barrier: std::sync::Mutex>, } @@ -116,13 +117,45 @@ struct LocalCompletionBarrier { release: oneshot::Receiver<()>, } +impl Default for WebSocketTrackerInner { + fn default() -> Self { + Self::with_metrics(WebSocketMetrics::from_global()) + } +} + +impl WebSocketTrackerInner { + fn with_metrics(metrics: WebSocketMetrics) -> Self { + Self { + active: AtomicUsize::new(0), + idle: Notify::new(), + metrics, + #[cfg(debug_assertions)] + local_completion_barrier: std::sync::Mutex::new(None), + } + } +} + pub(crate) struct WebSocketGuard { inner: Arc, } impl WebSocketTracker { + /// A tracker recording its connection and queue metrics with `metrics` + /// instead of the global meter provider's. + #[must_use] + pub fn with_metrics(metrics: WebSocketMetrics) -> Self { + Self { + inner: Arc::new(WebSocketTrackerInner::with_metrics(metrics)), + } + } + + pub(crate) fn metrics(&self) -> &WebSocketMetrics { + &self.inner.metrics + } + pub(crate) fn track(&self) -> WebSocketGuard { self.inner.active.fetch_add(1, Ordering::AcqRel); + self.inner.metrics.connection_opened(); WebSocketGuard { inner: Arc::clone(&self.inner), } @@ -178,6 +211,7 @@ impl WebSocketTracker { impl Drop for WebSocketGuard { fn drop(&mut self) { + self.inner.metrics.connection_closed(); if self.inner.active.fetch_sub(1, Ordering::AcqRel) == 1 { self.inner.idle.notify_waiters(); } diff --git a/crates/agentic-server/src/handler/http/messages.rs b/crates/agentic-server/src/handler/http/messages.rs index 8d636f46..8db065b6 100644 --- a/crates/agentic-server/src/handler/http/messages.rs +++ b/crates/agentic-server/src/handler/http/messages.rs @@ -34,7 +34,7 @@ async fn proxy_messages( query: parts.uri.query().map(str::to_owned), }, path, - &state.proxy_state, + state, ) .await, ) diff --git a/crates/agentic-server/src/handler/http/responses.rs b/crates/agentic-server/src/handler/http/responses.rs index 85f59c1b..e3972aa6 100644 --- a/crates/agentic-server/src/handler/http/responses.rs +++ b/crates/agentic-server/src/handler/http/responses.rs @@ -28,8 +28,7 @@ async fn proxy_responses(state: &AppState, parts: Parts, body: Bytes) -> Respons query: parts.uri.query().map(str::to_string), }; convert_response( - crate::telemetry::proxy::trace_proxy_request(Api::Responses, proxy_req, "/v1/responses", &state.proxy_state) - .await, + crate::telemetry::proxy::trace_proxy_request(Api::Responses, proxy_req, "/v1/responses", state).await, ) } diff --git a/crates/agentic-server/src/handler/websocket/responses.rs b/crates/agentic-server/src/handler/websocket/responses.rs index d7bff406..ecc2434c 100644 --- a/crates/agentic-server/src/handler/websocket/responses.rs +++ b/crates/agentic-server/src/handler/websocket/responses.rs @@ -232,7 +232,7 @@ async fn handle_ws_request(request: WsRequest, context: RequestExecution<'_>) -> generate, execution, } = request; - let mut execution = execution.unwrap_or_else(telemetry::QueuedExecution::new).dispatch(); + let mut execution = telemetry::dispatch(execution, state); if generate == Some(false) { debug!("handling non-generating websocket request locally"); diff --git a/crates/agentic-server/src/handler/websocket/responses/multiplexer.rs b/crates/agentic-server/src/handler/websocket/responses/multiplexer.rs index 87b1c72f..7580f0b6 100644 --- a/crates/agentic-server/src/handler/websocket/responses/multiplexer.rs +++ b/crates/agentic-server/src/handler/websocket/responses/multiplexer.rs @@ -166,7 +166,7 @@ impl WsMultiplexer { self.sessions.insert(lane.clone(), Arc::new(session)); } if let WsWorkItem::Execute { request, .. } = &mut work { - request.execution = Some(telemetry::QueuedExecution::new()); + request.execution = Some(telemetry::QueuedExecution::new(&self.state)); } self.byte_budget.reserve(work.input_bytes()); if let Some(queue) = self.lanes.get_mut(&lane) { diff --git a/crates/agentic-server/src/handler/websocket/responses/telemetry.rs b/crates/agentic-server/src/handler/websocket/responses/telemetry.rs index 4916e529..a3c891ae 100644 --- a/crates/agentic-server/src/handler/websocket/responses/telemetry.rs +++ b/crates/agentic-server/src/handler/websocket/responses/telemetry.rs @@ -2,6 +2,9 @@ use std::time::Instant; +use crate::app::AppState; +use crate::telemetry::websocket::WebSocketMetrics; + use agentic_core::executor::telemetry::{Api, ExecutionSpan, FailureCategory, Route}; use opentelemetry::trace::TraceContextExt as _; use tracing_opentelemetry::OpenTelemetrySpanExt as _; @@ -16,31 +19,41 @@ pub(super) struct QueuedExecution { struct QueueWait { span: tracing::Span, admitted: Instant, + metrics: WebSocketMetrics, } impl Drop for QueueWait { fn drop(&mut self) { - self.span - .record("agentic.queue.wait", self.admitted.elapsed().as_secs_f64()); + let waited = self.admitted.elapsed(); + self.span.record("agentic.queue.wait", waited.as_secs_f64()); + self.metrics.record_queue_wait(waited); } } impl QueuedExecution { - pub(super) fn new() -> Self { + pub(super) fn new(state: &AppState) -> Self { let session = tracing::Span::current().context().span().span_context().clone(); - let execution = ExecutionSpan::start_linked(Api::Responses, Route::Executor, true, session); + let metrics = &state.exec_ctx.metrics; + let execution = ExecutionSpan::start_linked(Api::Responses, Route::Executor, true, metrics, session); let wait = QueueWait { span: execution.span().clone(), admitted: Instant::now(), + metrics: state.websocket_tracker.metrics().clone(), }; Self { execution, _wait: wait } } - pub(super) fn dispatch(self) -> ExecutionSpan { + fn dispatch(self) -> ExecutionSpan { self.execution } } +/// Start executing an admitted request, ending its queue wait. Every admitted +/// request carries its execution; one that does not is traced from dispatch. +pub(super) fn dispatch(queued: Option, state: &AppState) -> ExecutionSpan { + queued.unwrap_or_else(|| QueuedExecution::new(state)).dispatch() +} + pub(super) fn finish_local(execution: &mut ExecutionSpan, result: &Result<(), WsError>) { match result { Ok(()) => { diff --git a/crates/agentic-server/src/telemetry/mod.rs b/crates/agentic-server/src/telemetry/mod.rs index 20ac202d..4daa978d 100644 --- a/crates/agentic-server/src/telemetry/mod.rs +++ b/crates/agentic-server/src/telemetry/mod.rs @@ -12,6 +12,7 @@ pub mod http; mod lifecycle; pub(crate) mod proxy; mod subscriber; +pub mod websocket; pub use config::{ExporterSelection, OtlpCompression, OtlpProtocol, TelemetryConfig, TelemetryConfigError}; pub use lifecycle::{DEFAULT_SHUTDOWN_TIMEOUT, InstrumentationHandles, Signal, TelemetryError, TelemetryGuard}; diff --git a/crates/agentic-server/src/telemetry/proxy.rs b/crates/agentic-server/src/telemetry/proxy.rs index f1daa29f..b9f605dd 100644 --- a/crates/agentic-server/src/telemetry/proxy.rs +++ b/crates/agentic-server/src/telemetry/proxy.rs @@ -4,23 +4,25 @@ use std::pin::Pin; use std::task::{Context, Poll}; use agentic_core::executor::telemetry::{Api, ExecutionSpan, FailureCategory, Route}; -use agentic_core::proxy::{ProxyAuth, ProxyBody, ProxyRequest, ProxyResponse, ProxyState, proxy_request_with_path}; +use agentic_core::proxy::{ProxyAuth, ProxyBody, ProxyRequest, ProxyResponse, proxy_request_with_path}; use bytes::Bytes; use futures::Stream; use tracing::Instrument as _; +use crate::app::AppState; + pub(crate) async fn trace_proxy_request( api: Api, request: ProxyRequest, path: &str, - state: &ProxyState, + state: &AppState, ) -> ProxyResponse { - let mut execution = ExecutionSpan::start(api, Route::Proxy, request.is_streaming()); + let mut execution = ExecutionSpan::start(api, Route::Proxy, request.is_streaming(), &state.exec_ctx.metrics); let auth = match api { Api::Responses => ProxyAuth::OpenAiBearer, Api::Messages => ProxyAuth::Anthropic, }; - let response = proxy_request_with_path(request, path, auth, state) + let response = proxy_request_with_path(request, path, auth, &state.proxy_state) .instrument(execution.span().clone()) .await; if !response.status.is_success() { diff --git a/crates/agentic-server/src/telemetry/websocket.rs b/crates/agentic-server/src/telemetry/websocket.rs new file mode 100644 index 00000000..02c29473 --- /dev/null +++ b/crates/agentic-server/src/telemetry/websocket.rs @@ -0,0 +1,67 @@ +//! WebSocket transport metrics: open connections and per-message queue wait. +//! +//! Each `response.create` on a connection is its own execution and is counted +//! by the core execution metrics; these instruments cover what only the +//! transport sees. Neither carries attributes, so a connection or stream +//! identifier can never become a dimension. + +use std::time::Duration; + +use opentelemetry::global; +use opentelemetry::metrics::{Histogram, Meter, UpDownCounter}; + +const INSTRUMENTATION_SCOPE: &str = "agentic_server"; + +/// A queued message can wait behind an entire earlier turn on its stream, so +/// the boundaries match the execution durations. +const QUEUE_WAIT_BOUNDARIES: &[f64] = &[ + 0.001, 0.01, 0.02, 0.04, 0.08, 0.16, 0.32, 0.64, 1.28, 2.56, 5.12, 10.24, 20.48, 40.96, 81.92, 163.84, 327.68, +]; + +/// Instruments shared by every WebSocket connection; cheap to clone. +#[derive(Debug, Clone)] +pub struct WebSocketMetrics { + connections: UpDownCounter, + queue_wait: Histogram, +} + +impl WebSocketMetrics { + #[must_use] + pub fn new(meter: &Meter) -> Self { + Self { + connections: meter + .i64_up_down_counter("agentic.websocket.connections.active") + .with_unit("{connection}") + .with_description("Responses WebSocket connections being upgraded or open.") + .build(), + queue_wait: meter + .f64_histogram("agentic.websocket.queue.wait.duration") + .with_unit("s") + .with_description( + "Time a response.create waited on its connection before execution started, including 0 for \ + messages dispatched immediately.", + ) + .with_boundaries(QUEUE_WAIT_BOUNDARIES.to_vec()) + .build(), + } + } + + /// Instruments bound to the globally registered meter provider; no-ops + /// when none is installed. + #[must_use] + pub fn from_global() -> Self { + Self::new(&global::meter(INSTRUMENTATION_SCOPE)) + } + + pub(crate) fn connection_opened(&self) { + self.connections.add(1, &[]); + } + + pub(crate) fn connection_closed(&self) { + self.connections.add(-1, &[]); + } + + pub(crate) fn record_queue_wait(&self, waited: Duration) { + self.queue_wait.record(waited.as_secs_f64(), &[]); + } +} diff --git a/crates/agentic-server/tests/execution_metrics_test.rs b/crates/agentic-server/tests/execution_metrics_test.rs new file mode 100644 index 00000000..973a62fb --- /dev/null +++ b/crates/agentic-server/tests/execution_metrics_test.rs @@ -0,0 +1,399 @@ +//! Execution and transport metrics through the production router, over HTTP +//! and WebSocket, against a scripted upstream. +//! +//! Each test owns its meter provider, so tests run in parallel. Hard process +//! shutdown is covered by `telemetry_metrics_e2e_test.rs`; here shutdown is +//! the gateway's drain signal. + +use std::sync::Arc; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::time::Duration; + +use axum::body::{Body, Bytes}; +use axum::response::{IntoResponse as _, Response}; +use futures::{SinkExt as _, StreamExt as _}; +use serde_json::{Value, json}; +use tokio::sync::Notify; +use tokio_tungstenite::tungstenite::Message; + +use agentic_core::executor::{ConversationHandler, ExecutionContext, ResponseHandler}; +use agentic_core::storage::{ConversationStore, ResponseStore, create_pool_with_schema}; +use agentic_server::app::{AppState, ServerConfig, WebSocketTracker, build_router}; +use agentic_server::telemetry::websocket::WebSocketMetrics; + +#[allow(dead_code)] +mod common; +#[path = "../../agentic-server-core/tests/execution_metrics/harness.rs"] +mod harness; +use harness::{Metrics, Point, total}; + +static DATABASE: AtomicU64 = AtomicU64::new(0); +/// Like a real upstream, each response gets fresh item IDs: stored history +/// keys rows by public item ID, so a repeated ID cannot be stored twice (#385). +static ITEM: AtomicU64 = AtomicU64::new(0); + +fn fresh_item_id(template: &str) -> String { + template.replace("msg_up", &format!("msg_up_{}", ITEM.fetch_add(1, Ordering::Relaxed))) +} + +const USAGE: &str = r#"{"input_tokens":7,"input_tokens_details":{"cached_tokens":0},"output_tokens":2,"output_tokens_details":{"reasoning_tokens":0},"total_tokens":9}"#; + +fn sse_events(usage: &str) -> (String, String) { + let message = r#"{"id":"msg_up","type":"message","role":"assistant","status":"completed","content":[{"type":"output_text","text":"hi","annotations":[]}]}"#; + let head = r#"data: {"type":"response.created","sequence_number":0,"response":{"id":"resp_up","status":"in_progress","output":[]}} + +"# + .to_owned(); + let tail = format!( + "data: {{\"type\":\"response.output_item.added\",\"sequence_number\":1,\"output_index\":0,\"item\":{{\"id\":\"msg_up\",\"type\":\"message\",\"role\":\"assistant\",\"status\":\"in_progress\",\"content\":[]}}}}\n\n\ + data: {{\"type\":\"response.output_text.delta\",\"sequence_number\":2,\"output_index\":0,\"content_index\":0,\"delta\":\"hi\"}}\n\n\ + data: {{\"type\":\"response.output_item.done\",\"sequence_number\":3,\"output_index\":0,\"item\":{message}}}\n\n\ + data: {{\"type\":\"response.completed\",\"sequence_number\":4,\"response\":{{\"id\":\"resp_up\",\"status\":\"completed\",\"output\":[{message}],\"usage\":{usage}}}}}\n\n\ + data: [DONE]\n\n" + ); + (head, tail) +} + +fn json_body() -> String { + json!({ + "id": "resp_up", "object": "response", "created_at": 0, "model": "test-model", "status": "completed", + "output": [{"id": "msg_up", "type": "message", "role": "assistant", "status": "completed", + "content": [{"type": "output_text", "text": "hi", "annotations": []}]}], + "usage": serde_json::from_str::(USAGE).unwrap() + }) + .to_string() +} + +/// An upstream scripted by the prompt: `FAIL` answers 502, `HANG` streams +/// `response.created` and then waits for `release`, anything else completes. +async fn upstream(release: Arc) -> Server { + let router = axum::Router::new().route( + "/v1/responses", + axum::routing::post(move |body: Bytes| { + let release = Arc::clone(&release); + async move { scripted(&body, release) } + }), + ); + Server::start(router).await +} + +fn scripted(body: &[u8], release: Arc) -> Response { + let text = String::from_utf8_lossy(body); + if text.contains("FAIL") { + return ( + http::StatusCode::BAD_GATEWAY, + r#"{"error":{"message":"upstream secret","type":"server_error"}}"#, + ) + .into_response(); + } + let stream = serde_json::from_slice::(body).unwrap()["stream"] == true; + if !stream { + return ([("content-type", "application/json")], fresh_item_id(&json_body())).into_response(); + } + let (head, tail) = sse_events(USAGE); + let tail = fresh_item_id(&tail); + let hang = text.contains("HANG"); + let rest = futures::stream::once(async move { + if hang { + release.notified().await; + } + Ok::<_, std::io::Error>(Bytes::from(tail)) + }); + let body = futures::stream::once(std::future::ready(Ok(Bytes::from(head)))).chain(rest); + ([("content-type", "text/event-stream")], Body::from_stream(body)).into_response() +} + +struct Server { + url: String, + task: tokio::task::JoinHandle<()>, +} + +impl Server { + async fn start(router: axum::Router) -> Self { + let listener = tokio::net::TcpListener::bind("127.0.0.1:0").await.unwrap(); + let url = format!("http://{}", listener.local_addr().unwrap()); + let task = tokio::spawn(async move { axum::serve(listener, router).await.unwrap() }); + Self { url, task } + } +} + +impl Drop for Server { + fn drop(&mut self) { + self.task.abort(); + } +} + +async fn gateway_state(upstream: &str, metrics: &Metrics) -> AppState { + let id = DATABASE.fetch_add(1, Ordering::Relaxed); + let pool = create_pool_with_schema(Some(&format!("sqlite:file:metrics_{id}?mode=memory&cache=shared"))) + .await + .unwrap(); + let mut state = common::test_state(&common::test_config(upstream)); + state.exec_ctx = Arc::new( + ExecutionContext::new( + ConversationHandler::new(ConversationStore::new(pool.clone())), + ResponseHandler::new(ResponseStore::new(pool)), + Arc::new(reqwest::Client::new()), + upstream.to_owned(), + ) + .with_metrics(metrics.executor()), + ); + state.websocket_tracker = WebSocketTracker::with_metrics(WebSocketMetrics::new(&metrics.meter("agentic_server"))); + state +} + +async fn gateway(state: AppState) -> Server { + Server::start(build_router(state, &ServerConfig::from_env())).await +} + +fn request(prompt: &str, stream: bool, store: bool) -> Value { + json!({"model": "test-model", "input": prompt, "stream": stream, "store": store}) +} + +fn outcome(points: &[Point], outcome: &str) -> i64 { + total( + points, + "agentic.execution.count", + &[("agentic.execution.outcome", outcome)], + ) +} + +fn delivery(points: &[Point], delivery: &str) -> i64 { + total( + points, + "agentic.delivery.count", + &[("agentic.delivery.outcome", delivery)], + ) +} + +fn executions_total(points: &[Point]) -> i64 { + total(points, "agentic.execution.count", &[]) +} + +#[tokio::test] +async fn http_terminal_paths_each_finalize_once() { + let metrics = Metrics::new(); + let release = Arc::new(Notify::new()); + let upstream = upstream(Arc::clone(&release)).await; + let gateway = gateway(gateway_state(&upstream.url, &metrics).await).await; + let client = reqwest::Client::new(); + let url = format!("{}/v1/responses", gateway.url); + + let completed = client + .post(&url) + .json(&request("hello", true, true)) + .send() + .await + .unwrap(); + let body = completed.text().await.unwrap(); + assert!(body.contains("response.completed"), "{body}"); + + let failed = client + .post(&url) + .json(&request("FAIL", true, true)) + .send() + .await + .unwrap(); + assert_eq!(failed.status(), 200, "the failure is delivered in-band"); + assert!(failed.text().await.unwrap().contains("event: error")); + + let blocking = client + .post(&url) + .json(&request("hello", false, true)) + .send() + .await + .unwrap(); + assert_eq!(blocking.status(), 200); + blocking.bytes().await.unwrap(); + + let proxied = client + .post(&url) + .json(&request("hello", false, false)) + .send() + .await + .unwrap(); + assert_eq!(proxied.status(), 200); + proxied.bytes().await.unwrap(); + + let mut hanging = client + .post(&url) + .json(&request("HANG", true, true)) + .send() + .await + .unwrap() + .bytes_stream(); + let first = hanging.next().await.unwrap().unwrap(); + assert!(String::from_utf8_lossy(&first).contains("response.created")); + // The client disconnects mid-stream. + drop(hanging); + + let points = metrics + .wait_for("five executions", |points| executions_total(points) >= 5) + .await; + assert_eq!(executions_total(&points), 5, "{points:#?}"); + assert_eq!(total(&points, "agentic.delivery.count", &[]), 5); + assert_eq!(total(&points, "agentic.execution.active", &[]), 0); + assert_eq!(outcome(&points, "completed"), 3); + assert_eq!(outcome(&points, "failed"), 1); + assert_eq!(outcome(&points, "cancelled"), 1); + assert_eq!(delivery(&points, "delivered"), 4, "the in-band failure was delivered"); + assert_eq!(delivery(&points, "disconnected"), 1); + assert_eq!( + total( + &points, + "agentic.execution.count", + &[("agentic.route", "proxy"), ("agentic.execution.outcome", "completed")] + ), + 1 + ); + assert_eq!( + total( + &points, + "agentic.execution.count", + &[ + ("agentic.execution.outcome", "failed"), + ("error.type", "upstream_status") + ] + ), + 1 + ); +} + +async fn socket( + gateway: &Server, +) -> tokio_tungstenite::WebSocketStream> { + let url = format!("{}/v1/responses", gateway.url.replace("http:", "ws:")); + tokio_tungstenite::connect_async(url).await.unwrap().0 +} + +fn create(prompt: &str) -> Message { + let mut event = request(prompt, true, false); + event["type"] = json!("response.create"); + Message::Text(event.to_string().into()) +} + +/// Read events until `count` of them have type `event_type`. +async fn read_until( + socket: &mut tokio_tungstenite::WebSocketStream>, + event_type: &str, + count: usize, +) { + let mut seen = 0; + tokio::time::timeout(Duration::from_secs(5), async { + while seen < count { + if let Message::Text(text) = socket.next().await.unwrap().unwrap() { + let event: Value = serde_json::from_str(&text).unwrap(); + seen += usize::from(event["type"] == event_type); + } + } + }) + .await + .unwrap_or_else(|_| panic!("saw {seen} of {count} {event_type} events")); +} + +#[tokio::test] +async fn websocket_requests_count_once_each_on_one_connection() { + let metrics = Metrics::new(); + let upstream = upstream(Arc::new(Notify::new())).await; + let gateway = gateway(gateway_state(&upstream.url, &metrics).await).await; + let mut socket = socket(&gateway).await; + + for _ in 0..3 { + socket.send(create("hello")).await.unwrap(); + } + socket.send(create("FAIL")).await.unwrap(); + read_until(&mut socket, "response.completed", 3).await; + read_until(&mut socket, "error", 1).await; + + let open = metrics + .wait_for("four executions", |points| executions_total(points) >= 4) + .await; + assert_eq!(executions_total(&open), 4, "N requests, N executions"); + assert_eq!(outcome(&open, "completed"), 3); + assert_eq!(outcome(&open, "failed"), 1); + assert_eq!( + total(&open, "agentic.websocket.connections.active", &[]), + 1, + "one connection" + ); + assert_eq!(total(&open, "agentic.websocket.queue.wait.duration", &[]), 4); + assert_eq!(total(&open, "agentic.execution.active", &[]), 0); + // Retained WebSocket executions take the same first-* timings as HTTP + // streams: the upstream reader marks data, the event stream the rest. + assert_eq!(total(&open, "agentic.time_to_first_upstream_data", &[]), 3); + assert_eq!(total(&open, "agentic.time_to_first_text", &[]), 3); + assert_eq!(total(&open, "agentic.time_to_first_client_event", &[]), 4); + + socket.close(None).await.unwrap(); + let closed = metrics + .wait_for("closed connection", |points| { + total(points, "agentic.websocket.connections.active", &[]) == 0 + }) + .await; + assert_eq!(executions_total(&closed), 4, "closing counts nothing twice"); +} + +#[tokio::test] +async fn websocket_disconnect_cancels_active_and_queued_requests_once() { + let metrics = Metrics::new(); + let upstream = upstream(Arc::new(Notify::new())).await; + let gateway = gateway(gateway_state(&upstream.url, &metrics).await).await; + let mut socket = socket(&gateway).await; + + socket.send(create("HANG")).await.unwrap(); + read_until(&mut socket, "response.created", 1).await; + // Queued behind the hanging request on the default stream. + socket.send(create("hello")).await.unwrap(); + socket.send(Message::Ping("barrier".into())).await.unwrap(); + while !matches!(socket.next().await.unwrap().unwrap(), Message::Pong(_)) {} + drop(socket); + + let points = metrics + .wait_for("two executions", |points| executions_total(points) >= 2) + .await; + assert_eq!(outcome(&points, "cancelled"), 2); + assert_eq!(delivery(&points, "disconnected"), 2); + assert_eq!(total(&points, "agentic.execution.active", &[]), 0); + let closed = metrics + .wait_for("closed connection", |points| { + total(points, "agentic.websocket.connections.active", &[]) == 0 + }) + .await; + assert_eq!(executions_total(&closed), 2); +} + +#[tokio::test] +async fn websocket_drain_cancels_queued_requests_once_and_finishes_the_active_one() { + let metrics = Metrics::new(); + let release = Arc::new(Notify::new()); + let upstream = upstream(Arc::clone(&release)).await; + let state = gateway_state(&upstream.url, &metrics).await; + let shutdown = state.shutdown_token.clone(); + let gateway = gateway(state).await; + let mut socket = socket(&gateway).await; + + socket.send(create("HANG")).await.unwrap(); + read_until(&mut socket, "response.created", 1).await; + socket.send(create("hello")).await.unwrap(); + socket.send(Message::Ping("barrier".into())).await.unwrap(); + while !matches!(socket.next().await.unwrap().unwrap(), Message::Pong(_)) {} + + // Shutdown discards queued work; the active request may still finish. + shutdown.cancel(); + let points = metrics + .wait_for("queued execution", |points| executions_total(points) >= 1) + .await; + assert_eq!(outcome(&points, "cancelled"), 1); + assert_eq!(delivery(&points, "disconnected"), 1); + assert_eq!(total(&points, "agentic.execution.active", &[]), 1, "one still running"); + + release.notify_one(); + read_until(&mut socket, "response.completed", 1).await; + let points = metrics + .wait_for("both executions", |points| executions_total(points) >= 2) + .await; + assert_eq!(executions_total(&points), 2); + assert_eq!(outcome(&points, "completed"), 1); + assert_eq!(delivery(&points, "delivered"), 1); + assert_eq!(total(&points, "agentic.execution.active", &[]), 0); +} diff --git a/crates/agentic-server/tests/telemetry_metrics_e2e_test.rs b/crates/agentic-server/tests/telemetry_metrics_e2e_test.rs new file mode 100644 index 00000000..488efdbf --- /dev/null +++ b/crates/agentic-server/tests/telemetry_metrics_e2e_test.rs @@ -0,0 +1,366 @@ +//! The gateway binary, configured only through standard `OTEL_*` variables, +//! with trace sampling at zero, exporting to a local OTLP/HTTP stub. +//! +//! Metrics must not depend on sampling, carry the configured service name, +//! and finalize requests that are still in flight when the process receives +//! SIGTERM: the drain deadline abandons them, runtime shutdown drops them, +//! and the telemetry flush that follows exports their cancellation. + +#![cfg(unix)] + +use std::collections::BTreeMap; +use std::process::{Child, Command, Stdio}; +use std::sync::Arc; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::time::Duration; + +use axum::body::{Body, Bytes}; +use axum::response::{IntoResponse as _, Response}; +use futures::{SinkExt as _, StreamExt as _}; +use opentelemetry_proto::tonic::common::v1::KeyValue; +use opentelemetry_proto::tonic::common::v1::any_value::Value as AnyValue; +use opentelemetry_proto::tonic::metrics::v1::metric::Data; +use opentelemetry_proto::tonic::metrics::v1::number_data_point::Value as NumberValue; +use serde_json::{Value, json}; +use tokio::sync::Notify; +use tokio_tungstenite::tungstenite::Message; + +#[allow(dead_code)] +mod common; +#[path = "../../agentic-server-core/tests/execution_metrics/harness.rs"] +mod harness; +use common::otlp_stub::{OtlpStub, StubMode, service_name}; +use harness::{Point, PointValue, total}; + +const SERVICE: &str = "agentic-metrics-e2e"; +const USAGE: &str = r#"{"input_tokens":7,"input_tokens_details":{"cached_tokens":0},"output_tokens":2,"output_tokens_details":{"reasoning_tokens":0},"total_tokens":9}"#; + +/// Every instrument this scenario exercises. +const EXPECTED_INSTRUMENTS: &[&str] = &[ + "agentic.execution.count", + "agentic.execution.active", + "agentic.execution.duration", + "agentic.delivery.count", + "agentic.delivery.wait.duration", + "agentic.stage.duration", + "agentic.inference.rounds", + "gen_ai.client.token.usage", + "agentic.time_to_first_upstream_data", + "agentic.time_to_first_client_event", + "agentic.time_to_first_text", + "agentic.websocket.connections.active", + "agentic.websocket.queue.wait.duration", + "http.server.request.duration", + "http.server.active_requests", +]; + +/// Completes unless the prompt says `HANG`, which streams `response.created` +/// and then never finishes. +async fn upstream() -> (String, tokio::task::JoinHandle<()>) { + let never = Arc::new(Notify::new()); + let router = axum::Router::new().route( + "/v1/responses", + axum::routing::post(move |body: Bytes| { + let never = Arc::clone(&never); + async move { respond(&body, never) } + }), + ); + let listener = tokio::net::TcpListener::bind("127.0.0.1:0").await.unwrap(); + let url = format!("http://{}", listener.local_addr().unwrap()); + ( + url, + tokio::spawn(async move { axum::serve(listener, router).await.unwrap() }), + ) +} + +/// Like a real upstream, each response gets fresh item IDs: stored history +/// keys rows by public item ID, so a repeated ID cannot be stored twice (#385). +static ITEM: AtomicU64 = AtomicU64::new(0); + +fn respond(body: &[u8], never: Arc) -> Response { + let id = format!("msg_up_{}", ITEM.fetch_add(1, Ordering::Relaxed)); + let message = format!( + r#"{{"id":"{id}","type":"message","role":"assistant","status":"completed","content":[{{"type":"output_text","text":"hi","annotations":[]}}]}}"# + ); + let request: Value = serde_json::from_slice(body).unwrap(); + if request["stream"] != true { + let body = format!( + r#"{{"id":"resp_up","object":"response","created_at":0,"model":"m","status":"completed","output":[{message}],"usage":{USAGE}}}"# + ); + return ([("content-type", "application/json")], body).into_response(); + } + let head = "data: {\"type\":\"response.created\",\"sequence_number\":0,\"response\":{\"id\":\"resp_up\",\"status\":\"in_progress\",\"output\":[]}}\n\n"; + let tail = format!( + "data: {{\"type\":\"response.output_item.added\",\"sequence_number\":1,\"output_index\":0,\"item\":{{\"id\":\"{id}\",\"type\":\"message\",\"role\":\"assistant\",\"status\":\"in_progress\",\"content\":[]}}}}\n\n\ + data: {{\"type\":\"response.output_text.delta\",\"sequence_number\":2,\"output_index\":0,\"content_index\":0,\"delta\":\"hi\"}}\n\n\ + data: {{\"type\":\"response.output_item.done\",\"sequence_number\":3,\"output_index\":0,\"item\":{message}}}\n\n\ + data: {{\"type\":\"response.completed\",\"sequence_number\":4,\"response\":{{\"id\":\"resp_up\",\"status\":\"completed\",\"output\":[{message}],\"usage\":{USAGE}}}}}\n\n\ + data: [DONE]\n\n" + ); + let hang = String::from_utf8_lossy(body).contains("HANG"); + let rest = futures::stream::once(async move { + if hang { + never.notified().await; + } + Ok::<_, std::io::Error>(Bytes::from(tail)) + }); + let body = futures::stream::once(std::future::ready(Ok(Bytes::from_static(head.as_bytes())))).chain(rest); + ([("content-type", "text/event-stream")], Body::from_stream(body)).into_response() +} + +struct Gateway { + child: Child, + url: String, + home: tempfile::TempDir, +} + +impl Gateway { + fn spawn(llm: &str, otlp: &str) -> Self { + let home = tempfile::tempdir().unwrap(); + let port = std::net::TcpListener::bind("127.0.0.1:0") + .unwrap() + .local_addr() + .unwrap() + .port(); + let log = std::fs::File::create(home.path().join("server.log")).unwrap(); + let child = Command::new(env!("CARGO_BIN_EXE_agentic-server")) + .env_clear() + .env("HOME", home.path()) + .env("AGENTIC_API_HOME", home.path()) + .env("RUST_LOG", "info") + .env("OTEL_TRACES_EXPORTER", "otlp") + .env("OTEL_METRICS_EXPORTER", "otlp") + .env("OTEL_EXPORTER_OTLP_ENDPOINT", otlp) + .env("OTEL_SERVICE_NAME", SERVICE) + .env("OTEL_TRACES_SAMPLER", "parentbased_traceidratio") + .env("OTEL_TRACES_SAMPLER_ARG", "0") + .env("OTEL_BSP_SCHEDULE_DELAY", "50") + .args(["--llm-api-base", llm, "--skip-llm-ready-check"]) + .args(["--gateway-host", "127.0.0.1", "--gateway-port", &port.to_string()]) + .stdin(Stdio::null()) + .stdout(log.try_clone().unwrap()) + .stderr(log) + .spawn() + .expect("agentic-server starts"); + Self { + child, + url: format!("http://127.0.0.1:{port}"), + home, + } + } + + fn log(&self) -> String { + std::fs::read_to_string(self.home.path().join("server.log")).unwrap_or_default() + } + + async fn wait_ready(&self) { + let client = reqwest::Client::new(); + for _ in 0..500 { + if client.get(format!("{}/health", self.url)).send().await.is_ok() { + return; + } + tokio::time::sleep(Duration::from_millis(20)).await; + } + panic!("gateway did not start: {}", self.log()); + } + + async fn terminate(&mut self) { + let status = Command::new("kill") + .args(["-TERM", &self.child.id().to_string()]) + .status() + .unwrap(); + assert!(status.success()); + // Drain deadline (8 s), runtime shutdown (1 s), telemetry flush (3 s). + for _ in 0..1000 { + if let Some(status) = self.child.try_wait().unwrap() { + assert!(status.success(), "gateway exited with {status}: {}", self.log()); + return; + } + tokio::time::sleep(Duration::from_millis(20)).await; + } + panic!("gateway did not exit: {}", self.log()); + } +} + +impl Drop for Gateway { + fn drop(&mut self) { + let _ = self.child.kill(); + let _ = self.child.wait(); + } +} + +fn request(prompt: &str, stream: bool) -> Value { + json!({"model": "m", "input": prompt, "stream": stream, "store": true}) +} + +fn create(prompt: &str) -> Message { + let mut event = request(prompt, true); + event["store"] = json!(false); + event["type"] = json!("response.create"); + Message::Text(event.to_string().into()) +} + +type Socket = tokio_tungstenite::WebSocketStream>; + +async fn read_until(socket: &mut Socket, event_type: &str, count: usize) { + let mut seen = 0; + tokio::time::timeout(Duration::from_secs(10), async { + while seen < count { + if let Message::Text(text) = socket.next().await.unwrap().unwrap() { + let event: Value = serde_json::from_str(&text).unwrap(); + seen += usize::from(event["type"] == event_type); + } + } + }) + .await + .unwrap_or_else(|_| panic!("saw {seen} of {count} {event_type} events")); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn unsampled_gateway_exports_metrics_and_finalizes_shutdown_cancelled_requests() { + let (otlp, stub) = OtlpStub::spawn(StubMode::Accept).await; + let (llm, _llm) = upstream().await; + let mut gateway = Gateway::spawn(&llm, &otlp); + gateway.wait_ready().await; + let client = reqwest::Client::new(); + let url = format!("{}/v1/responses", gateway.url); + + // Completed over HTTP: streamed and blocking. + let streamed = client.post(&url).json(&request("hello", true)).send().await.unwrap(); + assert!(streamed.text().await.unwrap().contains("response.completed")); + let blocking = client.post(&url).json(&request("hello", false)).send().await.unwrap(); + assert_eq!(blocking.status(), 200, "{}", gateway.log()); + blocking.bytes().await.unwrap(); + + // Completed over WebSocket, twice on one connection. + let ws_url = format!("{}/v1/responses", gateway.url.replace("http:", "ws:")); + let (mut socket, _) = tokio_tungstenite::connect_async(&ws_url).await.unwrap(); + socket.send(create("hello")).await.unwrap(); + socket.send(create("hello")).await.unwrap(); + read_until(&mut socket, "response.completed", 2).await; + + // Still running at SIGTERM: one HTTP stream and one WebSocket request. + let mut in_flight = client + .post(&url) + .json(&request("HANG", true)) + .send() + .await + .unwrap() + .bytes_stream(); + assert!(String::from_utf8_lossy(&in_flight.next().await.unwrap().unwrap()).contains("response.created")); + socket.send(create("HANG")).await.unwrap(); + read_until(&mut socket, "response.created", 1).await; + + gateway.terminate().await; + drop((in_flight, socket)); + + let traces = stub.trace_exports().await; + let spans: usize = traces + .iter() + .flat_map(|export| &export.resource_spans) + .flat_map(|resource| &resource.scope_spans) + .map(|scope| scope.spans.len()) + .sum(); + assert_eq!(spans, 0, "OTEL_TRACES_SAMPLER_ARG=0 samples nothing"); + + let exports = stub.metric_exports().await; + let latest = exports.last().expect("metrics are flushed at shutdown"); + for resource in &latest.resource_metrics { + assert_eq!(service_name(resource.resource.as_ref()), Some(SERVICE)); + } + let points = otlp_points(latest); + harness::assert_allowed(&points); + for instrument in EXPECTED_INSTRUMENTS { + assert!( + points.iter().any(|point| point.name == *instrument), + "{instrument} was not exported" + ); + } + + let outcome = |outcome: &str| { + total( + &points, + "agentic.execution.count", + &[("agentic.execution.outcome", outcome)], + ) + }; + assert_eq!(total(&points, "agentic.execution.count", &[]), 6, "{points:#?}"); + assert_eq!(outcome("completed"), 4); + assert_eq!(outcome("cancelled"), 2, "both in-flight requests finalized at shutdown"); + assert_eq!( + total( + &points, + "agentic.delivery.count", + &[("agentic.delivery.outcome", "disconnected")] + ), + 2 + ); + assert_eq!( + total(&points, "agentic.execution.active", &[]), + 0, + "nothing left active" + ); + assert_eq!(total(&points, "agentic.websocket.connections.active", &[]), 0); + assert_eq!(total(&points, "agentic.websocket.queue.wait.duration", &[]), 3); + assert_eq!( + total(&points, "gen_ai.client.token.usage", &[("gen_ai.token.type", "input")]), + 4, + "one sample per completed upstream call" + ); + assert_eq!(total(&points, "http.server.active_requests", &[]), 0); +} + +fn otlp_points(export: &opentelemetry_proto::tonic::collector::metrics::v1::ExportMetricsServiceRequest) -> Vec { + let mut points = Vec::new(); + for metric in export + .resource_metrics + .iter() + .flat_map(|resource| &resource.scope_metrics) + .flat_map(|scope| &scope.metrics) + { + let mut push = |attributes: &[KeyValue], value| { + points.push(Point { + name: metric.name.clone(), + attributes: otlp_attributes(attributes), + value, + }); + }; + match &metric.data { + Some(Data::Sum(sum)) => { + for point in &sum.data_points { + let Some(NumberValue::AsInt(value)) = point.value else { + panic!("{}: every gateway sum is an integer", metric.name); + }; + push(&point.attributes, PointValue::Sum(value)); + } + } + Some(Data::Histogram(histogram)) => { + for point in &histogram.data_points { + let value = PointValue::Histogram { + count: point.count, + sum: point.sum.unwrap_or_default(), + }; + push(&point.attributes, value); + } + } + other => panic!("{}: unexpected data {other:?}", metric.name), + } + } + points +} + +fn otlp_attributes(attributes: &[KeyValue]) -> BTreeMap { + attributes + .iter() + .map(|attribute| { + let value = match attribute.value.as_ref().and_then(|value| value.value.as_ref()) { + Some(AnyValue::StringValue(value)) => value.clone(), + Some(AnyValue::BoolValue(value)) => value.to_string(), + Some(AnyValue::IntValue(value)) => value.to_string(), + Some(AnyValue::DoubleValue(value)) => value.to_string(), + other => panic!("{}: unexpected attribute value {other:?}", attribute.key), + }; + (attribute.key.clone(), value) + }) + .collect() +} diff --git a/deploy/otel/collector.yaml b/deploy/otel/collector.yaml new file mode 100644 index 00000000..d1b201c0 --- /dev/null +++ b/deploy/otel/collector.yaml @@ -0,0 +1,48 @@ +# Backend-neutral OpenTelemetry Collector for local gateway telemetry. +# +# Receives OTLP/HTTP from the gateway, prints every span and metric with the +# debug exporter, and serves metrics for Prometheus-compatible scrapers. +# Traces also go to Jaeger when started with `--profile jaeger`, which sets +# AGENTIC_OTEL_TRACE_EXPORTERS (see docker-compose.yaml). + +receivers: + otlp: + protocols: + http: + endpoint: 0.0.0.0:4318 + +processors: + memory_limiter: + check_interval: 1s + limit_mib: 400 + spike_limit_mib: 100 + batch: {} + +exporters: + debug: + verbosity: detailed + prometheus: + endpoint: 0.0.0.0:8889 + # Copies resource attributes such as service.name onto every series. + resource_to_telemetry_conversion: + enabled: true + otlp/jaeger: + endpoint: jaeger:4317 + tls: + insecure: true + +extensions: + health_check: + endpoint: 0.0.0.0:13133 + +service: + extensions: [health_check] + pipelines: + traces: + receivers: [otlp] + processors: [memory_limiter, batch] + exporters: ${env:AGENTIC_OTEL_TRACE_EXPORTERS} + metrics: + receivers: [otlp] + processors: [memory_limiter, batch] + exporters: [debug, prometheus] diff --git a/deploy/otel/docker-compose.yaml b/deploy/otel/docker-compose.yaml new file mode 100644 index 00000000..9a9785b4 --- /dev/null +++ b/deploy/otel/docker-compose.yaml @@ -0,0 +1,30 @@ +# Local, backend-neutral telemetry for the gateway. +# +# docker compose -f deploy/otel/docker-compose.yaml up -d +# docker compose -f deploy/otel/docker-compose.yaml --env-file deploy/otel/jaeger.env up -d # + Jaeger UI +# +# Then run the gateway with: +# OTEL_TRACES_EXPORTER=otlp OTEL_METRICS_EXPORTER=otlp \ +# OTEL_EXPORTER_OTLP_ENDPOINT=http://127.0.0.1:4318 agentic-server ... +# +# See docs/deploying/observability.md. + +services: + otel-collector: + image: otel/opentelemetry-collector-contrib:0.161.0@sha256:fd328de2552466ad78385e1b1289c3f2402b1c45f265b252aab1955b42845ac1 + command: ["--config=/etc/otelcol/collector.yaml"] + volumes: + - ./collector.yaml:/etc/otelcol/collector.yaml:ro + environment: + # `[debug]` by default; jaeger.env adds the Jaeger exporter. + AGENTIC_OTEL_TRACE_EXPORTERS: ${AGENTIC_OTEL_TRACE_EXPORTERS:-[debug]} + ports: + - "127.0.0.1:4318:4318" # OTLP/HTTP from the gateway + - "127.0.0.1:8889:8889" # Prometheus scrape endpoint + - "127.0.0.1:13133:13133" # health check + + jaeger: + profiles: [jaeger] + image: jaegertracing/jaeger:2.21.0@sha256:3d0ac795ff98aa04d1be04311d2dac6c25b4bfc8322dc02e53bc5b170c5018c3 + ports: + - "127.0.0.1:16686:16686" # UI diff --git a/deploy/otel/jaeger.env b/deploy/otel/jaeger.env new file mode 100644 index 00000000..98496771 --- /dev/null +++ b/deploy/otel/jaeger.env @@ -0,0 +1,4 @@ +# docker compose -f deploy/otel/docker-compose.yaml --env-file deploy/otel/jaeger.env up -d +# Starts Jaeger (UI on http://127.0.0.1:16686) and sends traces to it as well. +COMPOSE_PROFILES=jaeger +AGENTIC_OTEL_TRACE_EXPORTERS=[debug, otlp/jaeger] diff --git a/docs/deploying/observability.md b/docs/deploying/observability.md index c3958133..e05b3b15 100644 --- a/docs/deploying/observability.md +++ b/docs/deploying/observability.md @@ -6,9 +6,10 @@ selected the gateway creates no provider, exporter thread, or network connection, and only prints local logs as before. This page covers HTTP and execution traces, upstream context propagation, -standard HTTP request metrics, trace-correlated local logs, and the export -lifecycle from [#279](https://github.com/vllm-project/agentic-api/issues/279). -Gateway-specific metrics remain a later phase. +HTTP, execution, stage, token, timing, delivery, and WebSocket metrics, +trace-correlated local logs, the export lifecycle, a local Collector setup, +and measured overhead, from +[#279](https://github.com/vllm-project/agentic-api/issues/279). ## Enable export @@ -220,6 +221,16 @@ trace context are separate from this application-attribute contract. ### Metrics +Metrics are recorded by the same guards that finalize the spans above, so each +is recorded exactly once on every terminal path — completion, upstream failure, +client disconnect, and requests abandoned at shutdown — and **regardless of +the trace sampling decision**: an unsampled request is still counted. Every +attribute is one of the enumerated values below or a boolean. Instruments come +from two instrumentation scopes: `agentic_server` (HTTP and WebSocket +transport) and `agentic_core` (execution). + +#### HTTP + | Instrument | Type | Attributes | | --- | --- | --- | | `http.server.request.duration` (seconds) | histogram | `http.request.method`, `http.route`, `http.response.status_code`, `url.scheme` | @@ -229,8 +240,115 @@ Duration boundaries are the semantic-convention set extended with `30`, `60`, `120`, and `300` seconds because streamed inference responses routinely run for minutes. Both instruments are recorded exactly once per request from a guard attached to the response body, so a disconnecting client cannot leave -the active-request count drifting. Metrics are recorded regardless of the -trace sampling decision. +the active-request count drifting. + +#### Executions + +One execution is one `agentic.execute` span: an HTTP request the executor or +raw proxy handles, or one WebSocket `response.create`. + +| Instrument | Type | Unit | Attributes | +| --- | --- | --- | --- | +| `agentic.execution.count` | counter | `{execution}` | `agentic.api`, `agentic.route`, `agentic.stream`, `agentic.execution.outcome`, and `error.type` when the outcome is `failed` | +| `agentic.execution.duration` | histogram | `s` | Same as `agentic.execution.count` | +| `agentic.execution.active` | up-down counter | `{execution}` | `agentic.api`, `agentic.route`, `agentic.stream` | +| `agentic.delivery.count` | counter | `{execution}` | `agentic.api`, `agentic.route`, `agentic.stream`, `agentic.delivery.outcome` | + +Attribute values are the span's: see [Execution span](#execution-span). +An execution becomes active when the gateway accepts it — for WebSocket, when +the request is admitted to its connection's queue — and is finalized when its +span closes. At that moment the count, duration, and delivery outcome are +recorded once and the active count is released. Duration runs from acceptance +to finalization, so for a stream it includes client delivery. + +#### Stages, rounds, and tokens + +| Instrument | Type | Unit | Attributes | +| --- | --- | --- | --- | +| `agentic.stage.duration` | histogram | `s` | `agentic.stage`: `rehydrate`, `inference`, `tool`, `compaction`, or `persist`; `agentic.tool.type` on `tool` samples; `error.type` when the stage failed (a category from the list above) or `cancelled` when it was dropped unfinished | +| `agentic.inference.rounds` | histogram | `{round}` | `agentic.api` | +| `gen_ai.client.token.usage` | histogram | `{token}` | `gen_ai.operation.name`: `chat`; `gen_ai.token.type`: `input` or `output`; `agentic.api` | + +- An `inference` sample is one upstream round: sending the request and, for a + streamed round, reading its whole body. `persist` is recorded only when the + request asked for storage. `tool` covers gateway-executed built-in tools in + the Responses executor, one sample per tool call. Gateway-executed built-in + tools in the Messages loop are not timed yet. +- `agentic.inference.rounds` is recorded once per execution, however the loop + ended, when at least one round started. A multi-agent response records one + sample that counts every agent's rounds, so it can exceed the round cap. +- `gen_ai.client.token.usage` records one sample per token type for each + upstream call, from that call's own `usage` (compaction summaries + included), never from turn totals. When the upstream omits `usage` or a + count, nothing is recorded — the gateway never substitutes zero. For the + Messages API the input count adds `cache_creation_input_tokens` and + `cache_read_input_tokens` to `input_tokens`. +- `gen_ai.request.model`, `gen_ai.response.model`, and `gen_ai.provider.name` + are deliberately absent: model names are not a bounded dimension for a + gateway, and the gateway cannot know which provider serves its upstream. +- Explicit `/v1/responses/compact` requests record their stage and token + samples but no execution, as they have no `agentic.execute` span. + +#### First-data timings + +These describe streamed executor responses only; non-streaming requests and +the raw proxy route record none of them. Each is measured from the moment the +gateway accepted the execution, recorded at most once per execution, and +carries only `agentic.api`. None of them is labelled time to first token, +because they measure different boundaries: + +| Instrument (seconds, histogram) | Stops when | +| --- | --- | +| `agentic.time_to_first_upstream_data` | The first SSE line of the upstream response reaches the executor pipeline. | +| `agentic.time_to_first_client_event` | The executor's client-facing stream yields the first semantic event of the response, such as `response.created` or `message_start`, to the transport. An executor error frame is not a response event. | +| `agentic.time_to_first_text` | The executor's client-facing stream yields the first output-text delta (`response.output_text.delta`, or a Messages `text_delta`) to the transport. Reasoning and tool-call deltas do not count. | + +For a plain text response every client event derives from upstream data, so +`first_upstream_data ≤ first_client_event ≤ first_text`. Gateway-generated +events, such as MCP tool discovery, can reach the client before any upstream +data. + +#### Delivery and WebSocket + +| Instrument | Type | Unit | Recorded | +| --- | --- | --- | --- | +| `agentic.delivery.wait.duration` | histogram | `s` | Once per streamed execution that handed over at least one frame: the total time the transport took to ask for the next frame after taking one. This is how long a slow client — a full socket buffer or WebSocket send queue — held the execution back. A WebSocket response finalizes on its own task, so frames the connection takes after that are not included. Attribute: `agentic.api`. | +| `agentic.websocket.connections.active` | up-down counter | `{connection}` | Responses WebSocket connections being upgraded or open. No attributes. | +| `agentic.websocket.queue.wait.duration` | histogram | `s` | Once per admitted `response.create`: time until dispatch (near 0 when nothing was ahead of it) or until it was discarded. No attributes. | + +Each `response.create` is its own execution, so N requests on one connection +record N executions and one connection. + +#### Histogram boundaries + +| Instruments | Boundaries | +| --- | --- | +| Execution and stage durations | Powers of two from `0.01` to `327.68` s | +| First-data timings | The `gen_ai.server.time_to_first_token` semantic-convention set, plus `20` s | +| Delivery wait | `0.001` to `60` s | +| WebSocket queue wait | `0.001`, then the execution boundaries | +| Token usage | The `gen_ai.client.token.usage` semantic-convention set | +| Inference rounds | `1` to `10`, one agent's round cap | + +Temporality is cumulative. + +#### Cardinality contract + +Request, response, and conversation identifiers, tool names, model names, +URLs, and prompt or output text never become metric dimensions. The allow-list +of instruments, attribute keys, and attribute values in +[`crates/agentic-server-core/tests/execution_metrics/harness.rs`](https://github.com/vllm-project/agentic-api/blob/main/crates/agentic-server-core/tests/execution_metrics/harness.rs) +mirrors the tables on this page. Every metric test and the Collector smoke test +fail on anything outside it, so adding a dimension means updating the list and +this page together. + +#### Embedding applications + +`agentic-server-core` records through `ExecutorMetrics`, built from a `Meter`. +`ExecutionContext::new` and `ExecutionContext::from_config` bind it to the +global meter provider when they run, so register a provider first or pass +your own with `ExecutionContext::with_metrics(ExecutorMetrics::new(&meter))`. +Without a provider every instrument is a no-op. ## Sampling @@ -293,6 +411,80 @@ Correlated lines are written without ANSI colour. 12 s, well inside the 30 s termination grace period used by the Kubernetes manifests. Spans still buffered when the deadline passes are lost. +## Local Collector + +[`deploy/otel`](https://github.com/vllm-project/agentic-api/tree/main/deploy/otel) +runs a backend-neutral OpenTelemetry Collector (collector-contrib, pinned by +digest). It receives OTLP/HTTP, applies `memory_limiter` and `batch`, prints +every span and metric with the `debug` exporter, and serves the metrics in +Prometheus format with `service.name` on every series. All ports bind to +`127.0.0.1`. + +```bash +docker compose -f deploy/otel/docker-compose.yaml up -d + +OTEL_TRACES_EXPORTER=otlp OTEL_METRICS_EXPORTER=otlp \ +OTEL_EXPORTER_OTLP_ENDPOINT=http://127.0.0.1:4318 \ +OTEL_METRIC_EXPORT_INTERVAL=5000 \ +agentic-server --llm-api-base http://127.0.0.1:8000 + +docker compose -f deploy/otel/docker-compose.yaml logs -f otel-collector # every span and metric +curl -s http://127.0.0.1:8889/metrics | grep '^agentic_' # Prometheus format +``` + +The Prometheus exporter rewrites names in Prometheus style, for example +`agentic_execution_count_total` and `agentic_execution_duration_seconds_bucket`. + +To browse traces as well, add Jaeger (UI on ): + +```bash +docker compose -f deploy/otel/docker-compose.yaml --env-file deploy/otel/jaeger.env up -d +``` + +[`scripts/tests/otel-smoke.sh`](https://github.com/vllm-project/agentic-api/blob/main/scripts/tests/otel-smoke.sh) +checks the whole path against a running Collector. It sends streamed, +blocking, proxied, and WebSocket requests through a scripted upstream, stops +the gateway so it flushes, and verifies that every instrument arrived with the +run's `service.name` and only allow-listed attributes. CI runs it on every +change. + +## Overhead + +Measured with +[`scripts/otel-overhead.py`](https://github.com/vllm-project/agentic-api/blob/main/scripts/otel-overhead.py) +against a release build. The gateway used SQLite storage (every request is +rehydrated, executed, and persisted) and a local scripted upstream. Each +scenario ran 2,000 sequential requests per round after 200 warm-up requests, +over three rounds that alternated the two modes. *Enabled* exports traces for +every request (the default `parentbased_always_on` sampler) and all metrics +over OTLP/HTTP to the local Collector above. Host: 13th Gen Intel Core +i9-13980HX, Linux 6.6 (WSL2). + +| Scenario | Telemetry | p50 (ms) | p90 (ms) | p99 (ms) | Gateway CPU per request (ms) | Peak RSS (MiB) | +| --- | --- | ---: | ---: | ---: | ---: | ---: | +| Streaming | disabled | 0.96 | 1.18 | 13.03 | 0.86 | 31.5 | +| Streaming | enabled | 1.08 | 1.34 | 13.39 | 1.06 | 36.2 | +| Non-streaming | disabled | 0.87 | 1.11 | 12.52 | 0.76 | 31.5 | +| Non-streaming | enabled | 0.97 | 1.18 | 12.76 | 0.90 | 36.2 | + +Across two runs, enabling telemetry added 0.04–0.13 ms at p50 and +0.07–0.20 ms of gateway CPU per request, and about 5 MiB of peak RSS. +Run-to-run variation for one build was up to 0.1 ms at p50. The tail is +about 13 ms in both modes and does not change with telemetry. In the same +session, a build without these metrics (`main` at `5473e02`, execution traces +only) measured 0.01–0.13 ms lower at p50 and 0.01–0.14 ms less CPU per +request, with telemetry enabled or disabled. Each difference is within that +variation, but every one pointed the same way, so at this scale the metrics +cost at most about 0.1 ms per request. The streamed responses here are short +(five events). Longer streams add, per frame, one clock read and a few atomic +operations. + +```bash +cargo build --release -p agentic-server --bin agentic-server +docker compose -f deploy/otel/docker-compose.yaml up -d +scripts/otel-overhead.py --bin target/release/agentic-server --requests 2000 --warmup 200 --rounds 3 +``` + ## Kubernetes Add the variables to the gateway ConfigMap (see diff --git a/scripts/otel-overhead.py b/scripts/otel-overhead.py new file mode 100755 index 00000000..54ee0e15 --- /dev/null +++ b/scripts/otel-overhead.py @@ -0,0 +1,211 @@ +#!/usr/bin/env python3 +"""Measure gateway latency, CPU, and memory with telemetry disabled and enabled. + + cargo build --release -p agentic-server --bin agentic-server + docker compose -f deploy/otel/docker-compose.yaml up -d + scripts/otel-overhead.py --bin target/release/agentic-server + +Runs one gateway per mode against the same in-process scripted upstream, +alternating modes for --rounds rounds. Each round sends --requests sequential +streamed and blocking Responses requests (store=true, so every request is +rehydrated, executed, and persisted) after --warmup unmeasured ones. With +telemetry enabled the gateway exports traces (every request sampled) and +metrics over OTLP/HTTP to --otlp-endpoint. + +Reports per-request latency percentiles, gateway CPU time per request, and +the gateway's peak resident set size, as a Markdown table. + +The client re-arms TCP_QUICKACK after every read so that the gateway's +streamed writes never wait for a delayed ACK (the gateway does not set +TCP_NODELAY on accepted sockets); latency then reflects the gateway's own work. +Linux only. +""" + +from __future__ import annotations + +import argparse +import http.client +import json +import os +import signal +import socket +import statistics +import subprocess +import sys +import tempfile +import time +from pathlib import Path + +sys.path.insert(0, str(Path(__file__).resolve().parent / "tests")) + +import otel_fixtures # noqa: E402 + +TICKS = os.sysconf("SC_CLK_TCK") + + +def cpu_seconds(pid: int) -> float: + fields = Path(f"/proc/{pid}/stat").read_text().rsplit(")", 1)[1].split() + return (int(fields[11]) + int(fields[12])) / TICKS + + +def peak_rss_mib(pid: int) -> float: + for line in Path(f"/proc/{pid}/status").read_text().splitlines(): + if line.startswith("VmHWM:"): + return int(line.split()[1]) / 1024 + raise RuntimeError("no VmHWM") + + +def start_gateway(binary: str, upstream: int, enabled: bool, endpoint: str, home: str) -> tuple[subprocess.Popen, int]: + port = otel_fixtures.free_port() + env = {"PATH": os.environ["PATH"], "HOME": home, "AGENTIC_API_HOME": home, "RUST_LOG": "warn"} + if enabled: + env |= { + "OTEL_TRACES_EXPORTER": "otlp", + "OTEL_METRICS_EXPORTER": "otlp", + "OTEL_EXPORTER_OTLP_ENDPOINT": endpoint, + "OTEL_SERVICE_NAME": "agentic-overhead", + } + process = subprocess.Popen( + [ + binary, + "--llm-api-base", + f"http://127.0.0.1:{upstream}", + "--skip-llm-ready-check", + "--gateway-host", + "127.0.0.1", + "--gateway-port", + str(port), + ], + env=env, + stdout=subprocess.DEVNULL, + stderr=subprocess.DEVNULL, + ) + for _ in range(500): + try: + connection = http.client.HTTPConnection("127.0.0.1", port, timeout=1) + connection.request("GET", "/health") + if connection.getresponse().status == 200: + return process, port + except OSError: + time.sleep(0.02) + process.kill() + raise RuntimeError("gateway did not start") + + +class QuickAckClient: + """A keep-alive HTTP/1.1 client that acknowledges every segment at once.""" + + def __init__(self, port: int) -> None: + self.socket = socket.create_connection(("127.0.0.1", port), timeout=30) + self.socket.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1) + self.buffer = b"" + + def _receive(self) -> None: + self.socket.setsockopt(socket.IPPROTO_TCP, socket.TCP_QUICKACK, 1) + chunk = self.socket.recv(65536) + if not chunk: + raise RuntimeError("gateway closed the connection") + self.buffer += chunk + + def post(self, payload: dict) -> bytes: + body = json.dumps(payload).encode() + self.socket.sendall( + b"POST /v1/responses HTTP/1.1\r\nHost: gateway\r\nContent-Type: application/json\r\n" + + f"Content-Length: {len(body)}\r\n\r\n".encode() + + body + ) + while b"\r\n\r\n" not in self.buffer: + self._receive() + head, self.buffer = self.buffer.split(b"\r\n\r\n", 1) + status = head.split(b"\r\n", 1)[0] + if b" 200 " not in status: + raise RuntimeError(f"gateway answered {status!r}") + headers = dict(line.split(b": ", 1) for line in head.split(b"\r\n")[1:]) + headers = {key.lower(): value for key, value in headers.items()} + if b"content-length" in headers: + length = int(headers[b"content-length"]) + while len(self.buffer) < length: + self._receive() + response, self.buffer = self.buffer[:length], self.buffer[length:] + return response + # Chunked: every gateway response ends with the zero-length chunk. + while b"\r\n0\r\n\r\n" not in self.buffer: + self._receive() + response, self.buffer = self.buffer.split(b"\r\n0\r\n\r\n", 1) + return response + + def close(self) -> None: + self.socket.close() + + +def run_scenario(port: int, stream: bool, requests: int, warmup: int, pid: int) -> tuple[list[float], float]: + client = QuickAckClient(port) + payload = otel_fixtures.responses_request(stream=stream) + for _ in range(warmup): + client.post(payload) + latencies = [] + cpu_before = cpu_seconds(pid) + for _ in range(requests): + started = time.perf_counter() + client.post(payload) + latencies.append(time.perf_counter() - started) + cpu = (cpu_seconds(pid) - cpu_before) / requests + client.close() + return latencies, cpu + + +def percentile(values: list[float], fraction: float) -> float: + ordered = sorted(values) + return ordered[min(len(ordered) - 1, int(fraction * len(ordered)))] + + +def main() -> None: + parser = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter) + parser.add_argument("--bin", default="target/release/agentic-server") + parser.add_argument("--requests", type=int, default=1000) + parser.add_argument("--warmup", type=int, default=100) + parser.add_argument("--rounds", type=int, default=3) + parser.add_argument("--otlp-endpoint", default="http://127.0.0.1:4318") + args = parser.parse_args() + + upstream_port = otel_fixtures.free_port() + otel_fixtures.serve_upstream(upstream_port) + results: dict[tuple[str, str], dict] = {} + for round_ in range(args.rounds): + for enabled in (False, True): + mode = "enabled" if enabled else "disabled" + with tempfile.TemporaryDirectory() as home: + process, port = start_gateway(args.bin, upstream_port, enabled, args.otlp_endpoint, home) + try: + for stream in (True, False): + scenario = "streaming" if stream else "non-streaming" + latencies, cpu = run_scenario(port, stream, args.requests, args.warmup, process.pid) + entry = results.setdefault((scenario, mode), {"latencies": [], "cpu": [], "rss": []}) + entry["latencies"] += latencies + entry["cpu"].append(cpu) + results[("streaming", mode)]["rss"].append(peak_rss_mib(process.pid)) + finally: + process.send_signal(signal.SIGTERM) + process.wait(timeout=30) + print(f"round {round_ + 1}/{args.rounds}: {mode} done", file=sys.stderr) + + print("| Scenario | Telemetry | p50 (ms) | p90 (ms) | p99 (ms) | CPU / request (ms) | Peak RSS (MiB) |") + print("| --- | --- | ---: | ---: | ---: | ---: | ---: |") + for scenario in ("streaming", "non-streaming"): + for mode in ("disabled", "enabled"): + entry = results[(scenario, mode)] + latencies = entry["latencies"] + rss = results[("streaming", mode)]["rss"] + print( + f"| {scenario} | {mode} " + f"| {percentile(latencies, 0.5) * 1e3:.2f} " + f"| {percentile(latencies, 0.9) * 1e3:.2f} " + f"| {percentile(latencies, 0.99) * 1e3:.2f} " + f"| {statistics.median(entry['cpu']) * 1e3:.3f} " + f"| {statistics.median(rss):.1f} |" + ) + print(json.dumps({"requests": args.requests, "rounds": args.rounds}), file=sys.stderr) + + +if __name__ == "__main__": + main() diff --git a/scripts/tests/otel-smoke.sh b/scripts/tests/otel-smoke.sh new file mode 100755 index 00000000..f56816c4 --- /dev/null +++ b/scripts/tests/otel-smoke.sh @@ -0,0 +1,102 @@ +#!/usr/bin/env bash +# End-to-end check of gateway telemetry against the local Collector. +# +# docker compose -f deploy/otel/docker-compose.yaml up -d +# scripts/tests/otel-smoke.sh +# +# Starts a scripted upstream and the gateway exporting OTLP to the Collector, +# sends streamed, blocking, proxied, and WebSocket requests, stops the gateway +# so it flushes, then checks the Collector's debug output and Prometheus +# endpoint: every gateway instrument arrived with this run's service.name and +# only allow-listed attribute keys and values. +# +# AGENTIC_SERVER_BIN selects a prebuilt gateway; otherwise it is built with +# cargo. Requires docker, curl, and python3. +set -euo pipefail + +root=$(cd "$(dirname "${BASH_SOURCE[0]}")/../.." && pwd) +if docker compose version >/dev/null 2>&1; then + compose=(docker compose -f "$root/deploy/otel/docker-compose.yaml") +else + compose=(docker-compose -f "$root/deploy/otel/docker-compose.yaml") +fi +fixtures="$root/scripts/tests/otel_fixtures.py" +# Unique per run, so output left by earlier runs cannot satisfy the check. +service="agentic-otel-smoke-$$" +work=$(mktemp -d) +pids=() + +cleanup() { + for pid in "${pids[@]}"; do + kill "$pid" 2>/dev/null || true + done + rm -rf "$work" +} +trap cleanup EXIT + +wait_for() { + local what=$1 url=$2 + for _ in $(seq 1 150); do + if curl -fs -o /dev/null "$url"; then + return 0 + fi + sleep 0.2 + done + echo "timed out waiting for $what at $url" >&2 + return 1 +} + +wait_for "the Collector (docker compose -f deploy/otel/docker-compose.yaml up -d)" http://127.0.0.1:13133/ + +bin=${AGENTIC_SERVER_BIN:-} +if [[ -z "$bin" ]]; then + cargo build --quiet --manifest-path "$root/Cargo.toml" -p agentic-server --bin agentic-server + bin="$root/target/debug/agentic-server" +fi + +upstream_port=$(python3 -c 'import socket; s=socket.socket(); s.bind(("127.0.0.1", 0)); print(s.getsockname()[1])') +gateway_port=$(python3 -c 'import socket; s=socket.socket(); s.bind(("127.0.0.1", 0)); print(s.getsockname()[1])') + +python3 "$fixtures" upstream "$upstream_port" & +pids+=($!) +wait_for "the scripted upstream" "http://127.0.0.1:$upstream_port/health" + +env \ + AGENTIC_API_HOME="$work" \ + RUST_LOG=warn \ + OTEL_TRACES_EXPORTER=otlp \ + OTEL_METRICS_EXPORTER=otlp \ + OTEL_EXPORTER_OTLP_ENDPOINT=http://127.0.0.1:4318 \ + OTEL_SERVICE_NAME="$service" \ + "$bin" \ + --llm-api-base "http://127.0.0.1:$upstream_port" \ + --skip-llm-ready-check \ + --gateway-host 127.0.0.1 \ + --gateway-port "$gateway_port" \ + >"$work/gateway.log" 2>&1 & +gateway_pid=$! +pids+=("$gateway_pid") +wait_for "the gateway" "http://127.0.0.1:$gateway_port/health" + +python3 "$fixtures" requests "$gateway_port" + +# SIGTERM drains the gateway and flushes both signals before it exits. +kill -TERM "$gateway_pid" +if ! wait "$gateway_pid"; then + echo "gateway exited unsuccessfully:" >&2 + cat "$work/gateway.log" >&2 + exit 1 +fi + +# The Collector batches before exporting; poll until this run's metrics show up. +for _ in $(seq 1 50); do + "${compose[@]}" logs --no-color otel-collector >"$work/collector.log" 2>&1 + curl -fsS http://127.0.0.1:8889/metrics >"$work/prometheus.txt" + if grep -q "service.name: Str($service)" "$work/collector.log" && + grep -q "service_name=\"$service\"" "$work/prometheus.txt"; then + break + fi + sleep 0.2 +done + +python3 "$fixtures" check "$service" "$work/collector.log" "$work/prometheus.txt" diff --git a/scripts/tests/otel_fixtures.py b/scripts/tests/otel_fixtures.py new file mode 100755 index 00000000..2bf07adc --- /dev/null +++ b/scripts/tests/otel_fixtures.py @@ -0,0 +1,335 @@ +#!/usr/bin/env python3 +"""Fixtures for the gateway telemetry smoke test and overhead benchmark. + +Standard library only. Subcommands: + + upstream PORT serve a scripted OpenAI Responses upstream + requests GATEWAY_PORT send streamed, blocking, proxied, and WebSocket requests + check SERVICE LOG METRICS verify the Collector's debug log and Prometheus output + +The metric allow-list is read from the Rust test harness, so the smoke test +and `cargo test` enforce the same cardinality contract. +""" + +from __future__ import annotations + +import base64 +import http.client +import itertools +import json +import os +import re +import socket +import sys +import threading +from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer +from pathlib import Path + +ROOT = Path(__file__).resolve().parents[2] +HARNESS = ROOT / "crates/agentic-server-core/tests/execution_metrics/harness.rs" + +USAGE = { + "input_tokens": 7, + "input_tokens_details": {"cached_tokens": 0}, + "output_tokens": 2, + "output_tokens_details": {"reasoning_tokens": 0}, + "total_tokens": 9, +} +MESSAGE = { + "type": "message", + "role": "assistant", + "status": "completed", + "content": [{"type": "output_text", "text": "hi", "annotations": []}], +} + + +_ITEM_IDS = itertools.count() + + +def message() -> dict: + """An assistant message with a fresh item ID, as a real upstream sends. + + The gateway keys stored history rows by public item ID, so a repeated ID + cannot be stored twice (#385). + """ + return {**MESSAGE, "id": f"msg_up_{next(_ITEM_IDS)}"} + + +def sse_body() -> bytes: + item = message() + events = [ + {"type": "response.created", "response": {"id": "resp_up", "status": "in_progress", "output": []}}, + { + "type": "response.output_item.added", + "output_index": 0, + "item": {**item, "status": "in_progress", "content": []}, + }, + {"type": "response.output_text.delta", "output_index": 0, "content_index": 0, "delta": "hi"}, + {"type": "response.output_item.done", "output_index": 0, "item": item}, + { + "type": "response.completed", + "response": {"id": "resp_up", "status": "completed", "output": [item], "usage": USAGE}, + }, + ] + lines = [f"data: {json.dumps({**event, 'sequence_number': n})}\n\n" for n, event in enumerate(events)] + return ("".join(lines) + "data: [DONE]\n\n").encode() + + +def json_body() -> bytes: + body = { + "id": "resp_up", + "object": "response", + "created_at": 0, + "model": "test-model", + "status": "completed", + "output": [message()], + "usage": USAGE, + } + return json.dumps(body).encode() + + +class Upstream(BaseHTTPRequestHandler): + """Completes every Responses request; keeps connections alive.""" + + protocol_version = "HTTP/1.1" + + def setup(self) -> None: + super().setup() + # Headers and body are separate writes; without this, Nagle's algorithm + # and delayed ACKs add ~40 ms to every keep-alive response. + self.connection.setsockopt(socket.IPPROTO_TCP, socket.TCP_NODELAY, 1) + + def do_GET(self) -> None: # noqa: N802 - http.server API + self._send(200, "application/json", b"{}") + + def do_POST(self) -> None: # noqa: N802 - http.server API + length = int(self.headers.get("content-length", "0")) + request = json.loads(self.rfile.read(length) or b"{}") + if request.get("stream"): + self._send(200, "text/event-stream", sse_body()) + else: + self._send(200, "application/json", json_body()) + + def _send(self, status: int, content_type: str, body: bytes) -> None: + self.send_response(status) + self.send_header("content-type", content_type) + self.send_header("content-length", str(len(body))) + self.end_headers() + self.wfile.write(body) + + def log_message(self, *_args: object) -> None: + pass + + +def serve_upstream(port: int) -> ThreadingHTTPServer: + server = ThreadingHTTPServer(("127.0.0.1", port), Upstream) + server.daemon_threads = True + threading.Thread(target=server.serve_forever, daemon=True).start() + return server + + +def free_port() -> int: + with socket.socket() as probe: + probe.bind(("127.0.0.1", 0)) + return probe.getsockname()[1] + + +def responses_request(stream: bool, store: bool = True) -> dict: + return {"model": "test-model", "input": "say hi", "stream": stream, "store": store} + + +def post(connection: http.client.HTTPConnection, payload: dict) -> bytes: + connection.request( + "POST", "/v1/responses", body=json.dumps(payload), headers={"content-type": "application/json"} + ) + response = connection.getresponse() + body = response.read() + if response.status != 200: + raise RuntimeError(f"gateway answered {response.status}: {body[:200]!r}") + return body + + +class WebSocket: + """A minimal RFC 6455 client: text frames out, frames in.""" + + def __init__(self, port: int, path: str = "/v1/responses") -> None: + self.socket = socket.create_connection(("127.0.0.1", port)) + self.reader = self.socket.makefile("rb") + key = base64.b64encode(os.urandom(16)).decode() + self.socket.sendall( + ( + f"GET {path} HTTP/1.1\r\nHost: 127.0.0.1:{port}\r\nUpgrade: websocket\r\n" + f"Connection: Upgrade\r\nSec-WebSocket-Key: {key}\r\nSec-WebSocket-Version: 13\r\n\r\n" + ).encode() + ) + status = self.reader.readline() + if b" 101 " not in status: + raise RuntimeError(f"websocket upgrade failed: {status!r}") + while self.reader.readline() not in (b"\r\n", b""): + pass + + def send_text(self, text: str) -> None: + self._send(0x1, text.encode()) + + def _send(self, opcode: int, payload: bytes) -> None: + mask = os.urandom(4) + header = bytes([0x80 | opcode]) + if len(payload) < 126: + header += bytes([0x80 | len(payload)]) + elif len(payload) < 1 << 16: + header += bytes([0x80 | 126]) + len(payload).to_bytes(2, "big") + else: + header += bytes([0x80 | 127]) + len(payload).to_bytes(8, "big") + masked = bytes(byte ^ mask[i % 4] for i, byte in enumerate(payload)) + self.socket.sendall(header + mask + masked) + + def receive_json(self) -> dict: + while True: + first, second = self.reader.read(2) + opcode, length = first & 0x0F, second & 0x7F + if length == 126: + length = int.from_bytes(self.reader.read(2), "big") + elif length == 127: + length = int.from_bytes(self.reader.read(8), "big") + payload = self.reader.read(length) + if opcode == 0x1: + return json.loads(payload) + if opcode == 0x9: + self._send(0xA, payload) + elif opcode == 0x8: + raise RuntimeError("websocket closed by the gateway") + + def complete(self) -> None: + """Send one response.create and read until it completes.""" + self.send_text(json.dumps({**responses_request(True, store=False), "type": "response.create"})) + while (event := self.receive_json())["type"] != "response.completed": + if event["type"] == "error": + raise RuntimeError(f"websocket request failed: {event}") + + def close(self) -> None: + self._send(0x8, b"") + self.socket.close() + + +def send_smoke_requests(gateway_port: int) -> None: + connection = http.client.HTTPConnection("127.0.0.1", gateway_port, timeout=30) + body = post(connection, responses_request(stream=True)) + assert b"response.completed" in body, body[-200:] + post(connection, responses_request(stream=False)) + post(connection, responses_request(stream=False, store=False)) # proxied + connection.close() + socket_ = WebSocket(gateway_port) + socket_.complete() + socket_.complete() + socket_.close() + + +# ---------------------------------------------------------------- checking + + +def _rust_string_list(text: str) -> list[str]: + return re.findall(r'"([^"]*)"', text) + + +def load_allow_list() -> tuple[dict[str, list[str]], dict[str, list[str]]]: + """Parse INSTRUMENT_KEYS and KEY_VALUES from the Rust test harness.""" + source = HARNESS.read_text() + tables = {} + for name in ("INSTRUMENT_KEYS", "KEY_VALUES"): + block = re.search(rf"const {name}: &\[\(&str, &\[&str\]\)\] = &\[(.*?)\n\];", source, re.S) + if block is None: + raise SystemExit(f"cannot find {name} in {HARNESS}") + entries = re.findall(r'\(\s*"([^"]+)",\s*&\[(.*?)\],?\s*\)', block.group(1), re.S) + tables[name] = {key: _rust_string_list(values) for key, values in entries} + return tables["INSTRUMENT_KEYS"], tables["KEY_VALUES"] + + +def value_allowed(key_values: dict[str, list[str]], key: str, value: str) -> bool: + if key in key_values: + return value in key_values[key] + if key == "http.route": + return value.startswith("/") and "?" not in value + if key == "http.response.status_code": + return value.isdigit() and 100 <= int(value) <= 599 + return False + + +_ATTRIBUTE = re.compile(r"^\s*-> ([^:]+): (?:Str|Bool|Int|Double)\((.*)\)$") +_DATA_POINT = re.compile(r"^\w*DataPoints #\d+$") + + +def parse_debug_metrics(log: str) -> list[tuple[str | None, str | None, dict[str, str]]]: + """(service.name, metric, attributes) for each data point in a detailed debug log. + + A data point's attribute block is printed only when it has attributes. + """ + points: list[tuple[str | None, str | None, dict[str, str]]] = [] + service = metric = None + section = None + attributes: dict[str, str] = {} + for raw in log.splitlines(): + line = raw.split("| ", 1)[1] if "| " in raw else raw + stripped = line.strip() + if stripped == "Resource attributes:": + section, service = "resource", None + elif stripped == "Descriptor:": + section = "descriptor" + elif _DATA_POINT.match(stripped): + section, attributes = None, {} + points.append((service, metric, attributes)) + elif stripped == "Data point attributes:": + section = "point" + elif match := _ATTRIBUTE.match(line): + if section == "resource" and match.group(1) == "service.name": + service = match.group(2) + elif section == "point": + attributes[match.group(1)] = match.group(2) + elif stripped.startswith("-> Name: ") and section == "descriptor": + metric = stripped.removeprefix("-> Name: ") + elif not stripped.startswith("->") and section == "point": + section = None + return points + + +def check(service: str, log_path: str, prometheus_path: str) -> None: + instrument_keys, key_values = load_allow_list() + points = [(metric, attrs) for svc, metric, attrs in parse_debug_metrics(Path(log_path).read_text()) if svc == service] + if not points: + raise SystemExit(f"the Collector printed no metrics for service.name={service}") + problems = [] + for metric, attributes in points: + if metric not in instrument_keys: + problems.append(f"unlisted instrument {metric}") + continue + for key, value in attributes.items(): + if key not in instrument_keys[metric]: + problems.append(f"{metric}: unlisted attribute {key}") + elif not value_allowed(key_values, key, value): + problems.append(f"{metric}: {key}={value!r} outside the allowed values") + seen = {metric for metric, _ in points} + missing = sorted(set(instrument_keys) - seen) + if missing: + problems.append(f"instruments missing from the Collector output: {missing}") + prometheus = Path(prometheus_path).read_text() + if not re.search(rf'^agentic_execution_count\w*\{{[^}}]*service_name="{re.escape(service)}"', prometheus, re.M): + problems.append("the Prometheus endpoint has no agentic_execution_count series for this service") + if problems: + raise SystemExit("telemetry smoke check failed:\n " + "\n ".join(problems)) + print(f"ok: {len(seen)} instruments, {len(points)} data points, all allow-listed, service.name={service}") + + +def main() -> None: + command, *args = sys.argv[1:] or ["help"] + if command == "upstream": + serve_upstream(int(args[0])) + threading.Event().wait() + elif command == "requests": + send_smoke_requests(int(args[0])) + elif command == "check": + check(*args) + else: + raise SystemExit(__doc__) + + +if __name__ == "__main__": + main() diff --git a/scripts/tests/test_otel_fixtures.py b/scripts/tests/test_otel_fixtures.py new file mode 100644 index 00000000..5859375c --- /dev/null +++ b/scripts/tests/test_otel_fixtures.py @@ -0,0 +1,110 @@ +"""Tests for the telemetry smoke checker in otel_fixtures.py.""" + +import sys +import tempfile +import unittest +from pathlib import Path + +sys.path.insert(0, str(Path(__file__).resolve().parent)) + +import otel_fixtures # noqa: E402 + +SERVICE = "agentic-test" + + +def resource(service: str) -> list[str]: + return [ + "info\tResourceMetrics #0", + "Resource attributes:", + f" -> service.name: Str({service})", + "ScopeMetrics #0", + "InstrumentationScope agentic_core ", + ] + + +def metric(name: str, attributes: dict[str, str] | None = None) -> list[str]: + lines = ["Metric #0", "Descriptor:", f" -> Name: {name}", " -> DataType: Sum", "NumberDataPoints #0"] + if attributes: + lines.append("Data point attributes:") + lines += [f" -> {key}: Str({value})" for key, value in attributes.items()] + return [*lines, "StartTimestamp: 2026-01-01 00:00:00 +0000 UTC", "Value: 1"] + + +def complete_log(extra: list[str] | None = None) -> str: + """One point for every allow-listed instrument, as the Collector prints them.""" + instruments, _ = otel_fixtures.load_allow_list() + lines = resource(SERVICE) + for name in instruments: + lines += metric(name) + lines += extra or [] + return "\n".join(f"otel-collector-1 | {line}" for line in lines) + + +PROMETHEUS = f'agentic_execution_count_total{{agentic_api="responses",service_name="{SERVICE}"}} 1\n' + + +def run_check(log: str, prometheus: str = PROMETHEUS) -> None: + with tempfile.TemporaryDirectory() as directory: + log_path, metrics_path = Path(directory, "collector.log"), Path(directory, "metrics.txt") + log_path.write_text(log) + metrics_path.write_text(prometheus) + otel_fixtures.check(SERVICE, str(log_path), str(metrics_path)) + + +class AllowListTest(unittest.TestCase): + def test_reads_the_rust_harness_tables(self) -> None: + instruments, values = otel_fixtures.load_allow_list() + self.assertIn("agentic.execution.count", instruments) + self.assertEqual(instruments["agentic.websocket.connections.active"], []) + self.assertEqual(values["agentic.api"], ["responses", "messages"]) + self.assertIn("cancelled", values["error.type"]) + + +class ParseTest(unittest.TestCase): + def test_points_without_attributes_are_still_points(self) -> None: + log = "\n".join(resource(SERVICE) + metric("agentic.execution.active") + metric("a", {"k": "v"})) + self.assertEqual( + otel_fixtures.parse_debug_metrics(log), + [(SERVICE, "agentic.execution.active", {}), (SERVICE, "a", {"k": "v"})], + ) + + def test_points_belong_to_their_resource(self) -> None: + log = "\n".join(resource("other") + metric("a") + resource(SERVICE) + metric("b")) + self.assertEqual( + [(service, name) for service, name, _ in otel_fixtures.parse_debug_metrics(log)], + [("other", "a"), (SERVICE, "b")], + ) + + +class CheckTest(unittest.TestCase): + def test_accepts_every_instrument_with_allowed_attributes(self) -> None: + run_check(complete_log(metric("agentic.execution.count", {"agentic.api": "responses"}))) + + def test_rejects_an_unlisted_attribute_key(self) -> None: + with self.assertRaisesRegex(SystemExit, "unlisted attribute response.id"): + run_check(complete_log(metric("agentic.execution.count", {"response.id": "resp_1"}))) + + def test_rejects_an_unlisted_attribute_value(self) -> None: + with self.assertRaisesRegex(SystemExit, "outside the allowed values"): + run_check(complete_log(metric("agentic.execution.count", {"agentic.api": "gpt-4o"}))) + + def test_rejects_an_unlisted_instrument(self) -> None: + with self.assertRaisesRegex(SystemExit, "unlisted instrument agentic.surprise"): + run_check(complete_log(metric("agentic.surprise"))) + + def test_rejects_missing_instruments(self) -> None: + log = "\n".join(resource(SERVICE) + metric("agentic.execution.count")) + with self.assertRaisesRegex(SystemExit, "instruments missing"): + run_check(log) + + def test_ignores_other_services(self) -> None: + log = complete_log() + "\n" + "\n".join(resource("other") + metric("agentic.surprise")) + run_check(log) + + def test_requires_the_prometheus_series(self) -> None: + with self.assertRaisesRegex(SystemExit, "Prometheus endpoint"): + run_check(complete_log(), prometheus="") + + +if __name__ == "__main__": + unittest.main()