From 28f7cf88f873d9f5e585bf59a6841edc5ee42359 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 22 Aug 2026 18:17:04 +0000 Subject: [PATCH] Route logs to stderr in MCP mode MCP speaks JSON-RPC 2.0 over stdout, but the tracing subscriber defaulted to stdout too, so every log line was interleaved into the protocol stream. A client reading the first line for its initialize response got INFO ThreadId(01) tinker: src/main.rs:90: Starting Tinker Workshop... instead of JSON, and failed to parse. This affected any MCP client, including Claude Desktop using the configuration in the readme. Logging was also initialized before the arguments were parsed, so it could not know whether --mcp was set. Parse first, then point the subscriber at stderr when running as an MCP server. Non-MCP output is unchanged. The MCP write loop itself was already correct, and there are no other stdout writers in the tree, so the subscriber was the sole corruption source. This is why tests/mcp_tests.rs had three #[ignore]d tests. The attribute said they were skipped because they require building the binary, but they were failing on the corrupted stream. They pass now and are re-enabled, giving end-to-end protocol coverage that guards this regression. cargo test: 167 passed, 0 failed, 0 ignored (was 164 passed, 3 ignored). Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01Pg53xf5xcUV7oc5CkaiCpz --- src/main.rs | 20 ++++++++++++++------ tests/mcp_tests.rs | 28 ++++++++++++---------------- 2 files changed, 26 insertions(+), 22 deletions(-) diff --git a/src/main.rs b/src/main.rs index 0727983..2f0a9bd 100644 --- a/src/main.rs +++ b/src/main.rs @@ -76,21 +76,29 @@ async fn main() -> Result<(), Box> { env::set_var("DEBUG", "TRUE"); } + // Parse arguments before initializing logging: MCP mode speaks JSON-RPC over + // stdout, so the subscriber has to be pointed at stderr before it writes its + // first line. Anything on stdout that isn't a JSON-RPC message corrupts the + // stream and the client fails to parse the response. + let args = Args::parse(); + // Initialize logging with more detailed format - tracing_subscriber::fmt() + let subscriber = tracing_subscriber::fmt() .with_env_filter(tracing_subscriber::EnvFilter::from_default_env() .add_directive("tinker=debug".parse()?) .add_directive("wry=debug".parse()?)) .with_file(true) .with_line_number(true) .with_thread_ids(true) - .with_target(true) - .init(); + .with_target(true); - info!("Starting Tinker Workshop..."); + if args.mcp { + subscriber.with_writer(std::io::stderr).init(); + } else { + subscriber.init(); + } - // Parse command line arguments - let args = Args::parse(); + info!("Starting Tinker Workshop..."); // Create broadcast channels for API server or MCP server if enabled let (api_event_tx, api_event_rx) = if args.api || args.mcp { diff --git a/tests/mcp_tests.rs b/tests/mcp_tests.rs index 65e0a22..625ccfa 100644 --- a/tests/mcp_tests.rs +++ b/tests/mcp_tests.rs @@ -3,13 +3,11 @@ use serde_json::json; use std::io::{BufRead, BufReader, Write}; use std::process::{Command, Stdio}; -use std::time::Duration; #[test] -#[ignore] // Ignore by default since it requires building the binary fn test_mcp_server_initialize() { - let mut child = Command::new("cargo") - .args(&["run", "--", "--mcp", "--url", "https://example.com"]) + let mut child = Command::new(env!("CARGO_BIN_EXE_tinker")) + .args(&["--mcp", "--url", "https://example.com"]) .stdin(Stdio::piped()) .stdout(Stdio::piped()) .stderr(Stdio::piped()) @@ -20,8 +18,8 @@ fn test_mcp_server_initialize() { let stdout = child.stdout.take().expect("Failed to open stdout"); let mut reader = BufReader::new(stdout); - // Give the server time to start - std::thread::sleep(Duration::from_secs(2)); + // No startup wait needed: the binary is already built, and the server reads + // stdin as soon as it starts. The request below simply queues until then. // Send initialize request let request = json!({ @@ -60,10 +58,9 @@ fn test_mcp_server_initialize() { } #[test] -#[ignore] // Ignore by default since it requires building the binary fn test_mcp_server_tools_list() { - let mut child = Command::new("cargo") - .args(&["run", "--", "--mcp", "--url", "https://example.com"]) + let mut child = Command::new(env!("CARGO_BIN_EXE_tinker")) + .args(&["--mcp", "--url", "https://example.com"]) .stdin(Stdio::piped()) .stdout(Stdio::piped()) .stderr(Stdio::piped()) @@ -74,8 +71,8 @@ fn test_mcp_server_tools_list() { let stdout = child.stdout.take().expect("Failed to open stdout"); let mut reader = BufReader::new(stdout); - // Give the server time to start - std::thread::sleep(Duration::from_secs(2)); + // No startup wait needed: the binary is already built, and the server reads + // stdin as soon as it starts. The request below simply queues until then. // Send tools/list request let request = json!({ @@ -118,10 +115,9 @@ fn test_mcp_server_tools_list() { } #[test] -#[ignore] // Ignore by default since it requires building the binary fn test_mcp_server_invalid_request() { - let mut child = Command::new("cargo") - .args(&["run", "--", "--mcp", "--url", "https://example.com"]) + let mut child = Command::new(env!("CARGO_BIN_EXE_tinker")) + .args(&["--mcp", "--url", "https://example.com"]) .stdin(Stdio::piped()) .stdout(Stdio::piped()) .stderr(Stdio::piped()) @@ -132,8 +128,8 @@ fn test_mcp_server_invalid_request() { let stdout = child.stdout.take().expect("Failed to open stdout"); let mut reader = BufReader::new(stdout); - // Give the server time to start - std::thread::sleep(Duration::from_secs(2)); + // No startup wait needed: the binary is already built, and the server reads + // stdin as soon as it starts. The request below simply queues until then. // Send invalid JSON writeln!(stdin, "{{invalid json}}").expect("Failed to write request");