feat(subagent): 为subagent添加日志追踪

Author: elecvoid243

astrbot/core/agent/runners/tool_loop_agent_runner.py

@@ -989,6 +989,13 @@ def _append_tool_call_result(tool_call_id: str, content: str) -> None:
                 ),
             )
 
+        # 获取 trace span：优先使用 subagent trace_span，否则回退到 event.trace
+        _agent_ctx = getattr(self.run_context, "context", None)
+        _trace = getattr(_agent_ctx, "trace_span", None)
+        if _trace is None and _agent_ctx is not None:
+            _event = getattr(_agent_ctx, "event", None)
+            _trace = getattr(_event, "trace", None)
+
         # 执行函数调用
         for func_tool_name, func_tool_args, func_tool_id in zip(
             llm_response.tools_call_name,
@@ -1012,6 +1019,9 @@ def _append_tool_call_result(tool_call_id: str, content: str) -> None:
                     ],
                 )
             )
+            # 记录工具调用追踪
+            if _trace:
+                _trace.record("agent_tool_call", tool_name=func_tool_name)
             try:
                 if not req.func_tool:
                     return
@@ -1251,6 +1261,15 @@ def _append_tool_call_result(tool_call_id: str, content: str) -> None:
                     )
                 )
                 logger.info(f"Tool `{func_tool_name}` Result: {tool_result_content}")
+                # 记录工具结果追踪
+                if _trace:
+                    _trace.record(
+                        "agent_tool_result",
+                        tool_name=func_tool_name,
+                        tool_result=tool_result_content[:500]
+                        if tool_result_content
+                        else None,
+                    )
 
         # 处理函数调用响应
         if tool_call_result_blocks:

astrbot/core/astr_agent_context.py

@@ -18,6 +18,11 @@ class AstrAgentContext:
     """The message event associated with the agent context."""
     extra: dict[str, Any] = Field(default_factory=dict)
     """Customized extra data."""
+    trace_span: Any = Field(default=None)
+    """Optional custom TraceSpan for subagent tracing. When set, tool calls within
+    the agent loop will be recorded to this trace instead of event.trace.
+    This prevents concurrent subagent and main agent tool calls from mixing up
+    trace records."""
 
 
 AgentContextWrapper = ContextWrapper[AstrAgentContext]

astrbot/core/astr_agent_run_util.py

@@ -185,13 +185,6 @@ async def run_agent(
                 if resp.type == "tool_call_result":
                     msg_chain = resp.data["chain"]
 
-                    astr_event.trace.record(
-                        "agent_tool_result",
-                        tool_result=msg_chain.get_plain_text(
-                            with_other_comps_mark=True
-                        ),
-                    )
-
                     if msg_chain.type == "tool_direct_result":
                         # tool_direct_result 用于标记 llm tool 需要直接发送给用户的内容
                         await astr_event.send(msg_chain)
@@ -218,10 +211,6 @@ async def run_agent(
                         yield MessageChain(chain=[], type="break")
 
                     tool_info = _extract_chain_json_data(resp.data["chain"])
-                    astr_event.trace.record(
-                        "agent_tool_call",
-                        tool_name=tool_info if tool_info else "unknown",
-                    )
                     _record_tool_call_name(tool_info, tool_name_by_call_id)
 
                     if astr_event.get_platform_name() == "webchat":

astrbot/core/astr_agent_tool_exec.py

@@ -342,6 +342,7 @@ async def _execute_handoff(
         ctx = run_context.context.context
         event = run_context.context.event
         umo = event.unified_msg_origin
+        agent_name = getattr(tool.agent, "name", "unknown")
 
         # Use per-subagent provider override if configured; otherwise fall back
         # to the current/default provider resolution.
@@ -368,10 +369,38 @@ async def _execute_handoff(
         agent_max_step = int(prov_settings.get("max_agent_step", 30))
         stream = prov_settings.get("streaming_response", False)
 
+        # Create trace span for subagent execution
+        from astrbot.core.utils.trace import TraceSpan
+
+        parent_trace = getattr(event, "trace", None)
+        subagent_trace = TraceSpan(
+            name=f"SubAgent:{agent_name}",
+            umo=event.unified_msg_origin,
+            sender_name=event.get_sender_name()
+            if hasattr(event, "get_sender_name")
+            else None,
+            message_outline=f"Handoff to {agent_name}: {input_[:100] if input_ else ''}",
+            parent_span_id=parent_trace.span_id if parent_trace else None,
+        )
+        subagent_trace.record(
+            "subagent_execution_begin",
+            agent_name=agent_name,
+            input_preview=input_[:500] if input_ else None,
+            image_count=len(image_urls),
+            tools=[t.name for t in toolset] if toolset else [],
+            max_steps=agent_max_step,
+            stream=stream,
+        )
+
         # 获取子代理的历史上下文
         subagent_history, agent_name = cls._load_subagent_history(umo, tool)
         # 如果有历史上下文，合并到 contexts 中
         if subagent_history:
+            subagent_trace.record(
+                "subagent_history_loaded",
+                agent_name=agent_name,
+                history_messages_count=len(subagent_history),
+            )
             if contexts is None:
                 contexts = subagent_history
             else:
@@ -381,6 +410,14 @@ async def _execute_handoff(
         subagent_system_prompt = cls._build_subagent_system_prompt(
             umo, tool, prov_settings
         )
+        subagent_trace.record(
+            "subagent_system_prompt",
+            agent_name=agent_name,
+            prompt_length=len(subagent_system_prompt),
+            prompt_preview=subagent_system_prompt[:300]
+            if subagent_system_prompt
+            else None,
+        )
 
         # 构建子代理的追加内容
         extra_content_parts = SubAgentManager.build_subagent_extra_content_parts(
@@ -408,6 +445,7 @@ async def _run_subagent():
                 stream=stream,
                 runner_messages=runner_messages,
                 extra_user_content_parts=extra_content_parts,
+                trace_span=subagent_trace,
             )
 
         # 添加执行超时控制
@@ -419,6 +457,10 @@ async def _run_subagent():
             except asyncio.TimeoutError:
                 # 若超时，保存已产生的部分历史
                 cls._save_subagent_history(umo, runner_messages, agent_name)
+                subagent_trace.record(
+                    "subagent_execution_timeout",
+                    timeout_seconds=execution_timeout,
+                )
                 error_msg = f"SubAgent '{agent_name}' execution timeout after {execution_timeout:.1f} seconds."
                 logger.warning(f"[SubAgent:Timeout] {error_msg}")
 
@@ -433,8 +475,26 @@ async def _run_subagent():
         else:
             # 不设置超时
             llm_resp = await _run_subagent()
+
+        execution_time = time.time() - subagent_trace.started_at
+        subagent_trace.record(
+            "subagent_execution_complete",
+            agent_name=agent_name,
+            result_preview=llm_resp.completion_text[:500]
+            if hasattr(llm_resp, "completion_text") and llm_resp.completion_text
+            else None,
+            result_length=len(llm_resp.completion_text)
+            if hasattr(llm_resp, "completion_text") and llm_resp.completion_text
+            else 0,
+            execution_time=execution_time,
+        )
+
         # 保存历史上下文
         cls._save_subagent_history(umo, runner_messages, agent_name)
+        subagent_trace.record(
+            "subagent_history_saved",
+            messages_count=len(runner_messages),
+        )
 
         yield mcp.types.CallToolResult(
             content=[mcp.types.TextContent(type="text", text=llm_resp.completion_text)]
@@ -467,6 +527,26 @@ async def _execute_handoff_background(
 
         original_task_id = uuid.uuid4().hex
 
+        # Create trace span for background task creation
+        from astrbot.core.utils.trace import TraceSpan
+
+        parent_trace = getattr(event, "trace", None)
+        bg_trace = TraceSpan(
+            name=f"SubAgentBackground:{agent_name}",
+            umo=event.unified_msg_origin,
+            sender_name=event.get_sender_name()
+            if hasattr(event, "get_sender_name")
+            else None,
+            message_outline=f"Background handoff to {agent_name}",
+            parent_span_id=parent_trace.span_id if parent_trace else None,
+        )
+        bg_trace.record(
+            "subagent_background_task_created",
+            agent_name=agent_name,
+            subagent_task_id=subagent_task_id,
+            original_task_id=original_task_id,
+        )
+
         async def _run_handoff_in_background() -> None:
             try:
                 await cls._do_handoff_background(
@@ -515,6 +595,25 @@ async def _do_handoff_background(
         event = run_context.context.event
         umo = event.unified_msg_origin
         agent_name = getattr(tool.agent, "name", None)
+
+        # Create trace span for background subagent execution
+        from astrbot.core.utils.trace import TraceSpan
+
+        parent_trace = getattr(event, "trace", None)
+        bg_trace = TraceSpan(
+            name=f"SubAgentBackground:{agent_name}",
+            umo=event.unified_msg_origin,
+            sender_name=event.get_sender_name()
+            if hasattr(event, "get_sender_name")
+            else None,
+            message_outline=f"Background handoff to {agent_name}",
+            parent_span_id=parent_trace.span_id if parent_trace else None,
+        )
+        bg_trace.record(
+            "subagent_background_execution_start",
+            agent_name=agent_name,
+        )
+
         # 获取SubAgent的超时时间
         execution_timeout = cls._get_subagent_execution_timeout()
 
@@ -550,6 +649,14 @@ async def _run():
             )
 
         execution_time = time.time() - start_time
+        bg_trace.record(
+            "subagent_background_execution_end",
+            agent_name=agent_name,
+            success=error_text is None,
+            result_preview=result_text[:500] if result_text else None,
+            execution_time=execution_time,
+        )
+
         # Check if it's enhanced subagent
         is_managed = cls._is_managed_subagent(umo, agent_name)
         if is_managed:

astrbot/core/star/context.py

@@ -226,6 +226,7 @@ async def tool_loop_agent(
             agent_context = AstrAgentContext(
                 context=self,
                 event=event,
+                trace_span=kwargs.get("trace_span"),
             )
         agent_runner = ToolLoopAgentRunner()
         tool_executor = FunctionToolExecutor()

astrbot/core/subagent_manager.py

@@ -67,6 +67,7 @@ class SubAgentSession:
     )  # 后台subagent结果存储: {agent_name: {task_id: SubAgentExecutionResult}}
     # 任务计数器: {agent_name: next_task_id}
     background_task_counters: dict = field(default_factory=dict)
+    subagent_traces: dict = field(default_factory=dict)  # {agent_name: TraceSpan}
     last_activity_at: float = field(default_factory=time.time)  # 最后活跃时间戳
 
 
@@ -778,7 +779,16 @@ def set_shared_context_enabled(cls, session_id: str, enabled: bool) -> None:
     def set_subagent_status(cls, session_id: str, agent_name: str, status: str) -> None:
         session = cls._get_or_create_session(session_id)
         if agent_name in session.subagents:
+            old_status = session.subagent_status.get(agent_name, "UNKNOWN")
             session.subagent_status[agent_name] = status
+            trace = session.subagent_traces.get(agent_name)
+            if trace:
+                trace.record(
+                    "subagent_status_change",
+                    agent_name=agent_name,
+                    from_status=old_status,
+                    to_status=status,
+                )
 
     # for read-only operations
     @classmethod
@@ -845,11 +855,21 @@ async def create_subagent(
             protected: If True, the subagent will not be auto-cleaned per turn.
                        Static subagents from config should be protected.
         """
+        from astrbot.core.utils.trace import TraceSpan
+
+        trace = TraceSpan(name=f"SubAgent:{config.name}", umo=session_id)
         session = cls._get_or_create_session(session_id)
         if config.name not in session.subagents:
             # Check max count limit
             active_count = len(session.subagents.keys())
             if active_count >= cls._max_subagent_count:
+                trace.record(
+                    "subagent_created",
+                    agent_name=config.name,
+                    success=False,
+                    reason="max_count_reached",
+                    max_count=cls._max_subagent_count,
+                )
                 return (
                     f"Error: Maximum number of subagents ({cls._max_subagent_count}) reached. More subagents is not allowed.",
                     None,
@@ -892,6 +912,16 @@ async def create_subagent(
         # 如果标记为protected，则加入protected集合
         if protected:
             session.protected_agents.add(config.name)
+        trace.record(
+            "subagent_created",
+            agent_name=config.name,
+            success=True,
+            tools=list(config.tools) if config.tools else [],
+            skills=list(config.skills) if config.skills else [],
+            protected=protected,
+            provider_id=config.provider_id,
+        )
+        session.subagent_traces[config.name] = trace
         logger.info(
             "[SubAgent:Create] Created subagent: %s (protected=%s)",
             config.name,
@@ -927,6 +957,19 @@ def register_static_subagent(
         if (
             config.name not in session.subagents
         ):  # if the static agent already exists, pass
+            from astrbot.core.utils.trace import TraceSpan
+
+            trace = TraceSpan(name=f"SubAgent:{config.name}", umo=session_id)
+            trace.record(
+                "subagent_created",
+                agent_name=config.name,
+                success=True,
+                static=True,
+                tools=list(config.tools) if config.tools else [],
+                skills=list(config.skills) if config.skills else [],
+            )
+            session.subagent_traces[config.name] = trace
+
             if config.tools is None:
                 config.tools = None
             if config.tools is not None and not config.tools:
@@ -984,6 +1027,7 @@ def _remove_by_name(name):
             session.subagent_histories.pop(name, None)
             session.subagent_background_results.pop(name, None)
             session.background_task_counters.pop(name, None)
+            session.subagent_traces.pop(name, None)
             # 清理公共上下文中包含该Agent的内容
             cls.cleanup_shared_context_by_agent(session_id, name)
 
@@ -1004,6 +1048,7 @@ def _remove_by_name(name):
                 session.shared_context.clear()
                 session.subagent_background_results.clear()
                 session.background_task_counters.clear()
+                session.subagent_traces.clear()
                 logger.info("[SubAgent:Cleanup] All subagents cleaned.")
                 return "__SUBAGENT_REMOVED__: All subagents have been removed."
         else:
@@ -1165,6 +1210,17 @@ def store_subagent_result(
         if metadata:
             task_store[task_id].metadata.update(metadata)
 
+        trace = session.subagent_traces.get(agent_name)
+        if trace:
+            trace.record(
+                "subagent_result_stored",
+                agent_name=agent_name,
+                task_id=task_id,
+                success=success,
+                execution_time=execution_time,
+                has_error=error is not None,
+            )
+
     @classmethod
     def get_subagent_result(
         cls, session_id: str, agent_name: str, task_id: str | None = None