From 3ab41eab15b108324e9f8e2adaa9f23254feb7b1 Mon Sep 17 00:00:00 2001 From: lucarlig Date: Wed, 1 Jul 2026 14:33:35 +0100 Subject: [PATCH] Add dataplane config lookup diagnostics Signed-off-by: lucarlig --- AGENTS.md | 8 ++ .../src/gateway/mcp_call_validator.rs | 35 +++++- .../src/layers/user_config_store.rs | 43 ++++--- .../src/layers/virtual_host_id.rs | 7 +- .../user_config_store/redis_config_store.rs | 108 +++++++++++++----- 5 files changed, 153 insertions(+), 48 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 8eae4072..c8d643a9 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -145,6 +145,14 @@ Expected config growth: Keep persistent config access behind `UserConfigStore`. Do not push Redis details into routing code. +## Logging + +- Use consistent formatted tracing messages for related events so logs are easy to grep across request paths. +- Prefer captured variables inside the message, for example `level!("method_name - event text field = {field} other_field = {other_field}")`, over structured field syntax for dataplane logs. +- Keep the method/event prefix stable and reuse the same field names/order for related events. +- Keep warning logs for unexpected conditions that likely need operator attention. Expected user/config misses should be debug or info unless they indicate a platform problem. +- Do not log tokens, authorization headers, secrets, Redis key/value bytes, full `UserConfig`, or backend credentials. + ## Backend Sessions Initialization fans out: diff --git a/crates/contextforge-gateway-rs-lib/src/gateway/mcp_call_validator.rs b/crates/contextforge-gateway-rs-lib/src/gateway/mcp_call_validator.rs index ae9f0aaa..f9d6ce14 100644 --- a/crates/contextforge-gateway-rs-lib/src/gateway/mcp_call_validator.rs +++ b/crates/contextforge-gateway-rs-lib/src/gateway/mcp_call_validator.rs @@ -5,7 +5,7 @@ use rmcp::{ ErrorData, RoleServer, model::ErrorCode, service::RequestContext, transport::streamable_http_server::tower::DownstreamSessionId, }; -use tracing::info; +use tracing::debug; use crate::{ common::ContextForgeClaims, @@ -28,9 +28,14 @@ impl<'a> AuthorizedCallValidator<'a> { let maybe_claims = maybe_parts.and_then(|parts| parts.extensions.get::()); let maybe_virtual_host_id = maybe_parts.and_then(|parts| parts.extensions.get::()); - info!( - "{} user_config = {maybe_user_config:#?} session_id = {maybe_session_id:#?} virtual_host_id = {maybe_virtual_host_id:#?}", - self.call_name + let call_name = self.call_name; + let has_user_config = maybe_user_config.is_some(); + let virtual_hosts = maybe_user_config.map_or(0, |user_config| user_config.virtual_hosts.len()); + let has_session_id = maybe_session_id.is_some(); + let has_claims = maybe_claims.is_some(); + let virtual_host_id = maybe_virtual_host_id.map_or("", |id| id.value().as_str()); + debug!( + "AuthorizedCallValidator::validate - mcp call validation call_name = {call_name} has_user_config = {has_user_config} virtual_hosts = {virtual_hosts} has_session_id = {has_session_id} has_claims = {has_claims} virtual_host_id = {virtual_host_id}" ); let Some(session_id) = maybe_session_id else { @@ -58,6 +63,12 @@ impl<'a> AuthorizedCallValidator<'a> { }; let Some(virtual_host) = user_config.virtual_hosts.get(virtual_host_id.value()) else { + let call_name = self.call_name; + let virtual_host_id = virtual_host_id.value(); + let virtual_hosts = user_config.virtual_hosts.len(); + debug!( + "AuthorizedCallValidator::validate - mcp virtual host config missing call_name = {call_name} virtual_host_id = {virtual_host_id} virtual_hosts = {virtual_hosts}" + ); return Err(ErrorData { code: ErrorCode::RESOURCE_NOT_FOUND, message: "No configuration".into(), @@ -92,8 +103,14 @@ impl<'a> InitializeCallValidator<'a> { let maybe_user_config = maybe_parts.and_then(|parts| parts.extensions.get::()); let maybe_virtual_host_id = maybe_parts.and_then(|parts| parts.extensions.get::()); let maybe_claims = maybe_parts.and_then(|parts| parts.extensions.get::()); - info!( - "intialize user_config = {maybe_user_config:#?} downstream_session_id = {maybe_downstream_session:#?} virtual_host_id = {maybe_virtual_host_id:#?}" + let call_name = "initialize"; + let has_user_config = maybe_user_config.is_some(); + let virtual_hosts = maybe_user_config.map_or(0, |user_config| user_config.virtual_hosts.len()); + let has_session_id = maybe_downstream_session.is_some(); + let has_claims = maybe_claims.is_some(); + let virtual_host_id = maybe_virtual_host_id.map_or("", |id| id.value().as_str()); + debug!( + "InitializeCallValidator::validate - mcp call validation call_name = {call_name} has_user_config = {has_user_config} virtual_hosts = {virtual_hosts} has_session_id = {has_session_id} has_claims = {has_claims} virtual_host_id = {virtual_host_id}" ); let Some(downstream_session_id) = maybe_downstream_session else { @@ -121,6 +138,12 @@ impl<'a> InitializeCallValidator<'a> { }; let Some(virtual_host) = user_config.virtual_hosts.get(virtual_host_id.value()) else { + let call_name = "initialize"; + let virtual_host_id = virtual_host_id.value(); + let virtual_hosts = user_config.virtual_hosts.len(); + debug!( + "InitializeCallValidator::validate - mcp virtual host config missing call_name = {call_name} virtual_host_id = {virtual_host_id} virtual_hosts = {virtual_hosts}" + ); return Err(ErrorData { code: ErrorCode::RESOURCE_NOT_FOUND, message: "No configuration".into(), diff --git a/crates/contextforge-gateway-rs-lib/src/layers/user_config_store.rs b/crates/contextforge-gateway-rs-lib/src/layers/user_config_store.rs index 10c0b69d..80ba5ad2 100644 --- a/crates/contextforge-gateway-rs-lib/src/layers/user_config_store.rs +++ b/crates/contextforge-gateway-rs-lib/src/layers/user_config_store.rs @@ -14,31 +14,48 @@ pub async fn user_config_store_layer( mut request: http::Request, next: Next, ) -> Response { + let method = request.method().clone(); + let path = request.uri().path().to_owned(); let maybe_claims = request.extensions().get::(); if let Some(claims) = maybe_claims { let subject = claims.sub.clone(); - debug!("Getting user config for {subject:?}"); + debug!( + "user_config_store_layer - getting user config for request subject = {subject} method = {method} path = {path}" + ); match state.config_store.get_config(&User::new(&subject)).await { Ok(user_config) => { - info!(subject, virtual_hosts = user_config.virtual_hosts.len(), "loaded user config"); + let virtual_hosts = user_config.virtual_hosts.len(); + info!( + "user_config_store_layer - loaded user config subject = {subject} virtual_hosts = {virtual_hosts}" + ); request.extensions_mut().insert(user_config); next.run(request).await }, - Err(ConfigStoreError::NoDataForKey) => Response::builder() - .status(StatusCode::BAD_REQUEST) - .header(header::CONTENT_TYPE, "text/plain") - .body(Body::from("Problem occurred retrieving the configuration")) - .expect("Expecting this to work"), + Err(ConfigStoreError::NoDataForKey) => { + debug!( + "user_config_store_layer - user config lookup returned no data subject = {subject} method = {method} path = {path}" + ); + Response::builder() + .status(StatusCode::BAD_REQUEST) + .header(header::CONTENT_TYPE, "text/plain") + .body(Body::from("Problem occurred retrieving the configuration")) + .expect("Expecting this to work") + }, - Err(_) => Response::builder() - .status(StatusCode::INTERNAL_SERVER_ERROR) - .header(header::CONTENT_TYPE, "text/plain") - .body(Body::from("Problem occurred retrieving the configuration")) - .expect("Expecting this to work"), + Err(error) => { + debug!( + "user_config_store_layer - user config lookup failed subject = {subject} method = {method} path = {path} error = {error}" + ); + Response::builder() + .status(StatusCode::INTERNAL_SERVER_ERROR) + .header(header::CONTENT_TYPE, "text/plain") + .body(Body::from("Problem occurred retrieving the configuration")) + .expect("Expecting this to work") + }, } } else { - warn!("No claims"); + warn!("user_config_store_layer - no claims found in request extensions method = {method} path = {path}"); Response::builder() .status(StatusCode::BAD_REQUEST) .header(header::CONTENT_TYPE, "text/plain") diff --git a/crates/contextforge-gateway-rs-lib/src/layers/virtual_host_id.rs b/crates/contextforge-gateway-rs-lib/src/layers/virtual_host_id.rs index a48192b2..81716131 100644 --- a/crates/contextforge-gateway-rs-lib/src/layers/virtual_host_id.rs +++ b/crates/contextforge-gateway-rs-lib/src/layers/virtual_host_id.rs @@ -14,13 +14,14 @@ impl VirtualHostId { } pub async fn virtual_host_id_layer(mut request: http::Request, next: Next) -> Response { - let uri = request.uri(); + let path = request.uri().path().to_owned(); - debug!("Extracting virtual host from path {:?}", uri.path()); - if let Some(virtual_host_id) = extract_virtual_host_id(uri.path()) { + debug!("virtual_host_id_layer - extracting virtual host from path path = {path}"); + if let Some(virtual_host_id) = extract_virtual_host_id(&path) { request.extensions_mut().insert(virtual_host_id); next.run(request).await } else { + debug!("virtual_host_id_layer - failed to extract virtual host id from request path path = {path}"); Response::builder() .status(StatusCode::BAD_REQUEST) .header(header::CONTENT_TYPE, "text/plain") diff --git a/crates/contextforge-gateway-rs-lib/src/user_config_store/redis_config_store.rs b/crates/contextforge-gateway-rs-lib/src/user_config_store/redis_config_store.rs index 8db36f07..60c19a4b 100644 --- a/crates/contextforge-gateway-rs-lib/src/user_config_store/redis_config_store.rs +++ b/crates/contextforge-gateway-rs-lib/src/user_config_store/redis_config_store.rs @@ -9,6 +9,7 @@ use redis::{ cmd, }; use tokio::sync::Mutex; +use tracing::{debug, warn}; use super::{ConfigStoreError, UserConfigStore}; use crate::{ @@ -30,7 +31,10 @@ impl RedisUserConfigStore { ConnectionManagerConfig::default().set_number_of_retries(REDIS_RETRIES), ) .await - .map_err(|_| ConfigStoreError::InvalidConnection)?, + .map_err(|error| { + warn!("RedisUserConfigStore::new - failed to create Redis user config connection error = {error}"); + ConfigStoreError::InvalidConnection + })?, cache: Arc::new(Mutex::new(LruCache::with_expiry_duration_and_capacity( LRU_CACHE_EXPIRY_DURATION, LRU_CACHE_ENTRIES, @@ -42,51 +46,103 @@ impl RedisUserConfigStore { #[async_trait] impl UserConfigStore for RedisUserConfigStore { async fn get_config<'a>(&self, user_key: &'a User) -> Result { - let has_key = { self.cache.lock().await.contains_key(user_key.key()) }; - if has_key { - if let Some(user_config) = self.cache.lock().await.get_mut(user_key.key()) { - Ok(user_config.clone()) - } else { - return Err(ConfigStoreError::NoDataForKey); + let subject = user_key.key(); + + { + let mut cache = self.cache.lock().await; + if let Some(user_config) = cache.get_mut(subject) { + let virtual_hosts = user_config.virtual_hosts.len(); + debug!( + "RedisUserConfigStore::get_config - user config cache hit subject = {subject} virtual_hosts = {virtual_hosts}" + ); + return Ok(user_config.clone()); } - } else { - let Ok(key) = rmp_serde::encode::to_vec::(user_key) else { - return Err(ConfigStoreError::DataEncoding); - }; + } + + debug!("RedisUserConfigStore::get_config - user config cache miss subject = {subject}"); - let mut connection = self.connection.clone(); - let maybe_user_config: Result>, RedisError> = - cmd("GET").arg(key).take().query_async(&mut connection).await; + let Ok(key) = rmp_serde::encode::to_vec::(user_key) else { + warn!("RedisUserConfigStore::get_config - failed to encode Redis user config key subject = {subject}"); + return Err(ConfigStoreError::DataEncoding); + }; - let Ok(Some(user_config)) = maybe_user_config else { + let mut connection = self.connection.clone(); + let maybe_user_config: Result>, RedisError> = + cmd("GET").arg(key).take().query_async(&mut connection).await; + + let user_config = match maybe_user_config { + Ok(Some(user_config)) => { + let bytes = user_config.len(); + debug!( + "RedisUserConfigStore::get_config - loaded user config blob from Redis subject = {subject} bytes = {bytes}" + ); + user_config + }, + Ok(None) => { + debug!("RedisUserConfigStore::get_config - no user config found in Redis subject = {subject}"); + return Err(ConfigStoreError::NoDataForKey); + }, + Err(error) => { + warn!( + "RedisUserConfigStore::get_config - failed to load user config from Redis subject = {subject} error = {error}" + ); return Err(ConfigStoreError::NoDataForKey); - }; + }, + }; - let Ok(user_config) = rmp_serde::decode::from_slice::(&user_config) else { + let user_config = match rmp_serde::decode::from_slice::(&user_config) { + Ok(user_config) => user_config, + Err(error) => { + warn!( + "RedisUserConfigStore::get_config - failed to decode Redis user config blob subject = {subject} error = {error}" + ); return Err(ConfigStoreError::DataWrongFormat); - }; + }, + }; - self.cache.lock().await.insert(user_key.key().to_owned(), user_config.clone()); - Ok(user_config) - } + let virtual_hosts = user_config.virtual_hosts.len(); + debug!( + "RedisUserConfigStore::get_config - decoded user config subject = {subject} virtual_hosts = {virtual_hosts}" + ); + + self.cache.lock().await.insert(subject.to_owned(), user_config.clone()); + Ok(user_config) } async fn set_config<'a>(&self, user_key: &'a User, config: &'a UserConfig) -> Result<(), ConfigStoreError> { + let subject = user_key.key(); + let Ok(key) = rmp_serde::encode::to_vec::(user_key) else { + warn!("RedisUserConfigStore::set_config - failed to encode Redis user config key subject = {subject}"); return Err(ConfigStoreError::DataEncoding); }; let Ok(encoded) = rmp_serde::encode::to_vec::(config) else { + let virtual_hosts = config.virtual_hosts.len(); + warn!( + "RedisUserConfigStore::set_config - failed to encode user config subject = {subject} virtual_hosts = {virtual_hosts}" + ); return Err(ConfigStoreError::DataEncoding); }; let mut connection = self.connection.clone(); - if connection.set::<&[u8], &[u8], String>(&key, &encoded).await.is_ok() { - self.cache.lock().await.insert(user_key.key().to_owned(), config.clone()); - Ok(()) - } else { - return Err(ConfigStoreError::CantWriteData); + match connection.set::<&[u8], &[u8], String>(&key, &encoded).await { + Ok(_) => { + let bytes = encoded.len(); + let virtual_hosts = config.virtual_hosts.len(); + debug!( + "RedisUserConfigStore::set_config - wrote user config to Redis subject = {subject} bytes = {bytes} virtual_hosts = {virtual_hosts}" + ); + self.cache.lock().await.insert(subject.to_owned(), config.clone()); + Ok(()) + }, + Err(error) => { + warn!( + "RedisUserConfigStore::set_config - failed to write user config to Redis subject = {subject} error = {error}" + ); + Err(ConfigStoreError::CantWriteData) + }, } } }