结构化日志

引言 Agent系统的日志不仅是排障工具，更是质量改进和安全审计的数据基础。一次Agent对话可能涉及路由决策、记忆检索、工具调用、LLM推理等多个步骤，跨越多个微服务。如何在分布式环境中建立完整的日志链路，是Agent系统可观测性的核心挑战。 日志架构全景 ┌──────────────────────────────────────────────────────┐ │ 日志数据流 │ │ │ │ Agent Services │ │ ┌─────┐ ┌─────┐ ┌─────┐ ┌─────┐ │ │ │Router│ │Tool │ │LLM │ │Memory│ │ │ └──┬──┘ └──┬──┘ └──┬──┘ └──┬──┘ │ │ │ │ │ │ │ │ ▼ ▼ ▼ ▼ │ │ ┌──────────────────────────────┐ │ │ │ Fluent Bit (采集) │ │ │ └──────────┬───────────────────┘ │ │ │ │ │ ┌───────┼───────┐ │ │ ▼ ▼ │ │ ┌──────┐ ┌──────────┐ │ │ │ Loki │ │Elasticsearch│ │ │ │(日志) │ │ (全文搜索) │ │ │ └──────┘ └──────────┘ │ │ │ │ │ │ └───────┬───────┘ │ │ ▼ │ │ ┌──────────────┐ │ │ │ Grafana │ │ │ │ (可视化) │ │ │ └──────────────┘ │ └──────────────────────────────────────────────────────┘ 结构化日志标准 import structlog from datetime import datetime import uuid # 结构化日志配置 structlog.configure( processors=[ structlog.stdlib.add_log_level, structlog.processors.TimeStamper(fmt="iso"), structlog.processors.JSONRenderer() ], wrapper_class=structlog.stdlib.BoundLogger, logger_factory=structlog.stdlib.LoggerFactory(), ) logger = structlog.get_logger() class AgentLogger: """Agent专用日志器""" @staticmethod def log_request( session_id: str, request_id: str, user_input: str, route_decision: dict ): """记录请求日志""" logger.info( "agent_request_received", session_id=session_id, request_id=request_id, user_input_length=len(user_input), user_input_preview=user_input[:100], route_model=route_decision.get("model"), route_tools=route_decision.get("tools"), timestamp=datetime.now().isoformat() ) @staticmethod def log_tool_call( session_id: str, request_id: str, tool_name: str, params: dict, result: dict, latency_ms: float, success: bool ): """记录工具调用日志""" logger.info( "tool_call_completed", session_id=session_id, request_id=request_id, tool_name=tool_name, params_hash=hash(str(sorted(params.items()))), result_size=len(str(result)), latency_ms=latency_ms, success=success, error=result.get("error") if not success else None ) @staticmethod def log_llm_call( session_id: str, request_id: str, model: str, prompt_tokens: int, completion_tokens: int, latency_ms: float, quality_score: float = None ): """记录LLM调用日志""" logger.info( "llm_call_completed", session_id=session_id, request_id=request_id, model=model, prompt_tokens=prompt_tokens, completion_tokens=completion_tokens, total_tokens=prompt_tokens + completion_tokens, latency_ms=latency_ms, quality_score=quality_score ) @staticmethod def log_agent_decision( session_id: str, decision_type: str, reasoning: str, action: str, confidence: float ): """记录Agent决策日志——用于审计和改进""" logger.info( "agent_decision", session_id=session_id, decision_type=decision_type, # route, tool_select, terminate reasoning=reasoning[:500], # 截断推理过程 action=action, confidence=confidence ) Trace ID传播 from opentelemetry import trace from opentelemetry.propagate import inject, extract class TracingMiddleware: """分布式追踪中间件""" async def __call__(self, request, call_next): # 提取或生成trace context context = extract(request.headers) tracer = trace.get_tracer(__name__) with tracer.start_as_current_span( "agent_request", context=context, attributes={ "session_id": request.session_id, "user_id": request.user_id, } ) as span: # 在请求上下文中注入trace信息 headers = {} inject(headers) request.trace_context = headers try: response = await call_next(request) span.set_attribute("response.status", "success") span.set_attribute( "response.latency_ms", response.latency_ms ) return response except Exception as e: span.record_exception(e) span.set_status(trace.Status(trace.StatusCode.ERROR)) raise # 在服务间调用时传播Trace ID class ServiceClient: """带Trace传播的服务客户端""" async def call_service( self, service: str, method: str, data: dict, trace_context: dict = None ) -> dict: """调用其他微服务""" headers = { "Content-Type": "application/json", } # 注入trace context if trace_context: headers.update(trace_context) else: inject(headers) # 从当前context注入 # 记录出站调用 tracer = trace.get_tracer(__name__) with tracer.start_as_current_span( f"call_{service}", attributes={ "peer.service": service, "http.method": method, } ) as span: response = await self.http_client.post( f"http://{service}/{method}", json=data, headers=headers ) span.set_attribute("http.status_code", response.status_code) return response.json() 日志关联查询 class LogCorrelator: """日志关联查询器""" async def get_session_timeline( self, session_id: str ) -> list: """获取会话的完整事件时间线""" # 从多个数据源查询 logs = await self.loki.query( f'{{session_id="{session_id}"}} | json' ) traces = await self.jaeger.get_traces( tags={"session_id": session_id} ) metrics = await self.prometheus.query_range( query=f'agent_session_metrics{{session_id="{session_id}"}}', start=..., end=... ) # 合并并按时间排序 events = [] for log in logs: events.append({ "type": "log", "timestamp": log["timestamp"], "level": log["level"], "message": log["message"], **log }) for trace in traces: for span in trace.spans: events.append({ "type": "trace", "timestamp": span.start_time, "span_name": span.name, "duration_ms": span.duration_ms, "service": span.service, **span.tags }) events.sort(key=lambda e: e["timestamp"]) return events 日志采样策略 class LogSampler: """日志采样器——在保证可观测性的前提下控制日志量""" SAMPLING_RULES = { # 正常请求：10%采样 "normal": {"rate": 0.1, "level": "INFO"}, # 错误请求：100%记录 "error": {"rate": 1.0, "level": "ERROR"}, # 慢请求（>5s）：100%记录 "slow": {"rate": 1.0, "level": "INFO", "min_latency_ms": 5000}, # 工具调用失败：100%记录 "tool_failure": {"rate": 1.0, "level": "WARN"}, # 安全相关：100%记录 "security": {"rate": 1.0, "level": "INFO"}, # 高价值用户：50%采样 "enterprise": {"rate": 0.5, "level": "INFO"}, } def should_log( self, log_type: str, request: dict, response: dict = None ) -> tuple: """判断是否需要记录日志""" # 优先级判断 if response and response.get("error"): rule = self.SAMPLING_RULES["error"] elif response and response.get("latency_ms", 0) > 5000: rule = self.SAMPLING_RULES["slow"] elif request.get("user_tier") == "enterprise": rule = self.SAMPLING_RULES["enterprise"] else: rule = self.SAMPLING_RULES["normal"] import random if random.random() < rule["rate"]: return True, rule["level"] return False, None 日志分析 class LogAnalyzer: """日志分析器""" async def analyze_session(self, session_id: str) -> dict: """分析单个会话日志""" events = await self.log_store.get_session_events(session_id) analysis = { "session_id": session_id, "total_steps": len(events), "tool_calls": [], "llm_calls": [], "errors": [], "total_tokens": 0, "total_latency_ms": 0, "quality_indicators": {}, } for event in events: if event["type"] == "tool_call": analysis["tool_calls"].append({ "tool": event["tool_name"], "latency_ms": event["latency_ms"], "success": event["success"] }) if not event["success"]: analysis["errors"].append(event) elif event["type"] == "llm_call": analysis["llm_calls"].append({ "model": event["model"], "tokens": event["total_tokens"], "latency_ms": event["latency_ms"] }) analysis["total_tokens"] += event["total_tokens"] analysis["total_latency_ms"] += event.get("latency_ms", 0) return analysis async def detect_anomalies( self, time_window_hours: int = 1 ) -> list: """检测日志异常模式""" anomalies = [] # 1. 突发错误聚集 error_clusters = await self._find_error_clusters(time_window_hours) for cluster in error_clusters: anomalies.append({ "type": "error_cluster", "service": cluster["service"], "error_count": cluster["count"], "time_range": cluster["range"] }) # 2. 异常Token消耗 token_outliers = await self._find_token_outliers(time_window_hours) for outlier in token_outliers: anomalies.append({ "type": "token_anomaly", "session_id": outlier["session_id"], "tokens": outlier["tokens"], "expected": outlier["expected"] }) # 3. 工具调用模式异常 tool_anomalies = await self._find_tool_anomalies(time_window_hours) anomalies.extend(tool_anomalies) return anomalies 日志保留策略 日志类型 热存储（SSD） 温存储（HDD） 冷存储（S3） 错误日志 7天 30天 180天 安全审计 30天 180天 2年 正常请求 3天 14天 90天 Trace数据 3天 7天 30天 指标数据 7天 90天 365天 总结 Agent系统的日志架构需要在"详细度"和"成本"之间取得平衡。结构化日志是一切的基础——没有结构化，就无法进行有效的查询和分析。Trace ID的跨服务传播让分布式追踪成为可能。智能采样策略确保在控制成本的同时不丢失关键信息。 ...

引言 Agent 的执行过程是黑盒——你看到输入和输出，但中间发生了什么？调用了什么工具？为什么选择这个路径？Token 花在哪里？结构化日志是打开这个黑盒的钥匙。2026年，随着 Agent 系统复杂度增长，日志不再是"给人看的文本"，而是"给系统查询的数据"。 一、Agent 日志设计原则 传统日志 vs Agent 日志 维度 传统日志 Agent 日志 格式 半结构化文本 全结构化 JSON 粒度 请求级 步骤级（每轮迭代） 关联 request_id trace_id + session_id + step_id 内容 状态和错误 决策推理、工具调用、Token消耗 用途 故障排查 故障排查 + 质量分析 + 成本归因 查询 grep/正则 结构化查询 + 聚合分析 设计原则 一切皆结构化：每条日志都是可查询的 JSON 因果链完整：从输入到输出的每一步都可追溯 上下文丰富：每条日志携带足够的上下文独立理解 成本感知：Token 和费用信息嵌入每条日志 隐私安全：PII 自动脱敏 二、日志数据模型 from dataclasses import dataclass, field from datetime import datetime from enum import Enum import uuid class LogLevel(Enum): DEBUG = "debug" INFO = "info" WARN = "warn" ERROR = "error" CRITICAL = "critical" class EventType(Enum): # Agent 生命周期 AGENT_START = "agent.start" AGENT_END = "agent.end" AGENT_INTERRUPT = "agent.interrupt" # LLM 交互 LLM_REQUEST = "llm.request" LLM_RESPONSE = "llm.response" LLM_ERROR = "llm.error" LLM_RETRY = "llm.retry" # 工具调用 TOOL_DECISION = "tool.decision" TOOL_CALL_START = "tool.call.start" TOOL_CALL_END = "tool.call.end" TOOL_ERROR = "tool.error" # 决策推理 REASONING = "reasoning" PLANNING = "planning" REFLECTION = "reflection" # 状态变更 STATE_UPDATE = "state.update" CONTEXT_PRUNED = "context.pruned" # 错误恢复 ERROR_RECOVERY = "error.recovery" FALLBACK_TRIGGERED = "fallback.triggered" @dataclass class AgentLogEntry: """Agent 结构化日志条目""" # 标识 log_id: str = field(default_factory=lambda: str(uuid.uuid4())) timestamp: str = field(default_factory=lambda: datetime.now().isoformat()) # 关联 trace_id: str = "" # 贯穿整个请求 session_id: str = "" # 会话ID step_id: str = "" # 当前步骤ID parent_step_id: str = "" # 父步骤（用于嵌套） # 事件 event_type: EventType = EventType.AGENT_START level: LogLevel = LogLevel.INFO # Agent 信息 agent_name: str = "" agent_version: str = "" # 内容 message: str = "" data: dict = field(default_factory=dict) # 性能 duration_ms: float = 0 # 成本 tokens_in: int = 0 tokens_out: int = 0 cost_usd: float = 0 # 上下文 user_id: str = "" tenant_id: str = "" environment: str = "production" 三、结构化日志实现 3.1 日志记录器 import structlog from structlog.contextvars import bind_contextvars, clear_contextvars class AgentLogger: """Agent 结构化日志记录器""" def __init__(self): self.logger = structlog.get_logger("agent") def bind_request_context( self, trace_id: str, session_id: str, user_id: str, agent_name: str, agent_version: str ): """绑定请求级上下文""" bind_contextvars( trace_id=trace_id, session_id=session_id, user_id=user_id, agent_name=agent_name, agent_version=agent_version, ) def log_agent_start( self, query: str, available_tools: list[str], max_iterations: int ): """记录 Agent 启动""" self.logger.info( "agent.start", event_type=EventType.AGENT_START.value, query_preview=query[:200], query_length=len(query), available_tools=available_tools, max_iterations=max_iterations, ) def log_llm_call( self, model: str, messages_count: int, input_tokens: int, temperature: float, tools_provided: bool ): """记录 LLM 调用""" self.logger.info( "llm.request", event_type=EventType.LLM_REQUEST.value, model=model, messages_count=messages_count, input_tokens=input_tokens, temperature=temperature, tools_provided=tools_provided, ) def log_llm_response( self, model: str, output_tokens: int, duration_ms: float, cost_usd: float, tool_calls: list[dict] | None, finish_reason: str ): """记录 LLM 响应""" self.logger.info( "llm.response", event_type=EventType.LLM_RESPONSE.value, model=model, output_tokens=output_tokens, duration_ms=round(duration_ms, 2), cost_usd=round(cost_usd, 6), tool_calls_count=len(tool_calls) if tool_calls else 0, tool_calls=[ {"tool": tc["function"]["name"], "args_preview": str(tc["function"]["arguments"])[:100]} for tc in (tool_calls or []) ], finish_reason=finish_reason, ) def log_tool_decision( self, selected_tool: str, available_tools: list[str], reasoning: str, confidence: float | None = None ): """记录工具选择决策""" self.logger.debug( "tool.decision", event_type=EventType.TOOL_DECISION.value, selected_tool=selected_tool, available_tools=available_tools, reasoning=reasoning, confidence=confidence, ) def log_tool_execution( self, tool_name: str, args: dict, result: any, duration_ms: float, success: bool, error: str | None = None ): """记录工具执行""" log_data = { "event_type": EventType.TOOL_CALL_END.value, "tool": tool_name, "args_preview": self._truncate_args(args), "duration_ms": round(duration_ms, 2), "success": success, } if success: log_data["result_preview"] = str(result)[:500] log_data["result_size"] = len(str(result)) else: log_data["error"] = error self.logger.info("tool.call.end", **log_data) def log_reasoning( self, step: int, thought: str, action: str, observation: str ): """记录 ReAct 推理过程""" self.logger.debug( "reasoning", event_type=EventType.REASONING.value, step=step, thought=thought[:500], action=action, observation=observation[:500], ) def log_agent_end( self, total_iterations: int, total_tokens_in: int, total_tokens_out: int, total_cost: float, total_duration_ms: float, tools_used: list[str], status: str ): """记录 Agent 结束""" self.logger.info( "agent.end", event_type=EventType.AGENT_END.value, total_iterations=total_iterations, total_tokens_in=total_tokens_in, total_tokens_out=total_tokens_out, total_cost_usd=round(total_cost, 6), total_duration_ms=round(total_duration_ms, 2), tools_used=tools_used, status=status, ) def _truncate_args(self, args: dict, max_len: int = 200) -> dict: """截断过长的参数""" result = {} for k, v in args.items(): s = str(v) result[k] = s[:max_len] + "..." if len(s) > max_len else v return result def clear_context(self): """清理上下文""" clear_contextvars() 3.2 日志中间件 class AgentLoggingMiddleware: """Agent 日志中间件——自动记录""" def __init__(self, logger: AgentLogger): self.logger = logger async def wrap_agent( self, agent: Agent, request: Request ) -> Response: """包装 Agent 执行，自动记录日志""" trace_id = request.headers.get("X-Trace-ID", str(uuid.uuid4())) # 绑定上下文 self.logger.bind_request_context( trace_id=trace_id, session_id=request.session_id, user_id=request.user_id, agent_name=agent.name, agent_version=agent.version ) start_time = time.time() try: # 记录启动 self.logger.log_agent_start( query=request.query, available_tools=agent.get_tool_names(), max_iterations=agent.max_iterations ) # 执行 Agent（内部会通过回调记录各步骤） response = await agent.run(request.query) # 记录结束 self.logger.log_agent_end( total_iterations=agent.iteration_count, total_tokens_in=agent.total_input_tokens, total_tokens_out=agent.total_output_tokens, total_cost=agent.total_cost, total_duration_ms=(time.time() - start_time) * 1000, tools_used=agent.tools_used, status="success" ) return response except Exception as e: self.logger.logger.error( "agent.error", event_type="agent.error", error_type=type(e).__name__, error_message=str(e), duration_ms=(time.time() - start_time) * 1000, ) raise finally: self.logger.clear_context() 四、日志输出配置 import structlog import logging import sys def configure_logging(environment: str = "production"): """配置结构化日志""" if environment == "production": # 生产环境：JSON 输出到 stdout structlog.configure( processors=[ structlog.contextvars.merge_contextvars, structlog.processors.add_log_level, structlog.processors.TimeStamper(fmt="iso"), _add_server_info(), _pii_redactor(), # PII 脱敏 structlog.processors.JSONRenderer(ensure_ascii=False), ], wrapper_class=structlog.make_filtering_bound_logger(logging.INFO), logger_factory=structlog.PrintLoggerFactory(), ) elif environment == "development": # 开发环境：彩色控制台输出 structlog.configure( processors=[ structlog.contextvars.merge_contextvars, structlog.processors.add_log_level, structlog.dev.ConsoleRenderer(colors=True), ], ) # 同时写入文件（轮转） file_handler = logging.handlers.RotatingFileHandler( "/var/log/agent/agent.log", maxBytes=100_000_000, # 100MB backupCount=10, ) file_handler.setFormatter( logging.Formatter('{"message": "%(message)s"}') ) def _add_server_info(): """添加服务器信息处理器""" def processor(logger, method_name, event_dict): event_dict["hostname"] = socket.gethostname() event_dict["pid"] = os.getpid() return event_dict return processor def _pii_redactor(): """PII 脱敏处理器""" patterns = { "email": (r'[\w.-]+@[\w.-]+\.\w+', '[REDACTED_EMAIL]'), "phone": (r'\b1[3-9]\d{9}\b', '[REDACTED_PHONE]'), "id_card": (r'\b\d{17}[\dXx]\b', '[REDACTED_ID]'), } def redact(text: str) -> str: for pattern, replacement in patterns.values(): text = re.sub(pattern, replacement, text) return text def processor(logger, method_name, event_dict): for key, value in event_dict.items(): if isinstance(value, str): event_dict[key] = redact(value) elif isinstance(value, dict): event_dict[key] = { k: redact(v) if isinstance(v, str) else v for k, v in value.items() } return event_dict return processor 五、日志查询与分析 5.1 日志查询接口 class AgentLogQuery: """Agent 日志查询接口""" async def get_trace(self, trace_id: str) -> list[dict]: """获取完整执行链路""" return await self.elasticsearch.search( index="agent-logs-*", body={ "query": {"term": {"trace_id": trace_id}}, "sort": [{"timestamp": "asc"}] } ) async def find_slow_agents( self, threshold_ms: float = 30000, time_range: str = "1h" ) -> list[dict]: """查找慢 Agent 执行""" return await self.elasticsearch.search( index="agent-logs-*", body={ "query": { "bool": { "filter": [ {"term": {"event_type": "agent.end"}}, {"range": { "total_duration_ms": {"gte": threshold_ms} }}, {"range": { "timestamp": {"gte": f"now-{time_range}"} }} ] } }, "sort": [{"total_duration_ms": "desc"}], "size": 50 } ) async def find_expensive_sessions( self, min_cost: float = 0.10, time_range: str = "24h" ) -> list[dict]: """查找高成本会话""" return await self.elasticsearch.search( index="agent-logs-*", body={ "query": { "bool": { "filter": [ {"term": {"event_type": "agent.end"}}, {"range": {"total_cost_usd": {"gte": min_cost}}}, {"range": {"timestamp": {"gte": f"now-{time_range}"}}} ] } }, "sort": [{"total_cost_usd": "desc"}] } ) async def get_tool_failure_rate( self, time_range: str = "1h" ) -> dict: """工具失败率统计""" result = await self.elasticsearch.search( index="agent-logs-*", body={ "size": 0, "query": { "bool": { "filter": [ {"term": {"event_type": "tool.call.end"}}, {"range": {"timestamp": {"gte": f"now-{time_range}"}}} ] } }, "aggs": { "by_tool": { "terms": {"field": "tool"}, "aggs": { "success_count": { "filter": {"term": {"success": True}} }, "failure_count": { "filter": {"term": {"success": False}} } } } } } ) return { bucket["key"]: { "total": bucket["doc_count"], "success": bucket["success_count"]["doc_count"], "failure": bucket["failure_count"]["doc_count"], "failure_rate": bucket["failure_count"]["doc_count"] / bucket["doc_count"] } for bucket in result["aggregations"]["by_tool"]["buckets"] } 5.2 执行链路回放 class TraceReplay: """Agent 执行链路回放""" async def replay(self, trace_id: str) -> str: """生成可读的执行链路报告""" events = await self.query.get_trace(trace_id) if not events: return f"No trace found for {trace_id}" report = [] report.append(f"=== Agent Trace Replay: {trace_id} ===\n") total_tokens = 0 total_cost = 0 total_duration = 0 for event in events: ts = event["timestamp"] event_type = event["event_type"] data = event.get("data", {}) if event_type == "agent.start": report.append(f"[{ts}] 🚀 Agent started") report.append(f" Query: {data.get('query_preview', '')[:100]}") report.append(f" Tools: {data.get('available_tools', [])}") elif event_type == "llm.request": report.append(f"[{ts}] 📤 LLM call → {data.get('model')}") report.append(f" Input tokens: {data.get('input_tokens', 0)}") total_tokens += data.get('input_tokens', 0) elif event_type == "llm.response": report.append(f"[{ts}] 📥 LLM response ← {data.get('model')}") report.append(f" Output tokens: {data.get('output_tokens', 0)}") report.append(f" Duration: {data.get('duration_ms', 0):.0f}ms") report.append(f" Cost: ${data.get('cost_usd', 0):.6f}") if data.get('tool_calls_count', 0) > 0: report.append(f" Tool calls: {data['tool_calls']}") total_tokens += data.get('output_tokens', 0) total_cost += data.get('cost_usd', 0) total_duration += data.get('duration_ms', 0) elif event_type == "tool.call.end": status = "✅" if data.get('success') else "❌" report.append(f"[{ts}] 🔧 {status} {data.get('tool')}") report.append(f" Duration: {data.get('duration_ms', 0):.0f}ms") if not data.get('success'): report.append(f" Error: {data.get('error', '')}") total_duration += data.get('duration_ms', 0) elif event_type == "agent.end": report.append(f"\n[{ts}] 🏁 Agent finished") report.append(f" Status: {data.get('status')}") report.append(f" Total iterations: {data.get('total_iterations')}") report.append(f"\n=== Summary ===") report.append(f"Total tokens: {total_tokens}") report.append(f"Total cost: ${total_cost:.6f}") report.append(f"Total duration: {total_duration:.0f}ms") return "\n".join(report) 输出示例： ...