Skip to content

Commit ea05ddd

Browse files
committed
Add dataplane config lookup diagnostics
Signed-off-by: lucarlig <luca.carlig@ibm.com>
1 parent f8867ab commit ea05ddd

5 files changed

Lines changed: 127 additions & 46 deletions

File tree

AGENTS.md

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -145,6 +145,12 @@ Expected config growth:
145145

146146
Keep persistent config access behind `UserConfigStore`. Do not push Redis details into routing code.
147147

148+
## Logging
149+
150+
- Use consistent structured tracing fields for related events. Reuse event message strings and field names so logs are easy to grep across request paths.
151+
- 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.
152+
- Do not log tokens, authorization headers, secrets, raw JWT subjects, Redis key/value bytes, full `UserConfig`, or backend credentials.
153+
148154
## Backend Sessions
149155

150156
Initialization fans out:

crates/contextforge-gateway-rs-lib/src/gateway/mcp_call_validator.rs

Lines changed: 29 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@ use rmcp::{
55
ErrorData, RoleServer, model::ErrorCode, service::RequestContext,
66
transport::streamable_http_server::tower::DownstreamSessionId,
77
};
8-
use tracing::info;
8+
use tracing::debug;
99

1010
use crate::{
1111
common::ContextForgeClaims,
@@ -28,9 +28,14 @@ impl<'a> AuthorizedCallValidator<'a> {
2828
let maybe_claims = maybe_parts.and_then(|parts| parts.extensions.get::<ContextForgeClaims>());
2929

3030
let maybe_virtual_host_id = maybe_parts.and_then(|parts| parts.extensions.get::<VirtualHostId>());
31-
info!(
32-
"{} user_config = {maybe_user_config:#?} session_id = {maybe_session_id:#?} virtual_host_id = {maybe_virtual_host_id:#?}",
33-
self.call_name
31+
debug!(
32+
call_name = %self.call_name,
33+
has_user_config = maybe_user_config.is_some(),
34+
virtual_hosts = maybe_user_config.map_or(0, |user_config| user_config.virtual_hosts.len()),
35+
has_session_id = maybe_session_id.is_some(),
36+
has_claims = maybe_claims.is_some(),
37+
virtual_host_id = %maybe_virtual_host_id.map_or("<missing>", |id| id.value().as_str()),
38+
"mcp_call_validation"
3439
);
3540

3641
let Some(session_id) = maybe_session_id else {
@@ -58,6 +63,12 @@ impl<'a> AuthorizedCallValidator<'a> {
5863
};
5964

6065
let Some(virtual_host) = user_config.virtual_hosts.get(virtual_host_id.value()) else {
66+
debug!(
67+
call_name = %self.call_name,
68+
virtual_host_id = %virtual_host_id.value().as_str(),
69+
virtual_hosts = user_config.virtual_hosts.len(),
70+
"mcp_virtual_host_config_missing"
71+
);
6172
return Err(ErrorData {
6273
code: ErrorCode::RESOURCE_NOT_FOUND,
6374
message: "No configuration".into(),
@@ -92,8 +103,14 @@ impl<'a> InitializeCallValidator<'a> {
92103
let maybe_user_config = maybe_parts.and_then(|parts| parts.extensions.get::<UserConfig>());
93104
let maybe_virtual_host_id = maybe_parts.and_then(|parts| parts.extensions.get::<VirtualHostId>());
94105
let maybe_claims = maybe_parts.and_then(|parts| parts.extensions.get::<ContextForgeClaims>());
95-
info!(
96-
"intialize user_config = {maybe_user_config:#?} downstream_session_id = {maybe_downstream_session:#?} virtual_host_id = {maybe_virtual_host_id:#?}"
106+
debug!(
107+
call_name = "initialize",
108+
has_user_config = maybe_user_config.is_some(),
109+
virtual_hosts = maybe_user_config.map_or(0, |user_config| user_config.virtual_hosts.len()),
110+
has_session_id = maybe_downstream_session.is_some(),
111+
has_claims = maybe_claims.is_some(),
112+
virtual_host_id = %maybe_virtual_host_id.map_or("<missing>", |id| id.value().as_str()),
113+
"mcp_call_validation"
97114
);
98115

99116
let Some(downstream_session_id) = maybe_downstream_session else {
@@ -121,6 +138,12 @@ impl<'a> InitializeCallValidator<'a> {
121138
};
122139

123140
let Some(virtual_host) = user_config.virtual_hosts.get(virtual_host_id.value()) else {
141+
debug!(
142+
call_name = "initialize",
143+
virtual_host_id = %virtual_host_id.value().as_str(),
144+
virtual_hosts = user_config.virtual_hosts.len(),
145+
"mcp_virtual_host_config_missing"
146+
);
124147
return Err(ErrorData {
125148
code: ErrorCode::RESOURCE_NOT_FOUND,
126149
message: "No configuration".into(),

crates/contextforge-gateway-rs-lib/src/layers/user_config_store.rs

Lines changed: 21 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -14,31 +14,39 @@ pub async fn user_config_store_layer(
1414
mut request: http::Request<axum::body::Body>,
1515
next: Next,
1616
) -> Response {
17+
let method = request.method().clone();
18+
let path = request.uri().path().to_owned();
1719
let maybe_claims = request.extensions().get::<ContextForgeClaims>();
1820
if let Some(claims) = maybe_claims {
1921
let subject = claims.sub.clone();
20-
debug!("Getting user config for {subject:?}");
22+
debug!(subject_ref = "redacted", method = %method, path = %path, "getting user config for request");
2123
match state.config_store.get_config(&User::new(&subject)).await {
2224
Ok(user_config) => {
23-
info!(subject, virtual_hosts = user_config.virtual_hosts.len(), "loaded user config");
25+
info!(subject_ref = "redacted", virtual_hosts = user_config.virtual_hosts.len(), "loaded user config");
2426
request.extensions_mut().insert(user_config);
2527
next.run(request).await
2628
},
2729

28-
Err(ConfigStoreError::NoDataForKey) => Response::builder()
29-
.status(StatusCode::BAD_REQUEST)
30-
.header(header::CONTENT_TYPE, "text/plain")
31-
.body(Body::from("Problem occurred retrieving the configuration"))
32-
.expect("Expecting this to work"),
30+
Err(ConfigStoreError::NoDataForKey) => {
31+
warn!(subject_ref = "redacted", method = %method, path = %path, "user config lookup returned no data");
32+
Response::builder()
33+
.status(StatusCode::BAD_REQUEST)
34+
.header(header::CONTENT_TYPE, "text/plain")
35+
.body(Body::from("Problem occurred retrieving the configuration"))
36+
.expect("Expecting this to work")
37+
},
3338

34-
Err(_) => Response::builder()
35-
.status(StatusCode::INTERNAL_SERVER_ERROR)
36-
.header(header::CONTENT_TYPE, "text/plain")
37-
.body(Body::from("Problem occurred retrieving the configuration"))
38-
.expect("Expecting this to work"),
39+
Err(error) => {
40+
warn!(subject_ref = "redacted", method = %method, path = %path, error = %error, "user config lookup failed");
41+
Response::builder()
42+
.status(StatusCode::INTERNAL_SERVER_ERROR)
43+
.header(header::CONTENT_TYPE, "text/plain")
44+
.body(Body::from("Problem occurred retrieving the configuration"))
45+
.expect("Expecting this to work")
46+
},
3947
}
4048
} else {
41-
warn!("No claims");
49+
warn!(method = %method, path = %path, "no claims found in request extensions");
4250
Response::builder()
4351
.status(StatusCode::BAD_REQUEST)
4452
.header(header::CONTENT_TYPE, "text/plain")

crates/contextforge-gateway-rs-lib/src/layers/virtual_host_id.rs

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,6 @@
11
use axum::{body::Body, middleware::Next, response::Response};
22
use http::{StatusCode, header};
3-
use tracing::debug;
3+
use tracing::{debug, warn};
44

55
#[derive(Clone, Debug, PartialEq, PartialOrd)]
66
pub struct VirtualHostId {
@@ -21,6 +21,7 @@ pub async fn virtual_host_id_layer(mut request: http::Request<axum::body::Body>,
2121
request.extensions_mut().insert(virtual_host_id);
2222
next.run(request).await
2323
} else {
24+
warn!(path = %uri.path(), "failed to extract virtual host id from request path");
2425
Response::builder()
2526
.status(StatusCode::BAD_REQUEST)
2627
.header(header::CONTENT_TYPE, "text/plain")

crates/contextforge-gateway-rs-lib/src/user_config_store/redis_config_store.rs

Lines changed: 69 additions & 26 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@ use redis::{
99
cmd,
1010
};
1111
use tokio::sync::Mutex;
12+
use tracing::{debug, warn};
1213

1314
use super::{ConfigStoreError, UserConfigStore};
1415
use crate::{
@@ -30,7 +31,10 @@ impl RedisUserConfigStore {
3031
ConnectionManagerConfig::default().set_number_of_retries(REDIS_RETRIES),
3132
)
3233
.await
33-
.map_err(|_| ConfigStoreError::InvalidConnection)?,
34+
.map_err(|error| {
35+
warn!(error = %error, "failed to create Redis user config connection");
36+
ConfigStoreError::InvalidConnection
37+
})?,
3438
cache: Arc::new(Mutex::new(LruCache::with_expiry_duration_and_capacity(
3539
LRU_CACHE_EXPIRY_DURATION,
3640
LRU_CACHE_ENTRIES,
@@ -42,51 +46,90 @@ impl RedisUserConfigStore {
4246
#[async_trait]
4347
impl UserConfigStore for RedisUserConfigStore {
4448
async fn get_config<'a>(&self, user_key: &'a User) -> Result<UserConfig, ConfigStoreError> {
45-
let has_key = { self.cache.lock().await.contains_key(user_key.key()) };
46-
if has_key {
47-
if let Some(user_config) = self.cache.lock().await.get_mut(user_key.key()) {
48-
Ok(user_config.clone())
49-
} else {
50-
return Err(ConfigStoreError::NoDataForKey);
49+
let subject = user_key.key();
50+
51+
{
52+
let mut cache = self.cache.lock().await;
53+
if let Some(user_config) = cache.get_mut(subject) {
54+
debug!(
55+
subject_ref = "redacted",
56+
virtual_hosts = user_config.virtual_hosts.len(),
57+
"user config cache hit"
58+
);
59+
return Ok(user_config.clone());
5160
}
52-
} else {
53-
let Ok(key) = rmp_serde::encode::to_vec::<User>(user_key) else {
54-
return Err(ConfigStoreError::DataEncoding);
55-
};
61+
}
62+
63+
debug!(subject_ref = "redacted", "user config cache miss");
5664

57-
let mut connection = self.connection.clone();
58-
let maybe_user_config: Result<Option<Vec<u8>>, RedisError> =
59-
cmd("GET").arg(key).take().query_async(&mut connection).await;
65+
let Ok(key) = rmp_serde::encode::to_vec::<User>(user_key) else {
66+
warn!(subject_ref = "redacted", "failed to encode Redis user config key");
67+
return Err(ConfigStoreError::DataEncoding);
68+
};
6069

61-
let Ok(Some(user_config)) = maybe_user_config else {
70+
let mut connection = self.connection.clone();
71+
let maybe_user_config: Result<Option<Vec<u8>>, RedisError> =
72+
cmd("GET").arg(key).take().query_async(&mut connection).await;
73+
74+
let user_config = match maybe_user_config {
75+
Ok(Some(user_config)) => {
76+
debug!(subject_ref = "redacted", bytes = user_config.len(), "loaded user config blob from Redis");
77+
user_config
78+
},
79+
Ok(None) => {
80+
warn!(subject_ref = "redacted", "no user config found in Redis");
81+
return Err(ConfigStoreError::NoDataForKey);
82+
},
83+
Err(error) => {
84+
warn!(subject_ref = "redacted", error = %error, "failed to load user config from Redis");
6285
return Err(ConfigStoreError::NoDataForKey);
63-
};
86+
},
87+
};
6488

65-
let Ok(user_config) = rmp_serde::decode::from_slice::<UserConfig>(&user_config) else {
89+
let user_config = match rmp_serde::decode::from_slice::<UserConfig>(&user_config) {
90+
Ok(user_config) => user_config,
91+
Err(error) => {
92+
warn!(subject_ref = "redacted", error = %error, "failed to decode Redis user config blob");
6693
return Err(ConfigStoreError::DataWrongFormat);
67-
};
94+
},
95+
};
6896

69-
self.cache.lock().await.insert(user_key.key().to_owned(), user_config.clone());
70-
Ok(user_config)
71-
}
97+
debug!(subject_ref = "redacted", virtual_hosts = user_config.virtual_hosts.len(), "decoded user config");
98+
99+
self.cache.lock().await.insert(subject.to_owned(), user_config.clone());
100+
Ok(user_config)
72101
}
73102

74103
async fn set_config<'a>(&self, user_key: &'a User, config: &'a UserConfig) -> Result<(), ConfigStoreError> {
104+
let subject = user_key.key();
105+
75106
let Ok(key) = rmp_serde::encode::to_vec::<User>(user_key) else {
107+
warn!(subject_ref = "redacted", "failed to encode Redis user config key");
76108
return Err(ConfigStoreError::DataEncoding);
77109
};
78110

79111
let Ok(encoded) = rmp_serde::encode::to_vec::<UserConfig>(config) else {
112+
warn!(subject_ref = "redacted", virtual_hosts = config.virtual_hosts.len(), "failed to encode user config");
80113
return Err(ConfigStoreError::DataEncoding);
81114
};
82115

83116
let mut connection = self.connection.clone();
84117

85-
if connection.set::<&[u8], &[u8], String>(&key, &encoded).await.is_ok() {
86-
self.cache.lock().await.insert(user_key.key().to_owned(), config.clone());
87-
Ok(())
88-
} else {
89-
return Err(ConfigStoreError::CantWriteData);
118+
match connection.set::<&[u8], &[u8], String>(&key, &encoded).await {
119+
Ok(_) => {
120+
debug!(
121+
subject_ref = "redacted",
122+
bytes = encoded.len(),
123+
virtual_hosts = config.virtual_hosts.len(),
124+
"wrote user config to Redis"
125+
);
126+
self.cache.lock().await.insert(subject.to_owned(), config.clone());
127+
Ok(())
128+
},
129+
Err(error) => {
130+
warn!(subject_ref = "redacted", error = %error, "failed to write user config to Redis");
131+
Err(ConfigStoreError::CantWriteData)
132+
},
90133
}
91134
}
92135
}

0 commit comments

Comments
 (0)