refactor logging in brightstaff (#532)

refactor logs, move unnecessary info log statements to debug and start logging latest chat completion message to log

crates/brightstaff/src/handlers/chat_completions.rs

@@ -27,6 +27,7 @@ pub async fn chat_completions(
     router_service: Arc<RouterService>,
     llm_provider_endpoint: String,
 ) -> Result<Response<BoxBody<Bytes, hyper::Error>>, 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!(
+    debug!(
-        "sending request to llm provider: {} determined_model: {:?}, model from request: {}",
+        "sending request to llm provider: {}, with model hint: {}",
-        llm_provider_endpoint, determined_model, chat_completion_request.model
+        llm_provider_endpoint, model_name
     );
 
     request_headers.insert(
         ARCH_PROVIDER_HINT_HEADER,
-        header::HeaderValue::from_str(
+        header::HeaderValue::from_str(&model_name).unwrap(),
-            &determined_model.unwrap_or(chat_completion_request.model.clone()),
-        )
-        .unwrap(),
     );
 
     if let Some(trace_parent) = trace_parent {

crates/brightstaff/src/main.rs

@@ -156,7 +156,7 @@ async fn main() -> Result<(), Box<dyn std::error::Error + Send + Sync>> {
         });
 
         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)

crates/brightstaff/src/router/llm_router.rs

@@ -78,7 +78,7 @@ impl RouterService {
         messages: &[Message],
         trace_parent: Option<String>,
         usage_preferences: Option<Vec<ModelUsagePreference>>,
-    ) -> Result<Option<String>> {
+    ) -> Result<Option<(String, String)>> {
         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 {
+            if let Some(ref parsed_response) = parsed_response {
-                // return model name if route is found
+                return Ok(Some(parsed_response.clone()));
-                return Ok(Some(route.1.clone()));
             }
 
             Ok(None)