Add debug logging to diagnose Windows hanging issue

Author: felixweinberger

debug_windows_test.py

@@ -0,0 +1,64 @@
+"""Debug script to understand Windows hanging issue"""
+import asyncio
+import sys
+import time
+import textwrap
+import logging
+from mcp.client.stdio import StdioServerParameters, stdio_client
+import anyio
+
+# Enable debug logging
+logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(name)s - %(message)s')
+logger = logging.getLogger("mcp.stdio_debug")
+
+async def test_with_debug():
+    print("Starting debug test...")
+    
+    long_running_script = textwrap.dedent(
+        """
+        import time
+        import sys
+        
+        # Simulate a long-running process
+        for i in range(100):
+            time.sleep(0.1)
+            # Flush to ensure output is visible
+            sys.stdout.flush()
+            sys.stderr.flush()
+        """
+    )
+    
+    server_params = StdioServerParameters(
+        command=sys.executable,
+        args=["-c", long_running_script],
+    )
+
+    start_time = time.time()
+    print(f"Test started at {start_time}")
+
+    try:
+        with anyio.move_on_after(10.0) as cancel_scope:
+            print("Entering stdio_client context...")
+            async with stdio_client(server_params) as (read_stream, write_stream):
+                print("Inside stdio_client context, immediately exiting...")
+                pass
+            
+            print("Exited stdio_client context")
+            end_time = time.time()
+            elapsed = end_time - start_time
+            print(f"Cleanup took {elapsed:.2f} seconds")
+
+        if cancel_scope.cancelled_caught:
+            print("ERROR: Timed out after 10 seconds!")
+            sys.exit(1)
+        else:
+            print("SUCCESS: Cleanup completed without timeout")
+            
+    except Exception as e:
+        print(f"Exception occurred: {type(e).__name__}: {e}")
+        import traceback
+        traceback.print_exc()
+        sys.exit(1)
+
+if __name__ == "__main__":
+    anyio.run(test_with_debug)

src/mcp/client/stdio/__init__.py

@@ -185,29 +185,47 @@ async def stdin_writer():
             # 1. Close input stream to server
             # 2. Wait for server to exit, or send SIGTERM if it doesn't exit in time
             # 3. Send SIGKILL if still not exited
+            import logging
+            logger = logging.getLogger("mcp.stdio_debug")
+            logger.info("Starting cleanup sequence...")
+            
             if process.stdin:
                 try:
+                    logger.info("Closing stdin...")
                     await process.stdin.aclose()
-                except Exception:
+                    logger.info("stdin closed")
+                except Exception as e:
                     # stdin might already be closed, which is fine
+                    logger.info(f"stdin close exception (ignored): {e}")
                     pass
 
             try:
                 # Give the process time to exit gracefully after stdin closes
+                logger.info("Waiting for process to exit after stdin closure...")
                 with anyio.fail_after(2.0):
                     await process.wait()
+                logger.info("Process exited gracefully")
             except TimeoutError:
                 # Process didn't exit from stdin closure, use our termination function
                 # that handles child processes properly
+                logger.info("Process didn't exit from stdin closure, terminating...")
                 await _terminate_process_with_children(process)
+                logger.info("Process terminated")
             except ProcessLookupError:
                 # Process already exited, which is fine
+                logger.info("Process already exited")
                 pass
 
+            logger.info("Closing streams...")
             await read_stream.aclose()
+            logger.info("read_stream closed")
             await write_stream.aclose()
+            logger.info("write_stream closed")
             await read_stream_writer.aclose()
+            logger.info("read_stream_writer closed")
             await write_stream_reader.aclose()
+            logger.info("write_stream_reader closed")
+            logger.info("Cleanup complete")
 
 
 def _get_executable_command(command: str) -> str:
@@ -265,6 +283,9 @@ async def _terminate_process_with_children(process: Process | FallbackProcess, t
         process: The process to terminate
         timeout: Time to wait for graceful termination before force killing
     """
+    import logging
+    logger = logging.getLogger("mcp.stdio_debug")
+    logger.info(f"_terminate_process_with_children called for process on {sys.platform}")
     if sys.platform != "win32":
         # POSIX: Kill entire process group to avoid orphaning children
         pid = getattr(process, "pid", None)
@@ -302,17 +323,23 @@ async def _terminate_process_with_children(process: Process | FallbackProcess, t
 
         # Try graceful termination first
         try:
+            logger.info(f"Calling terminate() on process with PID {pid}")
             process.terminate()
+            logger.info("Waiting for process to exit after terminate()...")
             with anyio.fail_after(timeout):
                 await process.wait()
+            logger.info("Process exited after terminate()")
         except TimeoutError:
             # Force kill using taskkill for tree termination
-            await anyio.to_thread.run_sync(
+            logger.info(f"Process didn't exit after terminate(), force killing with taskkill")
+            result = await anyio.to_thread.run_sync(
                 subprocess.run,
                 ["taskkill", "/F", "/T", "/PID", str(pid)],
                 capture_output=True,
                 shell=False,
                 check=False,
             )
+            logger.info(f"taskkill result: returncode={result.returncode}, stdout={result.stdout}, stderr={result.stderr}")
         except ProcessLookupError:
+            logger.info("Process already exited (ProcessLookupError)")
             pass