1+ #!/usr/bin/env python
2+ # examples/debug_timeout_source.py
3+ """
4+ Trace the exact source of the 10-second timeout by instrumenting all timeout-related calls.
5+ """
6+
7+ import asyncio
8+ import sys
9+ import time
10+ import inspect
11+ from pathlib import Path
12+ from unittest .mock import patch , AsyncMock
13+
14+ # Add project root to path
15+ PROJECT_ROOT = Path (__file__ ).resolve ().parents [1 ]
16+ sys .path .insert (0 , str (PROJECT_ROOT ))
17+
18+ from chuk_tool_processor .execution .strategies .inprocess_strategy import InProcessStrategy
19+ from chuk_tool_processor .execution .tool_executor import ToolExecutor
20+ from chuk_tool_processor .registry .provider import ToolRegistryProvider
21+ from chuk_tool_processor .models .tool_call import ToolCall
22+ from chuk_tool_processor .mcp .setup_mcp_sse import setup_mcp_sse
23+
24+ # Store original functions
25+ original_wait_for = asyncio .wait_for
26+
27+ def get_call_stack ():
28+ """Get a simplified call stack for debugging."""
29+ stack = inspect .stack ()
30+ relevant_frames = []
31+ for frame in stack [2 :8 ]: # Skip this function and the wrapper
32+ filename = Path (frame .filename ).name
33+ relevant_frames .append (f"{ filename } { frame .lineno } { frame .function } )
34+ return " -> " .join (relevant_frames )
35+
36+ async def traced_wait_for (coro , timeout = None ):
37+ """Trace all asyncio.wait_for calls with their timeouts."""
38+ caller_stack = get_call_stack ()
39+ print (f" 🔍 asyncio.wait_for(timeout={ timeout } { caller_stack } )
40+
41+ start_time = time .time ()
42+ try :
43+ result = await original_wait_for (coro , timeout )
44+ duration = time .time () - start_time
45+ print (f" ✅ wait_for completed in { duration :.3f} { timeout } )
46+ return result
47+ except asyncio .TimeoutError :
48+ duration = time .time () - start_time
49+ print (f" ⏰ wait_for TIMED OUT after { duration :.3f} { timeout } )
50+ raise
51+ except Exception as e :
52+ duration = time .time () - start_time
53+ print (f" ❌ wait_for failed after { duration :.3f} { e } )
54+ raise
55+
56+ async def debug_timeout_source ():
57+ """Debug to find the exact source of the 10-second timeout."""
58+
59+ print ("=== Tracing Timeout Sources ===\n " )
60+
61+ # Patch asyncio.wait_for globally
62+ with patch ('asyncio.wait_for' , traced_wait_for ):
63+ # Also patch it in specific modules that might import it
64+ with patch ('chuk_tool_processor.execution.strategies.inprocess_strategy.asyncio.wait_for' , traced_wait_for ):
65+ with patch ('chuk_tool_processor.mcp.stream_manager.asyncio.wait_for' , traced_wait_for ):
66+
67+ # Connect to mock server
68+ try :
69+ print ("1. Connecting to mock MCP SSE server..." )
70+ _ , stream_manager = await setup_mcp_sse (
71+ servers = [
72+ {
73+ "name" : "mock_server" ,
74+ "url" : "http://localhost:8020" ,
75+ }
76+ ],
77+ server_names = {0 : "mock_server" },
78+ namespace = "sse" ,
79+ )
80+ print ("✅ Connected successfully\n " )
81+ except Exception as e :
82+ print (f"❌ Connection failed: { e } )
83+ return
84+
85+ registry = await ToolRegistryProvider .get_registry ()
86+
87+ # Test with 1 second timeout to see where the 10s comes from
88+ print (f"2. Testing 1 second timeout with comprehensive tracing..." )
89+
90+ strategy = InProcessStrategy (
91+ registry ,
92+ default_timeout = 1.0
93+ )
94+
95+ executor = ToolExecutor (registry = registry , strategy = strategy )
96+
97+ test_call = ToolCall (
98+ tool = "perplexity_search" ,
99+ namespace = "sse" ,
100+ arguments = {"query" : "Timeout tracing test" }
101+ )
102+
103+ print (f" Strategy default_timeout: { strategy .default_timeout } )
104+ print (f" Executing with full timeout tracing...\n " )
105+
106+ try :
107+ start_time = time .time ()
108+
109+ results = await executor .execute ([test_call ])
110+
111+ duration = time .time () - start_time
112+ result = results [0 ]
113+
114+ print (f"\n ✅ Total execution completed in { duration :.3f} )
115+ print (f" Result duration: { (result .end_time - result .start_time ).total_seconds ():.3f} )
116+
117+ if result .error :
118+ print (f" ⚠️ Error: { result .error } )
119+
120+ # Check if error message contains timeout info
121+ if "timeout" in result .error .lower ():
122+ print (f" 🔍 Timeout error detected! Message: { result .error } )
123+ else :
124+ print (f" 📝 Success" )
125+
126+ except Exception as e :
127+ duration = time .time () - start_time
128+ print (f"\n ❌ Failed after { duration :.3f} { e } )
129+
130+ # Also test the StreamManager call_tool directly
131+ print (f"\n 3. Testing StreamManager.call_tool directly..." )
132+
133+ try :
134+ start_time = time .time ()
135+
136+ # Call the stream manager directly to see if it has its own timeout
137+ result = await stream_manager .call_tool (
138+ tool_name = "perplexity_search" ,
139+ arguments = {"query" : "Direct StreamManager test" }
140+ )
141+
142+ duration = time .time () - start_time
143+ print (f" ✅ Direct call completed in { duration :.3f} )
144+
145+ if result .get ("isError" ):
146+ print (f" ⚠️ Error: { result .get ('error' )} )
147+ else :
148+ print (f" 📝 Success" )
149+
150+ except Exception as e :
151+ duration = time .time () - start_time
152+ print (f" ❌ Direct call failed after { duration :.3f} { e } )
153+
154+ # Test transport layer directly
155+ print (f"\n 4. Testing transport layer..." )
156+
157+ transport = stream_manager .transports .get ("mock_server" )
158+ if transport :
159+ try :
160+ start_time = time .time ()
161+
162+ result = await transport .call_tool (
163+ "perplexity_search" ,
164+ {"query" : "Direct transport test" }
165+ )
166+
167+ duration = time .time () - start_time
168+ print (f" ✅ Transport call completed in { duration :.3f} )
169+
170+ if result .get ("isError" ):
171+ print (f" ⚠️ Error: { result .get ('error' )} )
172+ else :
173+ print (f" 📝 Success" )
174+
175+ except Exception as e :
176+ duration = time .time () - start_time
177+ print (f" ❌ Transport call failed after { duration :.3f} { e } )
178+ else :
179+ print (" ❌ No transport found for mock_server" )
180+
181+ # Cleanup
182+ await stream_manager .close ()
183+ print (f"\n ✅ Timeout source tracing completed!" )
184+
185+ if __name__ == "__main__" :
186+ asyncio .run (debug_timeout_source ())
0 commit comments