From c3741ea006047ae187f5da52f2ddba6a03b389d2 Mon Sep 17 00:00:00 2001 From: "Yuyao Huang (Sam)" Date: Sat, 28 Mar 2026 08:09:10 +0800 Subject: [PATCH] =?UTF-8?q?refactor(logging):=20=E4=BC=98=E5=8C=96?= =?UTF-8?q?=E6=97=A5=E5=BF=97=E6=A0=BC=E5=BC=8F=E5=92=8C=E5=86=85=E5=AE=B9?= =?UTF-8?q?=E4=BB=A5=E6=8F=90=E9=AB=98=E5=8F=AF=E8=AF=BB=E6=80=A7?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - 调整日志格式，增加模块名显示 - 将部分debug日志升级为info级别以增加可见性 - 简化日志消息，缩短显示长度 - 统一日志前缀格式 - 优化工具调用日志显示 --- agent/pty_process.py | 10 ++++++---- bot/handler.py | 8 ++++---- main.py | 9 +++++++-- orchestrator/agent.py | 42 ++++++++++++++++++------------------------ 4 files changed, 35 insertions(+), 34 deletions(-) diff --git a/agent/pty_process.py b/agent/pty_process.py index 0e0a8c6..ffd132d 100644 --- a/agent/pty_process.py +++ b/agent/pty_process.py @@ -53,9 +53,11 @@ async def run_claude( else: args = ["claude"] + base_args - logger.debug( - "[worker] cmd=%s session_id=%s resume=%s cwd=%s prompt=%r", - " ".join(args[:6]), cc_session_id, resume, cwd, prompt[:120], + logger.info( + "[worker] %s cwd=%s prompt=%r", + ("resume" if resume else "new") + f"/{cc_session_id[:8] if cc_session_id else '-'}", + cwd, + prompt[:80], ) proc = await asyncio.create_subprocess_exec( @@ -84,7 +86,7 @@ async def run_claude( if not output: output = f"[Error exit {proc.returncode}] {err[:500]}" - logger.debug("[worker] output (%d chars): %r", len(output), output[:300]) + logger.info("[worker] output (%d chars): %r", len(output), output[:120]) if len(output) > MAX_OUTPUT_CHARS: output = output[:MAX_OUTPUT_CHARS] + "\n...[truncated]" diff --git a/bot/handler.py b/bot/handler.py index a06d795..071c8b9 100644 --- a/bot/handler.py +++ b/bot/handler.py @@ -30,11 +30,11 @@ def _handle_message(data: P2ImMessageReceiveV1) -> None: sender = data.event.sender # Log raw event for debugging - logger.info( - "RAW event: type=%r content=%r chat_type=%r", + logger.debug( + "event type=%r chat_type=%r content=%r", getattr(message, "message_type", None), - getattr(message, "content", None), getattr(message, "chat_type", None), + (getattr(message, "content", None) or "")[:100], ) # Only handle text messages @@ -60,7 +60,7 @@ def _handle_message(data: P2ImMessageReceiveV1) -> None: logger.info("Empty text after stripping, ignoring") return - logger.info("Received message from %s in %s: %r", open_id, chat_id, text[:80]) + logger.info("✉ ...%s → %r", open_id[-8:], text[:80]) # Use open_id as user identifier for per-user history in the orchestrator user_id = open_id or chat_id diff --git a/main.py b/main.py index 3028500..b00dae6 100644 --- a/main.py +++ b/main.py @@ -14,9 +14,14 @@ from bot.handler import start_websocket_client logging.basicConfig( level=logging.DEBUG, - format="%(message)s", + format="%(name)-20s %(message)s", datefmt="[%X]", - handlers=[RichHandler(rich_tracebacks=True, markup=True)], + handlers=[RichHandler( + rich_tracebacks=True, + markup=True, + show_path=False, + omit_repeated_times=False, + )], ) # Suppress noisy third-party debug output for _noisy in ("httpcore", "httpx", "openai._base_client", "urllib3", "lark_oapi", "websockets"): diff --git a/orchestrator/agent.py b/orchestrator/agent.py index c316686..c638cc1 100644 --- a/orchestrator/agent.py +++ b/orchestrator/agent.py @@ -84,63 +84,57 @@ 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], - ) + short_uid = user_id[-8:] + logger.info(">>> user=...%s conv=%s msg=%r", short_uid, active_conv, text[:80]) + logger.debug(" history_len=%d", len(self._history[user_id])) 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 iteration in range(MAX_ITERATIONS): - logger.debug("[mailboy] LLM call iteration=%d", iteration) + logger.debug(" LLM call #%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]) + logger.debug(" → done (no tool call)") 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"] tool_id = tc["id"] + args_summary = ", ".join( + f"{k}={str(v)[:50]!r}" for k, v in tool_args.items() + ) + logger.info(" ⚙ %s(%s)", tool_name, args_summary) + 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) + logger.warning(" 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]) + logger.error(" tool %s error: %s", tool_name, exc) + + logger.debug(" ← %s: %r", tool_name, str(result)[:120]) - # If a session was just created, record it as the active session if tool_name == "create_conversation": try: data = json.loads(result) if "conv_id" in data: self._active_conv[user_id] = data["conv_id"] - logger.info( - "[mailboy] active session for %s set to %s", - user_id, data["conv_id"], - ) + logger.info(" ✓ active session → %s", data["conv_id"]) except Exception: pass @@ -149,13 +143,13 @@ class OrchestrationAgent: ) else: reply = "[Max iterations reached]" - logger.warning("[mailboy] max iterations reached for user=%s", user_id) + logger.warning(" max iterations reached") except Exception as exc: - logger.exception("[mailboy] agent error for user=%s", user_id) + logger.exception("agent error for user=%s", user_id) reply = f"[Error] {exc}" - logger.info("[mailboy] user=%s reply=%r", user_id, reply[:200]) + logger.info("<<< reply: %r", reply[:120]) # Update history self._history[user_id].append(HumanMessage(content=text))