diff --git a/agent/pty_process.py b/agent/pty_process.py index 73c16bb..0e0a8c6 100644 --- a/agent/pty_process.py +++ b/agent/pty_process.py @@ -53,7 +53,10 @@ async def run_claude( else: args = ["claude"] + base_args - logger.debug("Running: %s (cwd=%s)", " ".join(args[:6]), cwd) + logger.debug( + "[worker] cmd=%s session_id=%s resume=%s cwd=%s prompt=%r", + " ".join(args[:6]), cc_session_id, resume, cwd, prompt[:120], + ) proc = await asyncio.create_subprocess_exec( *args, @@ -69,6 +72,7 @@ async def run_claude( except asyncio.TimeoutError: proc.kill() await proc.communicate() + logger.warning("[worker] timed out after %.0fs session_id=%s", timeout, cc_session_id) return f"[Timed out after {timeout:.0f}s]" output = stdout_bytes.decode("utf-8", errors="replace") @@ -76,10 +80,12 @@ async def run_claude( if proc.returncode != 0: err = stderr_bytes.decode("utf-8", errors="replace").strip() - logger.warning("claude -p exited %d: %s", proc.returncode, err[:200]) + logger.warning("[worker] exit=%d stderr=%r", proc.returncode, err[:200]) if not output: output = f"[Error exit {proc.returncode}] {err[:500]}" + logger.debug("[worker] output (%d chars): %r", len(output), output[:300]) + if len(output) > MAX_OUTPUT_CHARS: output = output[:MAX_OUTPUT_CHARS] + "\n...[truncated]" diff --git a/bot/feishu.py b/bot/feishu.py index d742cc1..c15d5a7 100644 --- a/bot/feishu.py +++ b/bot/feishu.py @@ -47,7 +47,12 @@ async def send_text(receive_id: str, receive_id_type: str, text: str) -> None: text: message content. """ import json as _json - content = _json.dumps({"text": _truncate(text)}, ensure_ascii=False) + truncated = _truncate(text) + logger.debug( + "[feishu] send_text to=%s type=%s len=%d/%d text=%r", + receive_id, receive_id_type, len(truncated), len(text), truncated[:120], + ) + content = _json.dumps({"text": truncated}, ensure_ascii=False) request = ( CreateMessageRequest.builder() diff --git a/main.py b/main.py index f2f2e20..3028500 100644 --- a/main.py +++ b/main.py @@ -7,14 +7,20 @@ import logging import uvicorn from fastapi import FastAPI +from rich.logging import RichHandler from agent.manager import manager from bot.handler import start_websocket_client logging.basicConfig( - level=logging.INFO, - format="%(asctime)s [%(levelname)s] %(name)s: %(message)s", + level=logging.DEBUG, + format="%(message)s", + datefmt="[%X]", + handlers=[RichHandler(rich_tracebacks=True, markup=True)], ) +# Suppress noisy third-party debug output +for _noisy in ("httpcore", "httpx", "openai._base_client", "urllib3", "lark_oapi", "websockets"): + logging.getLogger(_noisy).setLevel(logging.WARNING) logger = logging.getLogger(__name__) app = FastAPI(title="PhoneWork", version="0.1.0") diff --git a/orchestrator/agent.py b/orchestrator/agent.py index bc4d08a..c316686 100644 --- a/orchestrator/agent.py +++ b/orchestrator/agent.py @@ -83,22 +83,36 @@ class OrchestrationAgent: async def run(self, user_id: str, text: str) -> str: """Process a user message and return the agent's reply.""" + active_conv = self._active_conv[user_id] + logger.debug( + "[mailboy] run | user=%s active_conv=%s msg=%r", + user_id, active_conv, text[:120], + ) + messages: List[BaseMessage] = ( [SystemMessage(content=self._build_system_prompt(user_id))] + self._history[user_id] + [HumanMessage(content=text)] ) + logger.debug("[mailboy] history_len=%d", len(self._history[user_id])) reply = "" try: - for _ in range(MAX_ITERATIONS): + for iteration in range(MAX_ITERATIONS): + logger.debug("[mailboy] LLM call iteration=%d", iteration) ai_msg: AIMessage = await self._llm_with_tools.ainvoke(messages) messages.append(ai_msg) if not ai_msg.tool_calls: reply = ai_msg.content or "" + logger.debug("[mailboy] final reply (no tool calls): %r", reply[:200]) break + logger.debug( + "[mailboy] tool_calls=%s", + [(tc["name"], tc["args"]) for tc in ai_msg.tool_calls], + ) + for tc in ai_msg.tool_calls: tool_name = tc["name"] tool_args = tc["args"] @@ -107,11 +121,15 @@ class OrchestrationAgent: tool_obj = _TOOL_MAP.get(tool_name) if tool_obj is None: result = f"Unknown tool: {tool_name}" + logger.warning("[mailboy] unknown tool: %s", tool_name) else: + logger.debug("[mailboy] calling tool %s args=%s", tool_name, tool_args) try: result = await tool_obj.arun(tool_args) except Exception as exc: result = f"Tool error: {exc}" + logger.error("[mailboy] tool %s error: %s", tool_name, exc) + logger.debug("[mailboy] tool %s result: %r", tool_name, str(result)[:300]) # If a session was just created, record it as the active session if tool_name == "create_conversation": @@ -120,7 +138,7 @@ class OrchestrationAgent: if "conv_id" in data: self._active_conv[user_id] = data["conv_id"] logger.info( - "Active session for %s set to %s", + "[mailboy] active session for %s set to %s", user_id, data["conv_id"], ) except Exception: @@ -131,11 +149,14 @@ class OrchestrationAgent: ) else: reply = "[Max iterations reached]" + logger.warning("[mailboy] max iterations reached for user=%s", user_id) except Exception as exc: - logger.exception("Agent error for user %s", user_id) + logger.exception("[mailboy] agent error for user=%s", user_id) reply = f"[Error] {exc}" + logger.info("[mailboy] user=%s reply=%r", user_id, reply[:200]) + # Update history self._history[user_id].append(HumanMessage(content=text)) self._history[user_id].append(AIMessage(content=reply)) diff --git a/requirements.txt b/requirements.txt index 6fedd38..676a87f 100644 --- a/requirements.txt +++ b/requirements.txt @@ -6,3 +6,4 @@ langchain-openai>=0.1.0 langchain-community>=0.2.0 pywinpty>=2.0.0 pyyaml>=6.0.0 +rich>=13.0.0