diff --git a/crates/libsy-llm-client/src/run.rs b/crates/libsy-llm-client/src/run.rs index 8103a3bb6..8561816e7 100644 --- a/crates/libsy-llm-client/src/run.rs +++ b/crates/libsy-llm-client/src/run.rs @@ -130,17 +130,15 @@ fn emit_routing_observations( let (Some(observer), Some(observations)) = (observer, observations) else { return; }; - let mut answer_observation = None; + let mut answer_observed = false; for observation in observations.lock().drain(..) { - if answer_observation.is_none() && answered_model == Some(&observation.selected_model) { - answer_observation = Some(observation); + if !answer_observed && answered_model == Some(&observation.selected_model) { + answer_observed = true; + observer(RunObservation::AnswerCall(observation)); } else { observer(RunObservation::LlmCall(observation)); } } - if let Some(observation) = answer_observation { - observer(RunObservation::AnswerCall(observation)); - } } /// Serve one offloaded call and fulfill its promise. @@ -652,6 +650,32 @@ mod tests { Ok(()) } + #[test] + fn answer_observation_keeps_call_order() { + let pending = Some(Arc::new(Mutex::new( + ["answer", "judge"] + .map(|model| LlmCallObservation { + selected_model: model.into(), + is_success: true, + duration: std::time::Duration::ZERO, + usage: None, + }) + .into(), + ))); + let emitted = Arc::new(Mutex::new(Vec::new())); + let captured = Arc::clone(&emitted); + let observer: RunObserver = Arc::new(move |event| captured.lock().push(event)); + let answer = ModelId::from("answer"); + + emit_routing_observations(&Some(observer), &pending, Some(&answer)); + + assert!(matches!( + &emitted.lock()[..], + [RunObservation::AnswerCall(answer), RunObservation::LlmCall(judge)] + if answer.selected_model == "answer" && judge.selected_model == "judge" + )); + } + #[tokio::test] async fn each_fallback_candidate_receives_only_its_own_prompt() -> Result<()> { let client = Arc::new(CandidateClient { diff --git a/crates/switchyard-nemo-relay-plugin/README.md b/crates/switchyard-nemo-relay-plugin/README.md index e017f5893..ce74bb02f 100644 --- a/crates/switchyard-nemo-relay-plugin/README.md +++ b/crates/switchyard-nemo-relay-plugin/README.md @@ -155,10 +155,10 @@ backend from that format rather than translating a route to a different provider API. When one upstream model must serve multiple caller formats, declare a target and route for each corresponding client format. -The plugin emits a routing request mark, routing-model call marks, measured -routing-overhead marks, and a selected-model decision mark. Token usage is -emitted as Switchyard metrics for both routing-model and answer-model calls; -Relay retains ownership of the outer LLM lifecycle. +The plugin emits routing request, model-call, measured-overhead, and decision +marks. Call marks distinguish routing from answer calls; decisions distinguish +selected from served models. Token metrics cover both call roles, while Relay +retains ownership of the outer LLM lifecycle. ## Observability @@ -166,8 +166,9 @@ When Relay is configured with OTLP logs and metrics exporters, the plugin emits typed telemetry through Relay's native plugin runtime: - Routing request, decision, and overhead marks are Info logs. -- Per-routing-model call marks are Debug logs, including their outcome and - latency, but not token usage. +- Per-model call marks are Debug logs with `call_role`, outcome, and latency, + but no token usage. Streaming marks cover stream creation; later failures are + reported separately. - Terminal routing and response-finalization failures are Error logs. Their payload contains only the safe Switchyard failure summary; it excludes provider response bodies and free-form provider messages. @@ -197,9 +198,11 @@ meaning requires a new schema version. | `switchyard.routing.requested` | `algorithm` | | `switchyard.routing.llm_call` | `call_index`, `selected_model`, `call_role`, `outcome`, `latency_ms` | | `switchyard.routing.overhead` | `latency_ms` | -| `switchyard.routing.decision` | `algorithm`, `selected_model` | +| `switchyard.routing.decision` | `algorithm`, `selected_model`, nullable `served_model`, nullable `fallback_used` | | `switchyard.routing.error` | `failure_kind`; optional `category`, `phase`, `upstream_status`, and `target` | +`served_model` and `fallback_used` are `null` when serving metadata is unavailable. + ## Failure policy `switchyard-llm-client` owns provider retry and route-candidate fallback diff --git a/crates/switchyard-nemo-relay-plugin/src/runtime.rs b/crates/switchyard-nemo-relay-plugin/src/runtime.rs index 136ec2a88..f9e675ef4 100644 --- a/crates/switchyard-nemo-relay-plugin/src/runtime.rs +++ b/crates/switchyard-nemo-relay-plugin/src/runtime.rs @@ -203,11 +203,15 @@ impl SwitchyardRuntime { match route.execute(request, Some(observer)).await { Ok(output) => { self.emit_observations(&mut events, take_observations(&observations), &metadata); + let served_model = output.response.served_model().map(|model| model.as_str()); events.push(RoutingEvent::Mark(RoutingMark { name: "switchyard.routing.decision".into(), data: json!({ "algorithm": route.algorithm_name(), - "selected_model": output.selected_model, + "selected_model": output.selected_model.as_str(), + "served_model": served_model, + "fallback_used": served_model + .map(|model| model != output.selected_model.as_str()), }), metadata, severity: Some(LogSeverity::Info), @@ -264,6 +268,21 @@ impl SwitchyardRuntime { events.push(routing_overhead_metric(latency_ms, metadata.clone())); } RunObservation::AnswerCall(call) => { + call_index += 1; + let outcome = if call.is_success { "ok" } else { "error" }; + let latency_ms = call.duration.as_secs_f64() * 1_000.0; + events.push(RoutingEvent::Mark(RoutingMark { + name: "switchyard.routing.llm_call".into(), + data: json!({ + "call_index": call_index, + "selected_model": call.selected_model.as_str(), + "call_role": "answer", + "outcome": outcome, + "latency_ms": latency_ms, + }), + metadata: metadata.clone(), + severity: Some(LogSeverity::Debug), + })); events.extend(token_usage_metrics("answer", &call, metadata)); } } @@ -860,6 +879,19 @@ mod tests { let execution = runtime .execute_buffered(WireFormat::OpenAiResponses, decoded) .await; + let decision = execution + .events + .iter() + .find_map(|event| match event { + RoutingEvent::Mark(mark) if mark.name == "switchyard.routing.decision" => { + Some(&mark.data) + } + RoutingEvent::Mark(_) | RoutingEvent::Metric(_) => None, + }) + .expect("decision mark should be emitted"); + assert_eq!(decision["selected_model"], "target/model"); + assert_eq!(decision["served_model"], "target/model"); + assert_eq!(decision["fallback_used"], false); let response = execution.result.expect("target call should succeed"); assert_eq!(response["object"], "response"); assert_eq!(response["model"], "target/model"); @@ -1153,33 +1185,56 @@ mod tests { } #[test] - fn answer_observations_emit_token_metrics_without_answer_logs() { + fn answer_observations_emit_call_marks_and_token_metrics() { let runtime = runtime_for("switchyard"); let mut events = Vec::new(); runtime.emit_observations( &mut events, - vec![RunObservation::AnswerCall(LlmCallObservation { - selected_model: ModelId::from("selected-target"), - is_success: true, - duration: std::time::Duration::from_millis(2), - usage: Some(Usage { - output_tokens: Some(9), - ..Usage::default() + vec![ + RunObservation::AnswerCall(LlmCallObservation { + selected_model: ModelId::from("weak-target"), + is_success: false, + duration: std::time::Duration::from_millis(2), + usage: None, }), - })], + RunObservation::AnswerCall(LlmCallObservation { + selected_model: ModelId::from("strong-target"), + is_success: true, + duration: std::time::Duration::from_millis(3), + usage: Some(Usage { + output_tokens: Some(9), + ..Usage::default() + }), + }), + ], &json!({}), ); - assert_eq!(events.len(), 1); - let RoutingEvent::Metric(metric) = &events[0] else { - panic!("answer observation should only emit a token metric"); + assert_eq!(events.len(), 3); + for (event, index, target, outcome, latency_ms) in [ + (&events[0], 1, "weak-target", "error", 2.0), + (&events[1], 2, "strong-target", "ok", 3.0), + ] { + let RoutingEvent::Mark(mark) = event else { + panic!("answer observation should emit a call mark"); + }; + assert_eq!(mark.name, "switchyard.routing.llm_call"); + assert_eq!(mark.data["call_index"], index); + assert_eq!(mark.data["selected_model"], target); + assert_eq!(mark.data["call_role"], "answer"); + assert_eq!(mark.data["outcome"], outcome); + assert_eq!(mark.data["latency_ms"], latency_ms); + assert_eq!(mark.severity, Some(LogSeverity::Debug)); + } + let RoutingEvent::Metric(metric) = &events[2] else { + panic!("successful answer usage should emit a token metric"); }; assert_eq!(metric.name, "switchyard.routing.llm_tokens"); assert_eq!( metric.measurements[0].attributes, Some(json!({ "call_role": "answer", - "target_model": "selected-target", + "target_model": "strong-target", "token_type": "output", })) );