refactor(logging): 优化日志格式和内容以提高可读性
- 调整日志格式，增加模块名显示 - 将部分debug日志升级为info级别以增加可见性 - 简化日志消息，缩短显示长度 - 统一日志前缀格式 - 优化工具调用日志显示
This commit is contained in:
Yuyao Huang (Sam)
parent
b67e2dd2db
commit
c3741ea006
@ -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]"
|
||||
|
||||
@ -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
|
||||
|
||||
9
main.py
9
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"):
|
||||
|
||||
@ -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))
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user