《AI Agent 工程实战》13.1 结构化日志与追踪：OTel GenAI 语义约定埋点

/tmp/agentbook/venv/bin/python -c "import importlib.util as u; print(bool(u.find_spec('opentelemetry')))"
/tmp/agentbook/venv/bin/pip list | grep -i opentelemetry

True
opentelemetry-api         1.45.1

from opentelemetry import trace
t = trace.get_tracer("probe")
with t.start_as_current_span("probe") as s:
    s.set_attribute("gen_ai.system", "anthropic")
    print("span:", type(s).__module__ + "." + type(s).__name__)
    print("recording:", s.is_recording())

span: opentelemetry.trace.span.NonRecordingSpan
recording: False

agent.run
├── model.complete        (第 1 轮，返回 tool_use)
│   ├── tool.call          gen_ai.tool.name=search_corpus
│   └── tool.call          gen_ai.tool.name=query_pg      ← 两个工具并列
└── model.complete        (第 2 轮，返回 end_turn)

from contextvars import ContextVar
from dataclasses import dataclass, field

CURRENT_SPAN: ContextVar["Span | None"] = ContextVar("current_span", default=None)

@dataclass
class Span:
    name: str
    span_id: str
    parent_id: str | None
    start: float
    end: float | None = None
    attributes: dict = field(default_factory=dict)
    children: list["Span"] = field(default_factory=list)

    @property
    def duration_ms(self) -> float:
        return 0.0 if self.end is None else (self.end - self.start) * 1000.0

    def start_span(self, name, **attrs):
        parent = CURRENT_SPAN.get()
        s = Span(name, uuid.uuid4().hex[:8],
                 parent.span_id if parent else None,
                 time.perf_counter(), attributes=dict(attrs))
        (parent.children if parent else self._roots).append(s)
        self._tokens[s.span_id] = CURRENT_SPAN.set(s)   # 记住 token，退出时还原
        return s

    def end_span(self, s):
        s.end = time.perf_counter()
        CURRENT_SPAN.reset(self._tokens.pop(s.span_id))  # 必须还原，否则兄弟会串挂

async def one(tc):
    with tracer.span("tool.call", **{"gen_ai.tool.name": tc.name,
                                     "gen_ai.tool.call.id": tc.id}) as ts:
        out = await registry.call(tc)
        ts.attributes["ok"] = "error" not in out
    return out

outs = await asyncio.gather(*[one(tc) for tc in resp.message.tool_calls])

class JsonFormatter(logging.Formatter):
    def format(self, rec):
        base = {"ts": self.formatTime(rec, "%H:%M:%S"), "level": rec.levelname,
                "event": rec.getMessage(), "trace_id": TRACE_ID.get()}
        base.update(getattr(rec, "fields", {}))
        return json.dumps(base, ensure_ascii=False)

{"ts": "03:07:06", "level": "INFO", "event": "run.start", "trace_id": "1b1779ff3bbd482f", "run_id": "run_9f3c1a", "workspace_id": "ws_acme", "input": "向量检索召回率怎么样？"}
{"ts": "03:07:06", "level": "INFO", "event": "model.call", "trace_id": "1b1779ff3bbd482f", "run_id": "run_9f3c1a", "step": 0, "span_id": "0dadc520", "duration_ms": 0.01, "gen_ai.request.model": "claude-sonnet-4-5", "gen_ai.usage.input_tokens": 820, "gen_ai.usage.output_tokens": 64}
{"ts": "03:07:06", "level": "INFO", "event": "tool.call", "trace_id": "1b1779ff3bbd482f", "run_id": "run_9f3c1a", "span_id": "d412b144", "gen_ai.tool.name": "search_corpus", "gen_ai.tool.call.id": "c1", "duration_ms": 14.1, "ok": true}
{"ts": "03:07:06", "level": "INFO", "event": "tool.call", "trace_id": "1b1779ff3bbd482f", "run_id": "run_9f3c1a", "span_id": "b15f1f56", "gen_ai.tool.name": "query_pg", "gen_ai.tool.call.id": "c2", "duration_ms": 31.56, "ok": true}
{"ts": "03:07:06", "level": "INFO", "event": "model.call", "trace_id": "1b1779ff3bbd482f", "run_id": "run_9f3c1a", "step": 1, "span_id": "b3820502", "duration_ms": 0.01, "gen_ai.request.model": "claude-sonnet-4-5", "gen_ai.usage.input_tokens": 1210, "gen_ai.usage.output_tokens": 210}
{"ts": "03:07:06", "level": "INFO", "event": "run.end", "trace_id": "1b1779ff3bbd482f", "run_id": "run_9f3c1a", "workspace_id": "ws_acme", "duration_ms": 31.97, "ok": true}

=== span 树 ===
agent.run [31.97 ms] {'run_id': 'run_9f3c1a', 'workspace_id': 'ws_acme', 'gen_ai.operation.name': 'invoke_agent', 'gen_ai.usage.total_tokens': 2030}
  model.complete [0.01 ms] {'step': 0, 'gen_ai.system': 'anthropic', 'gen_ai.request.model': 'claude-sonnet-4-5', 'gen_ai.usage.input_tokens': 820, 'gen_ai.usage.output_tokens': 64, 'gen_ai.response.finish_reasons': ['tool_use']}
  tool.call [14.10 ms] {'gen_ai.tool.name': 'search_corpus', 'gen_ai.tool.call.id': 'c1', 'ok': True}
  tool.call [31.56 ms] {'gen_ai.tool.name': 'query_pg', 'gen_ai.tool.call.id': 'c2', 'ok': True}
  model.complete [0.01 ms] {'step': 1, 'gen_ai.system': 'anthropic', 'gen_ai.request.model': 'claude-sonnet-4-5', 'gen_ai.usage.input_tokens': 1210, 'gen_ai.usage.output_tokens': 210, 'gen_ai.response.finish_reasons': ['end_turn']}