diff --git a/CHANGELOG.md b/CHANGELOG.md index 76884e283..1208c0e63 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,13 @@ adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). ## [Unreleased] +### Fixed + +- **Request log distinguishes an absent id from an empty one** — the terminal + request event rendered `session_id` and `correlation_id` with + `unwrap_or("")`, so a request that carried no session and one that carried a + blank session both logged `session_id=`. An absent id now omits the field. + ### Added - **NeMo Relay native plugin** — a dynamically loaded integration that loads diff --git a/crates/switchyard-server/src/lib.rs b/crates/switchyard-server/src/lib.rs index 8b6f06de8..23a5855de 100644 --- a/crates/switchyard-server/src/lib.rs +++ b/crates/switchyard-server/src/lib.rs @@ -1132,8 +1132,8 @@ impl RequestLogContext { requested_model = self.requested_model.as_deref().unwrap_or(""), selected_model, streaming = self.streaming, - session_id = self.session_id.as_deref().unwrap_or(""), - correlation_id = self.correlation_id.as_deref().unwrap_or(""), + session_id = self.session_id.as_deref(), + correlation_id = self.correlation_id.as_deref(), handling_duration_ms = duration_ms, error, $message @@ -1160,8 +1160,8 @@ impl RequestLogContext { requested_model = self.requested_model.as_deref().unwrap_or(""), selected_model = "", streaming = self.streaming, - session_id = self.session_id.as_deref().unwrap_or(""), - correlation_id = self.correlation_id.as_deref().unwrap_or(""), + session_id = self.session_id.as_deref(), + correlation_id = self.correlation_id.as_deref(), handling_duration_ms = self.started.elapsed().as_secs_f64() * 1_000.0, error = "client disconnected before a response was written", "LLM request cancelled" @@ -1692,6 +1692,7 @@ mod tests { use switchyard_llm_client::LlmCallObservation; use tokio::io::{AsyncReadExt, AsyncWriteExt}; use tokio::sync::{Notify, oneshot}; + use tracing::field::{Field, Visit}; use super::*; @@ -1908,9 +1909,28 @@ mod tests { let _ = tokio::time::timeout(Duration::from_secs(5), server).await; } + // One terminal request event: its level, its message, and every other field it + // recorded. A field the event never recorded is a missing key, not an empty value. + type CapturedEvent = (Level, String, BTreeMap); + // Collects the terminal request events emitted while it is the active subscriber. #[derive(Clone, Default)] - struct CapturedEvents(Arc>>); + struct CapturedEvents(Arc>>); + + // Records every field into a string map, so a field the event never recorded is a + // missing key rather than an empty value. + struct FieldVisitor<'a>(&'a mut BTreeMap); + + impl Visit for FieldVisitor<'_> { + fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { + self.0 + .insert(field.name().to_string(), format!("{value:?}")); + } + + fn record_str(&mut self, field: &Field, value: &str) { + self.0.insert(field.name().to_string(), value.to_string()); + } + } impl tracing_subscriber::Layer for CapturedEvents { fn on_event( @@ -1921,15 +1941,12 @@ mod tests { if event.metadata().target() != "switchyard_server::request" { return; } - let mut message = String::new(); - event.record( - &mut |field: &tracing::field::Field, value: &dyn std::fmt::Debug| { - if field.name() == "message" { - message = format!("{value:?}"); - } - }, - ); - self.0.lock().push((*event.metadata().level(), message)); + let mut fields = BTreeMap::new(); + event.record(&mut FieldVisitor(&mut fields)); + let message = fields.remove("message").unwrap_or_default(); + self.0 + .lock() + .push((*event.metadata().level(), message, fields)); } } @@ -1944,7 +1961,7 @@ mod tests { } } - fn captured_events(run: impl FnOnce()) -> Vec<(Level, String)> { + fn captured_events(run: impl FnOnce()) -> Vec { use tracing_subscriber::layer::SubscriberExt; let captured = CapturedEvents::default(); @@ -1980,6 +1997,43 @@ mod tests { assert!(events[0].1.contains("handled"), "{:?}", events[0].1); } + // An operator has to be able to tell "no session was sent" from "a blank one was + // sent": an absent id omits the field, an empty one records an empty value. + #[test] + fn request_log_distinguishes_absent_ids_from_empty_ones() { + let rows = [ + (None, None), + (Some(String::new()), Some("")), + (Some("abc".to_string()), Some("abc")), + ]; + + for (id, expected) in rows { + let context = || { + let mut context = request_log_context(); + context.session_id = id.clone(); + context.correlation_id = id.clone(); + context + }; + + let answered = captured_events(|| { + let mut guard = RequestLogGuard(Some(context())); + guard.emit(&StatusCode::OK.into_response()); + }); + let cancelled = captured_events(|| drop(RequestLogGuard(Some(context())))); + + for events in [answered, cancelled] { + assert_eq!(events.len(), 1); + for field in ["session_id", "correlation_id"] { + assert_eq!( + events[0].2.get(field).map(String::as_str), + expected, + "{field} {id:?}" + ); + } + } + } + } + // Terminal request severity follows HTTP status instead of error-path bookkeeping. #[test] fn request_log_level_follows_http_status() {