222 lines
7.6 KiB
Python
222 lines
7.6 KiB
Python
"""Debug script with detailed logging to find CLI test hang cause."""
|
|
|
|
from __future__ import annotations
|
|
|
|
import os
|
|
import sys
|
|
import asyncio
|
|
import logging
|
|
import time
|
|
|
|
sys.path.insert(0, "/home/tcmofashi/proj/l2d_backend/agentlite/src")
|
|
|
|
logging.basicConfig(
|
|
level=logging.DEBUG,
|
|
format="%(asctime)s [%(levelname)s] %(name)s: %(message)s",
|
|
datefmt="%H:%M:%S",
|
|
)
|
|
logger = logging.getLogger("debug")
|
|
|
|
# SiliconFlow DeepSeek-V3 (known good function calling support)
|
|
SILICONFLOW_BASE_URL = "https://api.siliconflow.cn/v1"
|
|
SILICONFLOW_MODEL = "Pro/deepseek-ai/DeepSeek-V3.2"
|
|
SILICONFLOW_API_KEY = "sk-eaxfgkkcuatochftxpevkyvltghigsrclzjzalybmaqycual"
|
|
|
|
|
|
async def main():
|
|
from agentlite import Agent, OpenAIProvider
|
|
from agentlite.tools.shell.shell import Shell
|
|
from agentlite.message import Message
|
|
|
|
logger.info("=" * 60)
|
|
logger.info("CLI Debug Test with DeepSeek-V3 (SiliconFlow)")
|
|
logger.info("=" * 60)
|
|
|
|
api_key = os.environ.get("SILICONFLOW_API_KEY") or SILICONFLOW_API_KEY
|
|
if not api_key:
|
|
logger.error("SILICONFLOW_API_KEY not set")
|
|
return
|
|
|
|
logger.info(f"Using model: {SILICONFLOW_MODEL}")
|
|
|
|
provider = OpenAIProvider(
|
|
api_key=api_key,
|
|
base_url=SILICONFLOW_BASE_URL,
|
|
model=SILICONFLOW_MODEL,
|
|
timeout=30.0,
|
|
)
|
|
|
|
agent = Agent(
|
|
provider=provider,
|
|
system_prompt="You are a shell assistant. Execute commands when asked. Reply briefly.",
|
|
tools=[Shell(timeout=10)],
|
|
max_iterations=5,
|
|
)
|
|
|
|
start_time = time.time()
|
|
message = "Run 'echo test' and tell me the result."
|
|
|
|
logger.info("\n=== Starting Agent Run ===")
|
|
logger.info(f"Message: {message}")
|
|
logger.info(f"Max iterations: {agent.max_iterations}")
|
|
logger.info(f"Tools: {[t.name for t in agent.tools.tools]}")
|
|
|
|
agent._history.append(Message(role="user", content=message))
|
|
|
|
iterations = 0
|
|
final_response = None
|
|
|
|
while iterations < agent.max_iterations:
|
|
iterations += 1
|
|
elapsed = time.time() - start_time
|
|
|
|
logger.info(f"\n{'=' * 50}")
|
|
logger.info(f"ITERATION {iterations}/{agent.max_iterations} (elapsed: {elapsed:.1f}s)")
|
|
logger.info(f"{'=' * 50}")
|
|
|
|
# Step 1: Call Provider
|
|
logger.info(">>> Step 1: Calling provider.generate()...")
|
|
step_start = time.time()
|
|
|
|
try:
|
|
stream = await asyncio.wait_for(
|
|
provider.generate(
|
|
system_prompt=agent.system_prompt,
|
|
tools=agent.tools.tools,
|
|
history=agent._history,
|
|
),
|
|
timeout=60.0,
|
|
)
|
|
logger.info(f"<<< Provider returned stream in {time.time() - step_start:.2f}s")
|
|
except asyncio.TimeoutError:
|
|
logger.error("!!! Provider call TIMEOUT after 60s")
|
|
final_response = "ERROR: Provider timeout"
|
|
break
|
|
|
|
# Step 2: Collect stream parts
|
|
logger.info(">>> Step 2: Collecting stream parts...")
|
|
step_start = time.time()
|
|
|
|
from agentlite.message import TextPart, ToolCall, ContentPart
|
|
|
|
response_parts = []
|
|
tool_calls = []
|
|
chunk_count = 0
|
|
|
|
try:
|
|
async for part in stream:
|
|
chunk_count += 1
|
|
if chunk_count % 10 == 0:
|
|
logger.debug(f" Received chunk #{chunk_count}")
|
|
|
|
if isinstance(part, ToolCall):
|
|
tool_calls.append(part)
|
|
logger.info(
|
|
f" ToolCall received: {part.function.name if hasattr(part, 'function') else part}"
|
|
)
|
|
elif isinstance(part, ContentPart):
|
|
response_parts.append(part)
|
|
if isinstance(part, TextPart):
|
|
logger.debug(f" Text: {part.text[:50]}...")
|
|
|
|
logger.info(
|
|
f"<<< Stream finished in {time.time() - step_start:.2f}s, {chunk_count} chunks"
|
|
)
|
|
except asyncio.TimeoutError:
|
|
logger.error("!!! Stream reading TIMEOUT")
|
|
final_response = "ERROR: Stream timeout"
|
|
break
|
|
except Exception as e:
|
|
logger.error(f"!!! Stream error: {type(e).__name__}: {e}")
|
|
final_response = f"ERROR: Stream error - {e}"
|
|
break
|
|
|
|
# Extract text
|
|
response_text = ""
|
|
for part in response_parts:
|
|
if isinstance(part, TextPart):
|
|
response_text += part.text
|
|
logger.info(f"Response text ({len(response_text)} chars): {response_text[:100]}...")
|
|
logger.info(f"Tool calls: {len(tool_calls)}")
|
|
|
|
# Add to history
|
|
agent._history.append(
|
|
Message(
|
|
role="assistant",
|
|
content=response_parts,
|
|
tool_calls=tool_calls if tool_calls else None,
|
|
)
|
|
)
|
|
|
|
# Step 3: Check if done
|
|
if not tool_calls:
|
|
elapsed = time.time() - start_time
|
|
logger.info(f"\n=== Agent completed in {elapsed:.2f}s, {iterations} iterations ===")
|
|
final_response = response_text
|
|
break
|
|
|
|
# Step 4: Execute tool calls
|
|
logger.info(f"\n>>> Step 3: Executing {len(tool_calls)} tool calls...")
|
|
step_start = time.time()
|
|
|
|
for i, tc in enumerate(tool_calls):
|
|
func_name = tc.function.name if hasattr(tc, "function") else str(tc)
|
|
func_args = tc.function.arguments if hasattr(tc, "function") else ""
|
|
logger.info(f" Tool #{i + 1}: {func_name}")
|
|
logger.info(f" Args: {func_args[:200]}...")
|
|
|
|
try:
|
|
result = await asyncio.wait_for(
|
|
agent.tools.handle(tc),
|
|
timeout=30.0,
|
|
)
|
|
output = result.output if hasattr(result, "output") else str(result)
|
|
is_error = result.is_error if hasattr(result, "is_error") else False
|
|
logger.info(
|
|
f" Result: is_error={is_error}, output_len={len(output) if output else 0}"
|
|
)
|
|
output_preview = output[:100] if output else "None"
|
|
logger.info(f" Output preview: {output_preview}...")
|
|
except asyncio.TimeoutError:
|
|
logger.error(" !!! Tool execution TIMEOUT")
|
|
output = "Tool execution timed out"
|
|
is_error = True
|
|
except Exception as e:
|
|
logger.error(f" !!! Tool error: {type(e).__name__}: {e}")
|
|
output = str(e)
|
|
is_error = True
|
|
|
|
# Add tool result to history
|
|
agent._history.append(
|
|
Message(
|
|
role="tool",
|
|
content=output,
|
|
tool_call_id=tc.id if hasattr(tc, "id") else f"tc_{i}",
|
|
)
|
|
)
|
|
|
|
logger.info(f"<<< Tool execution finished in {time.time() - step_start:.2f}s")
|
|
|
|
# Check overall timeout
|
|
elapsed = time.time() - start_time
|
|
if elapsed > 90:
|
|
logger.warning(f"!!! Overall timeout approaching ({elapsed:.1f}s)")
|
|
final_response = f"Timeout after {iterations} iterations"
|
|
break
|
|
|
|
if iterations >= agent.max_iterations:
|
|
logger.warning(f"!!! Max iterations reached ({agent.max_iterations})")
|
|
final_response = f"Max iterations ({agent.max_iterations}) reached"
|
|
|
|
logger.info(f"\n{'=' * 60}")
|
|
logger.info("FINAL RESULT:")
|
|
logger.info(f"{'=' * 60}")
|
|
logger.info(f"{final_response}")
|
|
logger.info(f"Total iterations: {iterations}")
|
|
logger.info(f"Total time: {time.time() - start_time:.2f}s")
|
|
logger.info(f"History length: {len(agent._history)}")
|
|
|
|
|
|
if __name__ == "__main__":
|
|
asyncio.run(main())
|