From 0b576051034df2ee60de1a583363cc2ae114d066 Mon Sep 17 00:00:00 2001 From: voson Date: Sat, 21 Mar 2026 17:57:10 +0800 Subject: [PATCH] =?UTF-8?q?feat(secrets-mcp):=20MCP=20=E8=AF=B7=E6=B1=82?= =?UTF-8?q?=E6=97=A5=E5=BF=97=E3=80=81=E6=8E=A2=E6=B5=8B=20404=20=E4=B8=8E?= =?UTF-8?q?=E8=B5=84=E6=BA=90=E5=85=83=E6=95=B0=E6=8D=AE?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - 新增 logging 中间件：记录 client_ip、ua、JSON-RPC、tool 等 - tools 各入口/出口结构化日志 - 探测型 404（/.well-known、GET /mcp）降为 debug - /.well-known/oauth-protected-resource 最小元数据 - secrets-mcp 0.1.11 Made-with: Cursor --- Cargo.lock | 3 +- crates/secrets-mcp/Cargo.toml | 4 +- crates/secrets-mcp/src/logging.rs | 249 ++++++++++++++++++++++++++++++ crates/secrets-mcp/src/main.rs | 7 +- crates/secrets-mcp/src/tools.rs | 211 +++++++++++++++++++++++-- crates/secrets-mcp/src/web.rs | 26 ++++ 6 files changed, 486 insertions(+), 14 deletions(-) create mode 100644 crates/secrets-mcp/src/logging.rs diff --git a/Cargo.lock b/Cargo.lock index 0003571..8eadcc3 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1949,7 +1949,7 @@ dependencies = [ [[package]] name = "secrets-mcp" -version = "0.1.10" +version = "0.1.11" dependencies = [ "anyhow", "askama", @@ -2700,6 +2700,7 @@ dependencies = [ "tower", "tower-layer", "tower-service", + "tracing", ] [[package]] diff --git a/crates/secrets-mcp/Cargo.toml b/crates/secrets-mcp/Cargo.toml index 2d33a86..0fec568 100644 --- a/crates/secrets-mcp/Cargo.toml +++ b/crates/secrets-mcp/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "secrets-mcp" -version = "0.1.10" +version = "0.1.11" edition.workspace = true [[bin]] @@ -17,7 +17,7 @@ rmcp = { version = "1", features = ["server", "macros", "transport-streamable-ht axum = "0.8" axum-extra = { version = "0.10", features = ["typed-header"] } tower = "0.5" -tower-http = { version = "0.6", features = ["cors"] } +tower-http = { version = "0.6", features = ["cors", "trace"] } tower-sessions = "0.14" # OAuth (manual token exchange via reqwest) diff --git a/crates/secrets-mcp/src/logging.rs b/crates/secrets-mcp/src/logging.rs new file mode 100644 index 0000000..fc89056 --- /dev/null +++ b/crates/secrets-mcp/src/logging.rs @@ -0,0 +1,249 @@ +use std::net::SocketAddr; +use std::time::Instant; + +use axum::{ + body::{Body, Bytes, to_bytes}, + extract::{ConnectInfo, Request}, + http::{ + HeaderMap, Method, + header::{CONTENT_LENGTH, CONTENT_TYPE, USER_AGENT}, + }, + middleware::Next, + response::Response, +}; + +/// Axum middleware that logs structured info for every HTTP request. +/// +/// All requests: method, path, status, latency_ms, client_ip, user_agent. +/// POST /mcp requests: additionally parses JSON-RPC body for jsonrpc_method, +/// tool_name, jsonrpc_id, mcp_session, batch_size. +/// +/// Sensitive headers (Authorization, X-Encryption-Key) and secret values +/// are never logged. +pub async fn request_logging_middleware(req: Request, next: Next) -> Response { + let method = req.method().clone(); + let path = req.uri().path().to_string(); + let ip = client_ip(&req); + let ua = header_str(req.headers(), USER_AGENT); + let content_len = header_str(req.headers(), CONTENT_LENGTH).and_then(|v| v.parse::().ok()); + let mcp_session = req + .headers() + .get("mcp-session-id") + .or_else(|| req.headers().get("x-mcp-session")) + .and_then(|v| v.to_str().ok()) + .map(|s| s.to_string()); + + let is_mcp_post = path.starts_with("/mcp") && method == Method::POST; + let is_json = header_str(req.headers(), CONTENT_TYPE) + .map(|ct| ct.contains("application/json")) + .unwrap_or(false); + + let start = Instant::now(); + + // For MCP JSON-RPC POST requests, buffer body to extract JSON-RPC metadata. + // We cap at 512 KiB to avoid buffering large payloads. + if is_mcp_post && is_json { + let cap = content_len.unwrap_or(0); + if cap <= 512 * 1024 { + let (parts, body) = req.into_parts(); + match to_bytes(body, 512 * 1024).await { + Ok(bytes) => { + let rpc = parse_jsonrpc_meta(&bytes); + let req = Request::from_parts(parts, Body::from(bytes)); + let resp = next.run(req).await; + let status = resp.status().as_u16(); + let elapsed = start.elapsed().as_millis(); + log_mcp_request( + &method, + &path, + status, + elapsed, + ip.as_deref(), + ua.as_deref(), + content_len, + mcp_session.as_deref(), + &rpc, + ); + return resp; + } + Err(e) => { + tracing::warn!(path, error = %e, "failed to buffer MCP request body for logging"); + // Reconstruct with empty body; request was consumed — return 500. + // This branch is highly unlikely in practice. + let resp = next.run(Request::from_parts(parts, Body::empty())).await; + return resp; + } + } + } + } + + let resp = next.run(req).await; + let status = resp.status().as_u16(); + let elapsed = start.elapsed().as_millis(); + + // Known client probe patterns that legitimately 404 — downgrade to debug to + // avoid noise in production logs. These are: + // • GET /.well-known/* — OAuth/OIDC discovery by MCP clients (RFC 8414 / RFC 9728) + // • GET /mcp → 404 — old SSE-transport compatibility probe by clients + let is_expected_probe_404 = status == 404 + && (path.starts_with("/.well-known/") + || (method == Method::GET && path.starts_with("/mcp"))); + + if is_expected_probe_404 { + tracing::debug!( + method = method.as_str(), + path, + status, + elapsed_ms = elapsed, + client_ip = ip.as_deref(), + ua = ua.as_deref(), + "probe request (not found — expected)", + ); + } else { + log_http_request( + &method, + &path, + status, + elapsed, + ip.as_deref(), + ua.as_deref(), + content_len, + ); + } + + resp +} + +// ── Logging helpers ─────────────────────────────────────────────────────────── + +fn log_http_request( + method: &Method, + path: &str, + status: u16, + elapsed_ms: u128, + client_ip: Option<&str>, + ua: Option<&str>, + content_length: Option, +) { + tracing::info!( + method = method.as_str(), + path, + status, + elapsed_ms, + client_ip, + ua, + content_length, + "http request", + ); +} + +#[allow(clippy::too_many_arguments)] +fn log_mcp_request( + method: &Method, + path: &str, + status: u16, + elapsed_ms: u128, + client_ip: Option<&str>, + ua: Option<&str>, + content_length: Option, + mcp_session: Option<&str>, + rpc: &JsonRpcMeta, +) { + tracing::info!( + method = method.as_str(), + path, + status, + elapsed_ms, + client_ip, + ua, + content_length, + mcp_session, + jsonrpc = rpc.rpc_method.as_deref(), + tool = rpc.tool_name.as_deref(), + jsonrpc_id = rpc.request_id.as_deref(), + batch_size = rpc.batch_size, + "mcp request", + ); +} + +// ── JSON-RPC body parsing ───────────────────────────────────────────────────── + +#[derive(Debug, Default)] +struct JsonRpcMeta { + request_id: Option, + rpc_method: Option, + tool_name: Option, + batch_size: Option, +} + +fn parse_jsonrpc_meta(bytes: &Bytes) -> JsonRpcMeta { + let Ok(value) = serde_json::from_slice::(bytes) else { + return JsonRpcMeta::default(); + }; + + if let Some(arr) = value.as_array() { + // Batch request: summarise method(s) from first element only + let first = arr.first().map(parse_single).unwrap_or_default(); + return JsonRpcMeta { + batch_size: Some(arr.len()), + ..first + }; + } + + parse_single(&value) +} + +fn parse_single(value: &serde_json::Value) -> JsonRpcMeta { + let request_id = value.get("id").and_then(json_to_string); + let rpc_method = value + .get("method") + .and_then(|v| v.as_str()) + .map(|s| s.to_string()); + let tool_name = value + .pointer("/params/name") + .and_then(|v| v.as_str()) + .map(|s| s.to_string()); + + JsonRpcMeta { + request_id, + rpc_method, + tool_name, + batch_size: None, + } +} + +fn json_to_string(value: &serde_json::Value) -> Option { + match value { + serde_json::Value::Null => None, + serde_json::Value::String(s) => Some(s.clone()), + serde_json::Value::Number(n) => Some(n.to_string()), + serde_json::Value::Bool(b) => Some(b.to_string()), + other => Some(other.to_string()), + } +} + +// ── Header helpers ──────────────────────────────────────────────────────────── + +fn header_str(headers: &HeaderMap, name: impl axum::http::header::AsHeaderName) -> Option { + headers + .get(name) + .and_then(|v| v.to_str().ok()) + .map(|s| s.to_string()) +} + +fn client_ip(req: &Request) -> Option { + if let Some(first) = req + .headers() + .get("x-forwarded-for") + .and_then(|v| v.to_str().ok()) + .and_then(|s| s.split(',').next()) + { + let s = first.trim(); + if !s.is_empty() { + return Some(s.to_string()); + } + } + req.extensions() + .get::>() + .map(|c| c.ip().to_string()) +} diff --git a/crates/secrets-mcp/src/main.rs b/crates/secrets-mcp/src/main.rs index 529d743..6fc3475 100644 --- a/crates/secrets-mcp/src/main.rs +++ b/crates/secrets-mcp/src/main.rs @@ -1,4 +1,5 @@ mod auth; +mod logging; mod oauth; mod tools; mod web; @@ -53,7 +54,8 @@ async fn main() -> Result<()> { tracing_subscriber::fmt() .with_env_filter( - EnvFilter::try_from_default_env().unwrap_or_else(|_| "secrets_mcp=info".into()), + EnvFilter::try_from_default_env() + .unwrap_or_else(|_| "secrets_mcp=info,tower_http=info".into()), ) .init(); @@ -120,6 +122,9 @@ async fn main() -> Result<()> { let router = Router::new() .merge(web::web_router()) .nest_service("/mcp", mcp_service) + .layer(axum::middleware::from_fn( + logging::request_logging_middleware, + )) .layer(axum::middleware::from_fn_with_state( pool, auth::bearer_auth_middleware, diff --git a/crates/secrets-mcp/src/tools.rs b/crates/secrets-mcp/src/tools.rs index b656856..856a62b 100644 --- a/crates/secrets-mcp/src/tools.rs +++ b/crates/secrets-mcp/src/tools.rs @@ -1,4 +1,5 @@ use std::sync::Arc; +use std::time::Instant; use anyhow::Result; use rmcp::{ @@ -257,7 +258,17 @@ impl SecretsService { Parameters(input): Parameters, ctx: RequestContext, ) -> Result { + let t = Instant::now(); let user_id = Self::user_id_from_ctx(&ctx)?; + tracing::info!( + tool = "secrets_search", + ?user_id, + namespace = input.namespace.as_deref(), + kind = input.kind.as_deref(), + name = input.name.as_deref(), + query = input.query.as_deref(), + "tool call start", + ); let tags = input.tags.unwrap_or_default(); let result = svc_search( &self.pool, @@ -274,7 +285,10 @@ impl SecretsService { }, ) .await - .map_err(|e| rmcp::ErrorData::internal_error(e.to_string(), None))?; + .map_err(|e| { + tracing::warn!(tool = "secrets_search", ?user_id, error = %e, "tool call failed"); + rmcp::ErrorData::internal_error(e.to_string(), None) + })?; let summary = input.summary.unwrap_or(false); let entries: Vec = result @@ -312,6 +326,14 @@ impl SecretsService { }) .collect(); + let count = entries.len(); + tracing::info!( + tool = "secrets_search", + ?user_id, + result_count = count, + elapsed_ms = t.elapsed().as_millis(), + "tool call ok", + ); let json = serde_json::to_string_pretty(&entries).unwrap_or_else(|_| "[]".to_string()); Ok(CallToolResult::success(vec![Content::text(json)])) } @@ -326,7 +348,17 @@ impl SecretsService { Parameters(input): Parameters, ctx: RequestContext, ) -> Result { + let t = Instant::now(); let (user_id, user_key) = Self::require_user_and_key(&ctx)?; + tracing::info!( + tool = "secrets_get", + ?user_id, + namespace = %input.namespace, + kind = %input.kind, + name = %input.name, + field = input.field.as_deref(), + "tool call start", + ); if let Some(field_name) = &input.field { let value = get_secret_field( @@ -339,8 +371,17 @@ impl SecretsService { Some(user_id), ) .await - .map_err(|e| rmcp::ErrorData::internal_error(e.to_string(), None))?; + .map_err(|e| { + tracing::warn!(tool = "secrets_get", ?user_id, error = %e, "tool call failed"); + rmcp::ErrorData::internal_error(e.to_string(), None) + })?; + tracing::info!( + tool = "secrets_get", + ?user_id, + elapsed_ms = t.elapsed().as_millis(), + "tool call ok", + ); let result = serde_json::json!({ field_name: value }); let json = serde_json::to_string_pretty(&result).unwrap_or_default(); Ok(CallToolResult::success(vec![Content::text(json)])) @@ -354,8 +395,19 @@ impl SecretsService { Some(user_id), ) .await - .map_err(|e| rmcp::ErrorData::internal_error(e.to_string(), None))?; + .map_err(|e| { + tracing::warn!(tool = "secrets_get", ?user_id, error = %e, "tool call failed"); + rmcp::ErrorData::internal_error(e.to_string(), None) + })?; + let count = secrets.len(); + tracing::info!( + tool = "secrets_get", + ?user_id, + field_count = count, + elapsed_ms = t.elapsed().as_millis(), + "tool call ok", + ); let json = serde_json::to_string_pretty(&secrets).unwrap_or_default(); Ok(CallToolResult::success(vec![Content::text(json)])) } @@ -371,7 +423,16 @@ impl SecretsService { Parameters(input): Parameters, ctx: RequestContext, ) -> Result { + let t = Instant::now(); let (user_id, user_key) = Self::require_user_and_key(&ctx)?; + tracing::info!( + tool = "secrets_add", + ?user_id, + namespace = %input.namespace, + kind = %input.kind, + name = %input.name, + "tool call start", + ); let tags = input.tags.unwrap_or_default(); let meta = input.meta.unwrap_or_default(); @@ -391,8 +452,20 @@ impl SecretsService { &user_key, ) .await - .map_err(|e| rmcp::ErrorData::internal_error(e.to_string(), None))?; + .map_err(|e| { + tracing::warn!(tool = "secrets_add", ?user_id, error = %e, "tool call failed"); + rmcp::ErrorData::internal_error(e.to_string(), None) + })?; + tracing::info!( + tool = "secrets_add", + ?user_id, + namespace = %input.namespace, + kind = %input.kind, + name = %input.name, + elapsed_ms = t.elapsed().as_millis(), + "tool call ok", + ); let json = serde_json::to_string_pretty(&result).unwrap_or_default(); Ok(CallToolResult::success(vec![Content::text(json)])) } @@ -406,7 +479,16 @@ impl SecretsService { Parameters(input): Parameters, ctx: RequestContext, ) -> Result { + let t = Instant::now(); let (user_id, user_key) = Self::require_user_and_key(&ctx)?; + tracing::info!( + tool = "secrets_update", + ?user_id, + namespace = %input.namespace, + kind = %input.kind, + name = %input.name, + "tool call start", + ); let add_tags = input.add_tags.unwrap_or_default(); let remove_tags = input.remove_tags.unwrap_or_default(); @@ -432,8 +514,20 @@ impl SecretsService { &user_key, ) .await - .map_err(|e| rmcp::ErrorData::internal_error(e.to_string(), None))?; + .map_err(|e| { + tracing::warn!(tool = "secrets_update", ?user_id, error = %e, "tool call failed"); + rmcp::ErrorData::internal_error(e.to_string(), None) + })?; + tracing::info!( + tool = "secrets_update", + ?user_id, + namespace = %input.namespace, + kind = %input.kind, + name = %input.name, + elapsed_ms = t.elapsed().as_millis(), + "tool call ok", + ); let json = serde_json::to_string_pretty(&result).unwrap_or_default(); Ok(CallToolResult::success(vec![Content::text(json)])) } @@ -447,7 +541,17 @@ impl SecretsService { Parameters(input): Parameters, ctx: RequestContext, ) -> Result { + let t = Instant::now(); let user_id = Self::user_id_from_ctx(&ctx)?; + tracing::info!( + tool = "secrets_delete", + ?user_id, + namespace = %input.namespace, + kind = input.kind.as_deref(), + name = input.name.as_deref(), + dry_run = input.dry_run.unwrap_or(false), + "tool call start", + ); let result = svc_delete( &self.pool, @@ -460,8 +564,18 @@ impl SecretsService { }, ) .await - .map_err(|e| rmcp::ErrorData::internal_error(e.to_string(), None))?; + .map_err(|e| { + tracing::warn!(tool = "secrets_delete", ?user_id, error = %e, "tool call failed"); + rmcp::ErrorData::internal_error(e.to_string(), None) + })?; + tracing::info!( + tool = "secrets_delete", + ?user_id, + namespace = %input.namespace, + elapsed_ms = t.elapsed().as_millis(), + "tool call ok", + ); let json = serde_json::to_string_pretty(&result).unwrap_or_default(); Ok(CallToolResult::success(vec![Content::text(json)])) } @@ -475,7 +589,17 @@ impl SecretsService { Parameters(input): Parameters, ctx: RequestContext, ) -> Result { + let t = Instant::now(); let user_id = Self::user_id_from_ctx(&ctx)?; + tracing::info!( + tool = "secrets_history", + ?user_id, + namespace = %input.namespace, + kind = %input.kind, + name = %input.name, + "tool call start", + ); + let result = svc_history( &self.pool, &input.namespace, @@ -485,8 +609,17 @@ impl SecretsService { user_id, ) .await - .map_err(|e| rmcp::ErrorData::internal_error(e.to_string(), None))?; + .map_err(|e| { + tracing::warn!(tool = "secrets_history", ?user_id, error = %e, "tool call failed"); + rmcp::ErrorData::internal_error(e.to_string(), None) + })?; + tracing::info!( + tool = "secrets_history", + ?user_id, + elapsed_ms = t.elapsed().as_millis(), + "tool call ok", + ); let json = serde_json::to_string_pretty(&result).unwrap_or_default(); Ok(CallToolResult::success(vec![Content::text(json)])) } @@ -500,7 +633,17 @@ impl SecretsService { Parameters(input): Parameters, ctx: RequestContext, ) -> Result { + let t = Instant::now(); let (user_id, user_key) = Self::require_user_and_key(&ctx)?; + tracing::info!( + tool = "secrets_rollback", + ?user_id, + namespace = %input.namespace, + kind = %input.kind, + name = %input.name, + to_version = input.to_version, + "tool call start", + ); let result = svc_rollback( &self.pool, @@ -512,8 +655,17 @@ impl SecretsService { Some(user_id), ) .await - .map_err(|e| rmcp::ErrorData::internal_error(e.to_string(), None))?; + .map_err(|e| { + tracing::warn!(tool = "secrets_rollback", ?user_id, error = %e, "tool call failed"); + rmcp::ErrorData::internal_error(e.to_string(), None) + })?; + tracing::info!( + tool = "secrets_rollback", + ?user_id, + elapsed_ms = t.elapsed().as_millis(), + "tool call ok", + ); let json = serde_json::to_string_pretty(&result).unwrap_or_default(); Ok(CallToolResult::success(vec![Content::text(json)])) } @@ -527,9 +679,18 @@ impl SecretsService { Parameters(input): Parameters, ctx: RequestContext, ) -> Result { + let t = Instant::now(); let (user_id, user_key) = Self::require_user_and_key(&ctx)?; let tags = input.tags.unwrap_or_default(); let format = input.format.as_deref().unwrap_or("json"); + tracing::info!( + tool = "secrets_export", + ?user_id, + namespace = input.namespace.as_deref(), + kind = input.kind.as_deref(), + format, + "tool call start", + ); let data = svc_export( &self.pool, @@ -545,13 +706,23 @@ impl SecretsService { Some(&user_key), ) .await - .map_err(|e| rmcp::ErrorData::internal_error(e.to_string(), None))?; + .map_err(|e| { + tracing::warn!(tool = "secrets_export", ?user_id, error = %e, "tool call failed"); + rmcp::ErrorData::internal_error(e.to_string(), None) + })?; let serialized = format .parse::() .and_then(|fmt| fmt.serialize(&data)) .map_err(|e| rmcp::ErrorData::internal_error(e.to_string(), None))?; + tracing::info!( + tool = "secrets_export", + ?user_id, + entry_count = data.entries.len(), + elapsed_ms = t.elapsed().as_millis(), + "tool call ok", + ); Ok(CallToolResult::success(vec![Content::text(serialized)])) } @@ -565,9 +736,18 @@ impl SecretsService { Parameters(input): Parameters, ctx: RequestContext, ) -> Result { + let t = Instant::now(); let (user_id, user_key) = Self::require_user_and_key(&ctx)?; let tags = input.tags.unwrap_or_default(); let only_fields = input.only_fields.unwrap_or_default(); + tracing::info!( + tool = "secrets_env_map", + ?user_id, + namespace = input.namespace.as_deref(), + kind = input.kind.as_deref(), + prefix = input.prefix.as_deref().unwrap_or(""), + "tool call start", + ); let env_map = secrets_core::service::env_map::build_env_map( &self.pool, @@ -581,8 +761,19 @@ impl SecretsService { Some(user_id), ) .await - .map_err(|e| rmcp::ErrorData::internal_error(e.to_string(), None))?; + .map_err(|e| { + tracing::warn!(tool = "secrets_env_map", ?user_id, error = %e, "tool call failed"); + rmcp::ErrorData::internal_error(e.to_string(), None) + })?; + let entry_count = env_map.len(); + tracing::info!( + tool = "secrets_env_map", + ?user_id, + entry_count, + elapsed_ms = t.elapsed().as_millis(), + "tool call ok", + ); let json = serde_json::to_string_pretty(&env_map).unwrap_or_default(); Ok(CallToolResult::success(vec![Content::text(json)])) } diff --git a/crates/secrets-mcp/src/web.rs b/crates/secrets-mcp/src/web.rs index 34e975d..fcf128d 100644 --- a/crates/secrets-mcp/src/web.rs +++ b/crates/secrets-mcp/src/web.rs @@ -117,6 +117,10 @@ pub fn web_router() -> Router { "/favicon.ico", get(|| async { Redirect::permanent("/favicon.svg") }), ) + .route( + "/.well-known/oauth-protected-resource", + get(oauth_protected_resource_metadata), + ) .route("/", get(login_page)) .route("/auth/google", get(auth_google)) .route("/auth/google/callback", get(auth_google_callback)) @@ -626,6 +630,28 @@ async fn api_apikey_regenerate( Ok(Json(ApiKeyResponse { api_key })) } +// ── OAuth / Well-known ──────────────────────────────────────────────────────── + +/// RFC 9728 — OAuth 2.0 Protected Resource Metadata. +/// +/// Advertises that this server accepts Bearer tokens in the `Authorization` +/// header. We deliberately omit `authorization_servers` because this service +/// issues its own API keys (no external OAuth AS is involved). MCP clients +/// that probe this endpoint will see the resource identifier and stop looking +/// for a delegated OAuth flow. +async fn oauth_protected_resource_metadata(State(state): State) -> impl IntoResponse { + let body = serde_json::json!({ + "resource": state.base_url, + "bearer_methods_supported": ["header"], + "resource_documentation": format!("{}/dashboard", state.base_url), + }); + ( + StatusCode::OK, + [(header::CONTENT_TYPE, "application/json")], + axum::Json(body), + ) +} + // ── Helper ──────────────────────────────────────────────────────────────────── fn render_template(tmpl: T) -> Result {