From 83f4d334345f27e6c796f0a2de762754e11ab1e5 Mon Sep 17 00:00:00 2001 From: Adil Hafeez Date: Thu, 17 Jul 2025 16:00:04 -0700 Subject: [PATCH] refactor logging in brightstaff (#532) refactor logs, move unnecessary info log statements to debug and start logging latest chat completion message to log --- .../src/handlers/chat_completions.rs | 60 +++++++++++++------ crates/brightstaff/src/main.rs | 2 +- crates/brightstaff/src/router/llm_router.rs | 11 ++-- 3 files changed, 49 insertions(+), 24 deletions(-) diff --git a/crates/brightstaff/src/handlers/chat_completions.rs b/crates/brightstaff/src/handlers/chat_completions.rs index 614acb66..bd5cab79 100644 --- a/crates/brightstaff/src/handlers/chat_completions.rs +++ b/crates/brightstaff/src/handlers/chat_completions.rs @@ -27,6 +27,7 @@ pub async fn chat_completions( router_service: Arc, llm_provider_endpoint: String, ) -> Result>, hyper::Error> { + let request_path = request.uri().path().to_string(); let mut request_headers = request.headers().clone(); let chat_request_bytes = request.collect().await?.to_bytes(); @@ -61,20 +62,15 @@ pub async fn chat_completions( // remove metadata from the request let mut chat_request_user_preferences_removed = chat_request_parsed; if let Some(metadata) = chat_request_user_preferences_removed.get_mut("metadata") { - info!("Removing metadata from request"); + debug!("Removing metadata from request"); if let Some(m) = metadata.as_object_mut() { m.remove("archgw_preference_config"); - info!("Removed archgw_preference_config from metadata"); + debug!("Removed archgw_preference_config from metadata"); } - // metadata.as_object_mut().map(|m| { - // m.remove("archgw_preference_config"); - // info!("Removed archgw_preference_config from metadata"); - // }); - // if metadata is empty, remove it if metadata.as_object().map_or(false, |m| m.is_empty()) { - info!("Removing empty metadata from request"); + debug!("Removing empty metadata from request"); chat_request_user_preferences_removed .as_object_mut() .map(|m| m.remove("metadata")); @@ -102,9 +98,33 @@ pub async fn chat_completions( .as_ref() .and_then(|s| serde_yaml::from_str(s).ok()); + let latest_message_for_log = + chat_completion_request + .messages + .last() + .map_or("None".to_string(), |msg| { + msg.content.as_ref().map_or("None".to_string(), |content| { + content.to_string().replace('\n', "\\n") + }) + }); + + const MAX_MESSAGE_LENGTH: usize = 50; + let latest_message_for_log = if latest_message_for_log.len() > MAX_MESSAGE_LENGTH { + format!("{}...", &latest_message_for_log[..MAX_MESSAGE_LENGTH]) + } else { + latest_message_for_log + }; + + info!( + "request received, request type: chat_completion, usage preferences from request: {}, request path: {}, latest message: {}", + usage_preferences.is_some(), + request_path, + latest_message_for_log + ); + debug!("usage preferences from request: {:?}", usage_preferences); - let determined_model = match router_service + let model_name = match router_service .determine_route( &chat_completion_request.messages, trace_parent.clone(), @@ -112,7 +132,16 @@ pub async fn chat_completions( ) .await { - Ok(route) => route, + Ok(route) => match route { + Some((_, model_name)) => model_name, + None => { + debug!( + "No route determined, using default model from request: {}", + chat_completion_request.model + ); + chat_completion_request.model.clone() + } + }, Err(err) => { let err_msg = format!("Failed to determine route: {}", err); let mut internal_error = Response::new(full(err_msg)); @@ -121,17 +150,14 @@ pub async fn chat_completions( } }; - info!( - "sending request to llm provider: {} determined_model: {:?}, model from request: {}", - llm_provider_endpoint, determined_model, chat_completion_request.model + debug!( + "sending request to llm provider: {}, with model hint: {}", + llm_provider_endpoint, model_name ); request_headers.insert( ARCH_PROVIDER_HINT_HEADER, - header::HeaderValue::from_str( - &determined_model.unwrap_or(chat_completion_request.model.clone()), - ) - .unwrap(), + header::HeaderValue::from_str(&model_name).unwrap(), ); if let Some(trace_parent) = trace_parent { diff --git a/crates/brightstaff/src/main.rs b/crates/brightstaff/src/main.rs index 4e4f18b7..dbcc9124 100644 --- a/crates/brightstaff/src/main.rs +++ b/crates/brightstaff/src/main.rs @@ -156,7 +156,7 @@ async fn main() -> Result<(), Box> { }); tokio::task::spawn(async move { - info!("Accepted connection from {:?}", peer_addr); + debug!("Accepted connection from {:?}", peer_addr); if let Err(err) = http1::Builder::new() // .serve_connection(io, service_fn(chat_completion)) .serve_connection(io, service) diff --git a/crates/brightstaff/src/router/llm_router.rs b/crates/brightstaff/src/router/llm_router.rs index a20bf7c4..fc6d9365 100644 --- a/crates/brightstaff/src/router/llm_router.rs +++ b/crates/brightstaff/src/router/llm_router.rs @@ -78,7 +78,7 @@ impl RouterService { messages: &[Message], trace_parent: Option, usage_preferences: Option>, - ) -> Result> { + ) -> Result> { if !self.llm_usage_defined { return Ok(None); } @@ -87,7 +87,7 @@ impl RouterService { .router_model .generate_request(messages, &usage_preferences); - info!( + debug!( "sending request to arch-router model: {}, endpoint: {}", self.router_model.get_model_name(), self.router_url @@ -160,15 +160,14 @@ impl RouterService { .router_model .parse_response(content, &usage_preferences)?; info!( - "router response: {}, selected_model: {:?}, response time: {}ms", + "arch-router determined route: {}, selected_model: {:?}, response time: {}ms", content.replace("\n", "\\n"), parsed_response, router_response_time.as_millis() ); - if let Some(ref route) = parsed_response { - // return model name if route is found - return Ok(Some(route.1.clone())); + if let Some(ref parsed_response) = parsed_response { + return Ok(Some(parsed_response.clone())); } Ok(None)