From e051fae800fab78a18cf43bc0e97d53e537cdc91 Mon Sep 17 00:00:00 2001 From: Justin Date: Sat, 16 May 2026 06:20:22 +0800 Subject: [PATCH] fix(mcp): tighten stdio server logging and error semantics (#1790) Co-authored-by: Steven Enamakel --- src/openhuman/mcp_server/protocol.rs | 15 +++- src/openhuman/mcp_server/stdio.rs | 44 +++++++--- src/openhuman/mcp_server/tools.rs | 115 +++++++++++++++++++++++++-- 3 files changed, 153 insertions(+), 21 deletions(-) diff --git a/src/openhuman/mcp_server/protocol.rs b/src/openhuman/mcp_server/protocol.rs index dbae17811..3ae2288cc 100644 --- a/src/openhuman/mcp_server/protocol.rs +++ b/src/openhuman/mcp_server/protocol.rs @@ -160,12 +160,23 @@ async fn handle_request(id: Value, method: &str, params: Value) -> Value { success_response(id, result) } Err(err) => { + // Dispatch the JSON-RPC error code based on the + // variant: client-input problems (`InvalidParams`) + // stay as `-32602`, server-side failures + // (`Internal`) surface as `-32603` so clients don't + // mis-attribute them to the caller's arguments. log::debug!( - "[mcp_server] tools/call rejected tool={} error={}", + "[mcp_server] tools/call rejected tool={} code={} error={}", name, + err.code(), err.message() ); - error_response(id, -32602, "Invalid params", Some(json!(err.message()))) + error_response( + id, + err.code(), + err.jsonrpc_message(), + Some(json!(err.message())), + ) } } } diff --git a/src/openhuman/mcp_server/stdio.rs b/src/openhuman/mcp_server/stdio.rs index cba6d00d9..da5523790 100644 --- a/src/openhuman/mcp_server/stdio.rs +++ b/src/openhuman/mcp_server/stdio.rs @@ -19,9 +19,7 @@ pub fn run_stdio_from_cli(args: &[String]) -> Result<()> { } } - if verbose { - crate::core::logging::init_for_cli_run(true, CliLogDefault::Global); - } + init_mcp_logging(verbose); log::debug!("[mcp_server] starting stdio MCP server"); let rt = tokio::runtime::Builder::new_multi_thread() @@ -31,6 +29,25 @@ pub fn run_stdio_from_cli(args: &[String]) -> Result<()> { Ok(()) } +/// Initialize logging for the stdio MCP server. +/// +/// MCP servers run as subprocesses of clients (Claude Desktop, Cursor, …) which +/// surface the server's stderr to the user when something goes wrong. We +/// therefore always install the tracing subscriber — otherwise `log::error!` / +/// `log::warn!` events get silently dropped and field-debugging requires +/// re-running with `--verbose`. +/// +/// Default level is `warn` to keep the stderr stream quiet under normal use +/// while still surfacing problems; `--verbose` promotes it to `debug` so +/// `[mcp_server]` traces become visible. A user-set `RUST_LOG` always wins. +fn init_mcp_logging(verbose: bool) { + if std::env::var_os("RUST_LOG").is_none() { + let level = if verbose { "debug" } else { "warn" }; + std::env::set_var("RUST_LOG", level); + } + crate::core::logging::init_for_cli_run(verbose, CliLogDefault::Global); +} + pub async fn run_stdio(reader: R, mut writer: W) -> Result<()> where R: AsyncRead + Unpin, @@ -53,15 +70,18 @@ where } fn print_help() { - println!("Usage: openhuman-core mcp [-v|--verbose]"); - println!(); - println!("Start an opt-in stdio Model Context Protocol server."); - println!("The server exposes a curated read-only memory surface:"); - println!(" memory.search"); - println!(" memory.recall"); - println!(" tree.read_chunk"); - println!(); - println!("Logging is written to stderr. JSON-RPC protocol messages are written to stdout."); + // Use stderr so the help output never collides with the protocol stream, + // matching the banner-suppression contract in `core/cli.rs` for the `mcp` + // subcommand: stdout is reserved for JSON-RPC frames. + eprintln!("Usage: openhuman-core mcp [-v|--verbose]"); + eprintln!(); + eprintln!("Start an opt-in stdio Model Context Protocol server."); + eprintln!("The server exposes a curated read-only memory surface:"); + eprintln!(" memory.search"); + eprintln!(" memory.recall"); + eprintln!(" tree.read_chunk"); + eprintln!(); + eprintln!("Logging is written to stderr. JSON-RPC protocol messages are written to stdout."); } #[cfg(test)] diff --git a/src/openhuman/mcp_server/tools.rs b/src/openhuman/mcp_server/tools.rs index 2565d547c..6f8616d8d 100644 --- a/src/openhuman/mcp_server/tools.rs +++ b/src/openhuman/mcp_server/tools.rs @@ -20,13 +20,37 @@ pub struct McpToolSpec { #[derive(Debug, Clone, PartialEq, Eq)] pub enum ToolCallError { + /// Client-side problem: malformed arguments, unknown tool, validation + /// failure. Maps to JSON-RPC `-32602 Invalid params`. InvalidParams(String), + /// Server-side problem outside the caller's control: config load failure, + /// missing platform resources. Maps to JSON-RPC `-32603 Internal error`. + /// Kept distinct from `InvalidParams` so MCP clients don't display + /// internal failures as if the user supplied bad arguments. + Internal(String), } impl ToolCallError { pub fn message(&self) -> &str { match self { - Self::InvalidParams(message) => message, + Self::InvalidParams(message) | Self::Internal(message) => message, + } + } + + /// JSON-RPC error code corresponding to this variant. + pub fn code(&self) -> i64 { + match self { + Self::InvalidParams(_) => -32602, + Self::Internal(_) => -32603, + } + } + + /// JSON-RPC error `message` field (short, spec-canonical phrase). The + /// human-readable detail belongs in the response's `data` field. + pub fn jsonrpc_message(&self) -> &'static str { + match self { + Self::InvalidParams(_) => "Invalid params", + Self::Internal(_) => "Internal error", } } } @@ -236,7 +260,16 @@ fn optional_limit(args: &Map) -> Result { "argument `k` must be greater than zero".to_string(), )); } - Ok(limit.min(MAX_LIMIT)) + if limit > MAX_LIMIT { + // Reject explicitly instead of silently clamping. The schema advertises + // `maximum: MAX_LIMIT`, so a higher value is a client bug; surfacing it + // lets the LLM self-correct on the next call instead of believing it + // received the page size it asked for. + return Err(ToolCallError::InvalidParams(format!( + "argument `k` must not exceed {MAX_LIMIT} (got {limit})" + ))); + } + Ok(limit) } fn validate_controller_params( @@ -253,10 +286,24 @@ fn validate_controller_params( } async fn enforce_read_policy(tool_name: &str) -> Result<(), ToolCallError> { - let config = config_rpc::load_config_with_timeout() - .await - .map_err(|err| ToolCallError::InvalidParams(format!("failed to load config: {err}")))?; + // Config-load failure is an internal/server issue (disk error, corrupt + // config), not bad client input — report it as `-32603 Internal error` + // rather than `-32602 Invalid params`. + let config = match config_rpc::load_config_with_timeout().await { + Ok(config) => config, + Err(err) => { + log::warn!( + "[mcp_server] enforce_read_policy config load failed tool={tool_name} error={err}" + ); + return Err(ToolCallError::Internal(format!( + "failed to load config: {err}" + ))); + } + }; let policy = SecurityPolicy::from_config(&config.autonomy, &config.workspace_dir); + // A policy denial *is* something the caller can act on (toggle autonomy, + // approve the tool) — keep that as `InvalidParams` so clients surface the + // reason text instead of a generic internal-error banner. policy .enforce_tool_operation(ToolOperation::Read, tool_name) .map_err(ToolCallError::InvalidParams) @@ -325,20 +372,74 @@ mod tests { } #[test] - fn memory_search_params_default_and_clamp_k() { + fn memory_search_params_trim_query_and_use_default_k() { let params = build_rpc_params( "memory.search", json!({ "query": " phoenix migration ", - "k": 999 }), ) .expect("params"); assert_eq!(params["query"], "phoenix migration"); + assert_eq!(params["k"], DEFAULT_LIMIT); + } + + #[test] + fn memory_search_rejects_k_above_max() { + // Reject (don't silent-clamp) so the LLM can self-correct on the next + // call. Silent clamping makes the model believe it got the page size + // it asked for and prevents the corrective feedback loop. + let err = build_rpc_params( + "memory.search", + json!({ + "query": "phoenix", + "k": MAX_LIMIT + 1 + }), + ) + .expect_err("must reject k > MAX_LIMIT"); + + let message = err.message(); + assert!( + message.contains("must not exceed"), + "error should mention the cap, got: {message}" + ); + assert!( + message.contains(&MAX_LIMIT.to_string()), + "error should mention the limit value, got: {message}" + ); + } + + #[test] + fn memory_search_accepts_k_at_max() { + let params = build_rpc_params( + "memory.search", + json!({ "query": "phoenix", "k": MAX_LIMIT }), + ) + .expect("k = MAX_LIMIT must be accepted (boundary inclusive)"); assert_eq!(params["k"], MAX_LIMIT); } + #[test] + fn tool_call_error_invalid_params_maps_to_jsonrpc_invalid_params() { + let err = ToolCallError::InvalidParams("missing query".to_string()); + assert_eq!(err.code(), -32602); + assert_eq!(err.jsonrpc_message(), "Invalid params"); + assert_eq!(err.message(), "missing query"); + } + + #[test] + fn tool_call_error_internal_maps_to_jsonrpc_internal_error() { + // Server-side failures (config load, missing resources) must surface + // as `-32603 Internal error`, not `-32602 Invalid params`, so the MCP + // client doesn't mislead the user / LLM into retrying with different + // arguments. + let err = ToolCallError::Internal("disk read failed".to_string()); + assert_eq!(err.code(), -32603); + assert_eq!(err.jsonrpc_message(), "Internal error"); + assert_eq!(err.message(), "disk read failed"); + } + #[test] fn memory_recall_requires_query() { let err = build_rpc_params("memory.recall", json!({})).expect_err("must reject");