feat: 增强日志功能并添加rich依赖

- 添加rich库依赖以改进日志显示
- 在各模块添加详细调试日志,包括消息处理、命令执行和工具调用过程
- 使用RichHandler美化日志输出并抑制第三方库的噪音日志
- 在关键路径添加日志记录,便于问题排查
This commit is contained in:
Yuyao Huang (Sam) 2026-03-28 07:57:24 +08:00
parent 0eb29f2dcc
commit b67e2dd2db
5 changed files with 47 additions and 8 deletions

View File

@ -53,7 +53,10 @@ async def run_claude(
else: else:
args = ["claude"] + base_args 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( proc = await asyncio.create_subprocess_exec(
*args, *args,
@ -69,6 +72,7 @@ async def run_claude(
except asyncio.TimeoutError: except asyncio.TimeoutError:
proc.kill() proc.kill()
await proc.communicate() 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]" return f"[Timed out after {timeout:.0f}s]"
output = stdout_bytes.decode("utf-8", errors="replace") output = stdout_bytes.decode("utf-8", errors="replace")
@ -76,10 +80,12 @@ async def run_claude(
if proc.returncode != 0: if proc.returncode != 0:
err = stderr_bytes.decode("utf-8", errors="replace").strip() 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: if not output:
output = f"[Error exit {proc.returncode}] {err[:500]}" 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: if len(output) > MAX_OUTPUT_CHARS:
output = output[:MAX_OUTPUT_CHARS] + "\n...[truncated]" output = output[:MAX_OUTPUT_CHARS] + "\n...[truncated]"

View File

@ -47,7 +47,12 @@ async def send_text(receive_id: str, receive_id_type: str, text: str) -> None:
text: message content. text: message content.
""" """
import json as _json 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 = ( request = (
CreateMessageRequest.builder() CreateMessageRequest.builder()

10
main.py
View File

@ -7,14 +7,20 @@ import logging
import uvicorn import uvicorn
from fastapi import FastAPI from fastapi import FastAPI
from rich.logging import RichHandler
from agent.manager import manager from agent.manager import manager
from bot.handler import start_websocket_client from bot.handler import start_websocket_client
logging.basicConfig( logging.basicConfig(
level=logging.INFO, level=logging.DEBUG,
format="%(asctime)s [%(levelname)s] %(name)s: %(message)s", 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__) logger = logging.getLogger(__name__)
app = FastAPI(title="PhoneWork", version="0.1.0") app = FastAPI(title="PhoneWork", version="0.1.0")

View File

@ -83,22 +83,36 @@ class OrchestrationAgent:
async def run(self, user_id: str, text: str) -> str: async def run(self, user_id: str, text: str) -> str:
"""Process a user message and return the agent's reply.""" """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] = ( messages: List[BaseMessage] = (
[SystemMessage(content=self._build_system_prompt(user_id))] [SystemMessage(content=self._build_system_prompt(user_id))]
+ self._history[user_id] + self._history[user_id]
+ [HumanMessage(content=text)] + [HumanMessage(content=text)]
) )
logger.debug("[mailboy] history_len=%d", len(self._history[user_id]))
reply = "" reply = ""
try: 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) ai_msg: AIMessage = await self._llm_with_tools.ainvoke(messages)
messages.append(ai_msg) messages.append(ai_msg)
if not ai_msg.tool_calls: if not ai_msg.tool_calls:
reply = ai_msg.content or "" reply = ai_msg.content or ""
logger.debug("[mailboy] final reply (no tool calls): %r", reply[:200])
break 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: for tc in ai_msg.tool_calls:
tool_name = tc["name"] tool_name = tc["name"]
tool_args = tc["args"] tool_args = tc["args"]
@ -107,11 +121,15 @@ class OrchestrationAgent:
tool_obj = _TOOL_MAP.get(tool_name) tool_obj = _TOOL_MAP.get(tool_name)
if tool_obj is None: if tool_obj is None:
result = f"Unknown tool: {tool_name}" result = f"Unknown tool: {tool_name}"
logger.warning("[mailboy] unknown tool: %s", tool_name)
else: else:
logger.debug("[mailboy] calling tool %s args=%s", tool_name, tool_args)
try: try:
result = await tool_obj.arun(tool_args) result = await tool_obj.arun(tool_args)
except Exception as exc: except Exception as exc:
result = f"Tool error: {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 a session was just created, record it as the active session
if tool_name == "create_conversation": if tool_name == "create_conversation":
@ -120,7 +138,7 @@ class OrchestrationAgent:
if "conv_id" in data: if "conv_id" in data:
self._active_conv[user_id] = data["conv_id"] self._active_conv[user_id] = data["conv_id"]
logger.info( logger.info(
"Active session for %s set to %s", "[mailboy] active session for %s set to %s",
user_id, data["conv_id"], user_id, data["conv_id"],
) )
except Exception: except Exception:
@ -131,11 +149,14 @@ class OrchestrationAgent:
) )
else: else:
reply = "[Max iterations reached]" reply = "[Max iterations reached]"
logger.warning("[mailboy] max iterations reached for user=%s", user_id)
except Exception as exc: 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}" reply = f"[Error] {exc}"
logger.info("[mailboy] user=%s reply=%r", user_id, reply[:200])
# Update history # Update history
self._history[user_id].append(HumanMessage(content=text)) self._history[user_id].append(HumanMessage(content=text))
self._history[user_id].append(AIMessage(content=reply)) self._history[user_id].append(AIMessage(content=reply))

View File

@ -6,3 +6,4 @@ langchain-openai>=0.1.0
langchain-community>=0.2.0 langchain-community>=0.2.0
pywinpty>=2.0.0 pywinpty>=2.0.0
pyyaml>=6.0.0 pyyaml>=6.0.0
rich>=13.0.0