Keyboard shortcuts

Press ← or → to navigate between chapters

Press S or / to search in the book

Press ? to show this help

Press Esc to hide this help

Mini-project 9: instrument your agent with tracing

Your agent currently traces with print.

By the end of this chapter it emits real OpenTelemetry spans — a root span per run, a child per model call, a child per tool call — carrying token counts, cost, latency, arguments, results, and error status, using the GenAI semantic convention attribute names. You will have a forty-line trace viewer that renders the tree in your terminal, an export path to a hosted backend, and — the part that actually pays for all of it — a worked debugging session where a bad run’s trace tells you the root cause in about five seconds.

Everything runs locally. No collector, no Docker, no account, no network.

Setup:

pip install opentelemetry-api opentelemetry-sdk opentelemetry-semantic-conventions

The code below was written and run against opentelemetry-sdk 1.44.0 and opentelemetry-semantic-conventions 0.65b0. Every output block is real terminal output.

Read the attribute names from the package

First, a habit that will save you a migration.

The GenAI conventions are still in Development status, and names have moved between releases. Do not type "gen_ai.usage.input_tokens" as a string literal in forty places. Import the constants:

from opentelemetry.semconv._incubating.attributes import gen_ai_attributes as gen_ai

gen_ai.GEN_AI_OPERATION_NAME       # "gen_ai.operation.name"
gen_ai.GEN_AI_USAGE_INPUT_TOKENS   # "gen_ai.usage.input_tokens"
gen_ai.GEN_AI_TOOL_CALL_ARGUMENTS  # "gen_ai.tool.call.arguments"

The _incubating module path is the package telling you the truth: these are not stable. When the conventions graduate, the import moves and your attribute names come along. When a name changes, you pin, you bump, you fix the imports, and you are done — instead of grepping strings.

Wiring the provider

from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.resources import Resource


def setup_tracing(processor) -> trace.Tracer:
    provider = TracerProvider(resource=Resource.create({
        "service.name": "solaris-support-agent",
        "service.version": "1.4.0",
        "deployment.environment.name": os.environ.get("ENV", "dev"),
    }))
    provider.add_span_processor(processor)
    trace.set_tracer_provider(provider)
    return trace.get_tracer("solaris.agent")

The Resource is metadata stamped on every span from this process. service.version in there is not decoration: it is what lets you say “quality dropped when 1.4.0 rolled out” six weeks from now, which was the whole point of logging versions in Chapter 4.

The processor is injected rather than hardcoded because it is the swap point. SimpleSpanProcessor exports each span as it ends — correct for development and for the in-terminal viewer. BatchSpanProcessor buffers and exports on a background thread — correct for production, where you do not want an export round trip on your request path.

The root span: one agent run

def run(self, mission: str) -> str:
    with self.tracer.start_as_current_span(
        "invoke_agent solaris-support", kind=SpanKind.CLIENT,
        attributes={
            gen_ai.GEN_AI_OPERATION_NAME: "invoke_agent",
            gen_ai.GEN_AI_AGENT_NAME: "solaris-support",
            gen_ai.GEN_AI_PROVIDER_NAME: "anthropic",
            gen_ai.GEN_AI_CONVERSATION_ID: self.conversation_id,
        },
    ) as root:
        messages = [{"role": "user", "content": mission}]
        totals = {"in": 0, "out": 0, "tools": 0, "tool_errors": 0}

        for step in range(1, self.max_steps + 1):
            reply = self._chat(messages, step, totals)

            if reply.stop_reason != "tool_use":
                final = " ".join(b.text.strip() for b in reply.content
                                 if b.type == "text" and b.text)
                self._finish(root, totals, "answer", step, final)
                return final

            messages.append({"role": "assistant",
                             "content": [_block_to_api(b) for b in reply.content]})
            results = []
            for b in reply.content:
                if b.type != "tool_use":
                    continue
                obs = self._execute_tool(b, totals)
                results.append({"type": "tool_result", "tool_use_id": b.id, "content": obs})
            messages.append({"role": "user", "content": results})

        final = "I ran out of steps before finishing; a human should take over."
        root.set_status(Status(StatusCode.ERROR, "step cap exhausted"))
        root.set_attribute("error.type", "step_cap_exhausted")
        self._finish(root, totals, "step_cap", self.max_steps, final)
        return final

This is Part 1’s loop with a with block around it and nothing else changed. That is the point of having built the loop yourself: instrumenting it is an afternoon, not a rewrite.

The exhaustion path is worth noting. Hitting the step cap sets ERROR status and an error.type even though nothing threw and the caller gets a perfectly polite string back. Step-cap exhaustion is a failure, and if you do not mark it as one it will never appear in your error rate — which is exactly how you end up with a green dashboard and unhappy users.

gen_ai.conversation.id is the join key for multi-turn sessions. Add your own user.id or tenant.id alongside it if you have them; those are the attributes you will want when a single customer reports a problem.

The model call span

def _chat(self, messages, step, totals):
    with self.tracer.start_as_current_span(
        f"chat {self.model}", kind=SpanKind.CLIENT,
        attributes={
            gen_ai.GEN_AI_OPERATION_NAME: "chat",
            gen_ai.GEN_AI_PROVIDER_NAME: "anthropic",
            gen_ai.GEN_AI_REQUEST_MODEL: self.model,
            gen_ai.GEN_AI_REQUEST_MAX_TOKENS: 1024,
            "agent.step": step,
        },
    ) as span:
        t0 = time.perf_counter()
        try:
            reply = self.client.complete(system=self.system, messages=messages,
                                         tools=self.registry.specs())
        except Exception as exc:                       # model call failed outright
            span.set_status(Status(StatusCode.ERROR, str(exc)))
            span.set_attribute("error.type", type(exc).__name__)
            raise
        span.set_attribute(gen_ai.GEN_AI_RESPONSE_MODEL, self.model)
        span.set_attribute(gen_ai.GEN_AI_RESPONSE_FINISH_REASONS, [reply.stop_reason])
        span.set_attribute(gen_ai.GEN_AI_USAGE_INPUT_TOKENS, reply.input_tokens)
        span.set_attribute(gen_ai.GEN_AI_USAGE_OUTPUT_TOKENS, reply.output_tokens)
        span.set_attribute("gen_ai.usage.cost_usd",
                           cost_usd(self.model, reply.input_tokens, reply.output_tokens))
        span.set_attribute("llm.latency_ms", round((time.perf_counter() - t0) * 1000, 2))
        if os.environ.get("TRACE_CONTENT") == "1":
            span.set_attribute(gen_ai.GEN_AI_INPUT_MESSAGES, _truncate(json.dumps(messages)))
            span.set_attribute(gen_ai.GEN_AI_OUTPUT_MESSAGES,
                               _truncate(json.dumps([_block_to_api(b) for b in reply.content])))
        totals["in"] += reply.input_tokens
        totals["out"] += reply.output_tokens
        return reply

Span name is chat {model}, which is what the conventions specify for inference spans.

Attributes split into two groups on purpose: request attributes go on at span creation so they exist even if the call throws, and response attributes go on afterwards. A span for a failed call with no model name on it is a span you cannot group by.

gen_ai.usage.cost_usd is not a standard attribute — the conventions do not define one. Compute it yourself from a price table kept in one place:

PRICES = {"claude-sonnet-4-5": (3.00, 15.00), "mock-model": (3.00, 15.00)}

def cost_usd(model: str, input_tokens: int, output_tokens: int) -> float:
    pin, pout = PRICES.get(model, (0.0, 0.0))
    return (input_tokens * pin + output_tokens * pout) / 1_000_000

Yes, prices change and your historical spans will hold stale numbers. That is still far better than the alternative, which is joining token counts to a pricing table in a spreadsheet whenever anyone asks what a feature costs. Attach the number, keep the token counts too, and you can always recompute.

Content capture is behind TRACE_CONTENT=1 and off by default. The upstream instrumentation libraries do the same thing through OTEL_INSTRUMENTATION_GENAI_CAPTURE_MESSAGE_CONTENT, which takes modes including NO_CONTENT, SPAN_ONLY, EVENT_ONLY, and SPAN_AND_EVENT (https://opentelemetry-python-contrib.readthedocs.io/en/latest/instrumentation-genai/util.html). Full prompts are the most useful and most dangerous thing in your telemetry. Make turning them on a deliberate act.

The tool call span

def _execute_tool(self, block, totals) -> str:
    with self.tracer.start_as_current_span(
        f"execute_tool {block.name}", kind=SpanKind.INTERNAL,
        attributes={
            gen_ai.GEN_AI_OPERATION_NAME: "execute_tool",
            gen_ai.GEN_AI_TOOL_NAME: block.name,
            gen_ai.GEN_AI_TOOL_CALL_ID: block.id,
            gen_ai.GEN_AI_TOOL_CALL_ARGUMENTS: _safe_args(block.input),
        },
    ) as span:
        obs = self.registry.call(block.name, block.input)
        totals["tools"] += 1
        span.set_attribute(gen_ai.GEN_AI_TOOL_CALL_RESULT, _truncate(obs))
        if obs.startswith("ERROR"):
            totals["tool_errors"] += 1
            span.set_status(Status(StatusCode.ERROR, obs[:120]))
            span.set_attribute("error.type", obs.split(":")[0].replace("ERROR", "tool_error"))
        return obs

Three things here are the difference between a trace you can debug from and a trace you cannot.

Arguments go on the span, redacted and truncated.

MAX_ATTR_CHARS = 2000
REDACT_KEYS = {"to", "email", "body", "phone"}

def _safe_args(args: dict) -> str:
    return json.dumps({k: ("[redacted]" if k in REDACT_KEYS else v) for k, v in args.items()})

def _truncate(value: str) -> str:
    return value if len(value) <= MAX_ATTR_CHARS else value[:MAX_ATTR_CHARS] + "...[truncated]"

Without arguments, the trace tells you get_shipping_status was called and nothing about the fact that it was called with an order ID. The redaction list means send_email’s body never enters your telemetry.

The result goes on the span too. This is the one people skip, and it is what makes soft failures visible.

Part 1’s error-as-observation rule interacts with tracing in a way you must handle deliberately. The registry never raises; every failure comes back as a string starting with ERROR. That is right for the agent and wrong for the tracer, because a span that never sees an exception is OK by default. So the code inspects the observation and sets ERROR status explicitly. Otherwise your error rate is permanently zero and you will believe it.

A trace viewer in forty lines

You do not need a backend to look at a trace. Collect the spans in-process and print the tree.

class CollectingExporter(SpanExporter):
    def __init__(self) -> None:
        self.spans: list = []

    def export(self, spans) -> SpanExportResult:
        self.spans.extend(spans)
        return SpanExportResult.SUCCESS

    def shutdown(self) -> None:
        pass


def print_trace(exporter, show=KEY_ATTRS) -> None:
    spans = sorted(exporter.spans, key=lambda s: s.start_time)
    children, roots = {}, []
    for s in spans:
        if s.parent is None:
            roots.append(s)
        else:
            children.setdefault(s.parent.span_id, []).append(s)

    def walk(span, depth=0):
        dur = (span.end_time - span.start_time) / 1e6
        status = span.status.status_code.name
        mark = "x" if status == "ERROR" else "."
        pad = "  " * depth
        print(f"{pad}{mark} {span.name:<{40 - 2 * depth}} {dur:7.1f}ms  {status}")
        for k, v in (span.attributes or {}).items():
            if k in show:
                print(f"{pad}    {k} = {str(v)[:70]}")
        for c in sorted(children.get(span.context.span_id, []), key=lambda s: s.start_time):
            walk(c, depth + 1)

    print(f"trace_id = {roots[0].context.trace_id:032x}" if roots else "(no spans)")
    for r in roots:
        walk(r)

Forty lines, no dependencies beyond the SDK you already have, and it works in CI, in a test, and over SSH. Write this before you sign up for anything.

A good run

$ python3 demo_trace.py


===== GOOD RUN =====
trace_id = fa0584c491f392c6a2c983e86c8eae6e
. invoke_agent solaris-support                 0.5ms  UNSET
    agent.stop_reason = answer
    gen_ai.usage.input_tokens = 475
    gen_ai.usage.output_tokens = 120
    gen_ai.usage.cost_usd = 0.003225
  . chat mock-model                            0.1ms  UNSET
      gen_ai.response.finish_reasons = ('tool_use',)
      gen_ai.usage.input_tokens = 74
      gen_ai.usage.output_tokens = 40
      gen_ai.usage.cost_usd = 0.000822
  . execute_tool find_order                    0.1ms  UNSET
      gen_ai.tool.call.arguments = {"order_id": "12345"}
      gen_ai.tool.call.result = {"customer": "R. Okafor", "item": "Solaris headphones", "tracking": "Z
  . chat mock-model                            0.1ms  UNSET
      gen_ai.response.finish_reasons = ('tool_use',)
      gen_ai.usage.input_tokens = 161
      gen_ai.usage.output_tokens = 40
      gen_ai.usage.cost_usd = 0.001083
  . execute_tool get_shipping_status           0.0ms  UNSET
      gen_ai.tool.call.arguments = {"tracking_number": "ZYX987"}
      gen_ai.tool.call.result = Out for delivery, arriving today by 8pm
  . chat mock-model                            0.1ms  UNSET
      gen_ai.response.finish_reasons = ('end_turn',)
      gen_ai.usage.input_tokens = 240
      gen_ai.usage.output_tokens = 40
      gen_ai.usage.cost_usd = 0.00132
summary: {"llm_calls": 3, "tool_calls": 2, "error_spans": [], "repeated_tool_calls": [],
          "input_tokens": 475, "output_tokens": 120, "cost_usd": 0.003225, "wall_ms": 0.5}
answer: Order 12345 is out for delivery, arriving today by 8pm.

The latencies are sub-millisecond because the model is a mock and the tools are dictionaries. Against a real model those chat spans dominate and the shape of the trace becomes a latency budget you can act on.

One thing to notice even in the happy path: input tokens climb 74 → 161 → 240 across three calls, on a two-tool run. That is the quadratic context growth from Part 4’s control-flow chapter, visible in telemetry for the first time. On a fifteen-step trajectory this curve is where your money goes, and this is how you find it.

UNSET rather than OK is normal — OpenTelemetry treats unset as “no problem reported,” and you should only ever set ERROR explicitly.

A bad run, and finding the bug

Now the part that justifies the whole chapter.

A customer reports: “I asked where my order was and it just gave up.” Here is the trace.


===== BAD RUN =====
trace_id = 66a470d374bfc5f70afd35157719f234
x invoke_agent solaris-support                 0.6ms  ERROR
    error.type = step_cap_exhausted
    agent.stop_reason = step_cap
    gen_ai.usage.input_tokens = 767
    gen_ai.usage.output_tokens = 160
    gen_ai.usage.cost_usd = 0.004701
  . chat mock-model                            0.0ms  UNSET
      gen_ai.response.finish_reasons = ('tool_use',)
      gen_ai.usage.input_tokens = 74
      gen_ai.usage.output_tokens = 40
      gen_ai.usage.cost_usd = 0.000822
  . execute_tool get_shipping_status           0.0ms  UNSET
      gen_ai.tool.call.arguments = {"tracking_number": "12345"}
      gen_ai.tool.call.result = No shipment found for 12345.
  . chat mock-model                            0.0ms  UNSET
      gen_ai.response.finish_reasons = ('tool_use',)
      gen_ai.usage.input_tokens = 150
      gen_ai.usage.output_tokens = 40
      gen_ai.usage.cost_usd = 0.00105
  . execute_tool get_shipping_status           0.0ms  UNSET
      gen_ai.tool.call.arguments = {"tracking_number": "12345"}
      gen_ai.tool.call.result = No shipment found for 12345.
  . chat mock-model                            0.0ms  UNSET
      gen_ai.response.finish_reasons = ('tool_use',)
      gen_ai.usage.input_tokens = 226
      gen_ai.usage.output_tokens = 40
      gen_ai.usage.cost_usd = 0.001278
  x execute_tool lookup_parcel                 0.0ms  ERROR
      gen_ai.tool.call.arguments = {"id": "12345"}
      gen_ai.tool.call.result = ERROR: no tool named 'lookup_parcel'. Available tools: find_order, get
      error.type = tool_error
  . chat mock-model                            0.0ms  UNSET
      gen_ai.response.finish_reasons = ('tool_use',)
      gen_ai.usage.input_tokens = 317
      gen_ai.usage.output_tokens = 40
      gen_ai.usage.cost_usd = 0.001551
  . execute_tool get_shipping_status           0.0ms  UNSET
      gen_ai.tool.call.arguments = {"tracking_number": "12345"}
      gen_ai.tool.call.result = No shipment found for 12345.
summary: {"llm_calls": 4, "tool_calls": 4, "error_spans": ["execute_tool lookup_parcel",
          "invoke_agent solaris-support"], "repeated_tool_calls": ["get_shipping_status",
          "get_shipping_status"], "input_tokens": 767, "output_tokens": 160,
          "cost_usd": 0.004701, "wall_ms": 0.6}
answer: I ran out of steps before finishing; a human should take over.

Read it in this order.

Start at the root. ERROR, error.type = step_cap_exhausted. So this is not a crash and not a timeout: the agent used its whole budget and never converged. That already eliminates half the possible explanations.

Scan the children for the first thing that is not what you expected. Span two is execute_tool get_shipping_status. That is wrong before you read any further — the first tool call on an order query should be find_order. There is no find_order span anywhere in this trace.

Read that span’s arguments. {"tracking_number": "12345"}. 12345 is the order ID. It has been passed into the tracking-number parameter.

Read the result. No shipment found for 12345. Status UNSET.

That line is the whole lesson. The failure that started this run never registered as an error anywhere. The tool worked perfectly, returned a valid response meaning “nothing here,” and if you had only instrumented exceptions this span would be invisible. Chapter 4 called these soft failures; this is what one looks like, and it is why gen_ai.tool.call.result belongs on the span.

Now the rest is consequence. Same call, same arguments, again — repeated_tool_calls flags it. The model is retrying rather than re-planning. Then a hallucinated lookup_parcel, which the registry converts into a readable error — Part 1’s recovery mechanism working exactly as designed — but the model still does not go back and look up the order. Then the same failed call a third time, and the cap fires.

Root cause: step one used the order ID as a tracking number, and the agent never recovered because “no shipment found” reads like a fact rather than a mistake.

Three fixes, in ascending order of how much they cost you.

Sharpen the tool description: “tracking_number is a carrier tracking code from an order record, not an order ID. Call find_order first to obtain it.” Sharpen the not-found message so the observation carries the correction: No shipment found for '12345'. If this looks like an order ID, call find_order first to get the tracking number. — an error message written for a model to act on, which was Part 1’s rule. And add a repetition guard in the orchestration layer: the same tool with identical arguments twice is a stuck agent, and the loop should break the pattern rather than let the model burn the budget.

Notice how little of that required reading a prompt. The structure of the trace — a missing span, a suspicious argument, a repeated call — carried the diagnosis. That is what you are buying.

Then turn the run into a regression test. Add a case to cases.jsonl with tools_required: ["find_order", "get_shipping_status"], and Chapter 3’s harness will fail forever after if this comes back. That is the failure-to-case loop from Chapter 4, and it is two files and one afternoon.

Deriving metrics from spans

Metrics are aggregations over the attributes you already have. Here is the whole thing:

def summarize(exporter) -> dict:
    tool_spans = [s for s in exporter.spans
                  if s.attributes.get("gen_ai.operation.name") == "execute_tool"]
    chat_spans = [s for s in exporter.spans
                  if s.attributes.get("gen_ai.operation.name") == "chat"]
    errors = [s for s in exporter.spans if s.status.status_code.name == "ERROR"]

    seen, repeats = set(), []
    for s in tool_spans:
        key = (s.attributes.get("gen_ai.tool.name"),
               s.attributes.get("gen_ai.tool.call.arguments"))
        if key in seen:
            repeats.append(key[0])
        seen.add(key)

    return {"llm_calls": len(chat_spans), "tool_calls": len(tool_spans),
            "error_spans": [s.name for s in errors], "repeated_tool_calls": repeats, ...}

In production you do not write this — your backend does it with a query. But writing it once locally teaches the thing that matters: every metric in Chapter 4’s list is a group-by over span attributes. If you cannot compute a metric from your spans, the fix is an attribute, not a dashboard.

Exporting somewhere real

The console viewer is for development. Two lines get you to a backend, and because you instrumented against the OpenTelemetry API rather than a vendor SDK, the choice is a config change.

Any OTLP backend — a Collector, Jaeger, Tempo, Grafana Cloud:

from opentelemetry.exporter.otlp.proto.http.trace_exporter import OTLPSpanExporter
from opentelemetry.sdk.trace.export import BatchSpanProcessor

processor = BatchSpanProcessor(OTLPSpanExporter())  # reads OTEL_EXPORTER_OTLP_ENDPOINT
tracer = setup_tracing(processor)

Langfuse, which is an OTLP endpoint with Basic auth and maps the GenAI conventions onto its UI:

export OTEL_EXPORTER_OTLP_ENDPOINT="https://cloud.langfuse.com/api/public/otel"
export OTEL_EXPORTER_OTLP_HEADERS="Authorization=Basic ${BASE64_PUBLIC_SECRET}"

Opik, which the course uses, also speaks OTLP over HTTP:

export OTEL_EXPORTER_OTLP_ENDPOINT="https://www.comet.com/opik/api/v1/private/otel"
export OTEL_EXPORTER_OTLP_HEADERS="Authorization=<api-key>,projectName=<project>,Comet-Workspace=<workspace>"

Note that Opik’s OTel ingestion is HTTP transport; use the HTTP exporter rather than gRPC (https://www.comet.com/docs/opik/tracing/opentelemetry/overview).

Nothing in TracedAgent changes for any of these. That is the payoff for using the standard.

The hosted option: Opik natively

Opik also has its own SDK, which is less portable and considerably less code, and it connects tracing to the evaluation side of Chapters 2 and 3 in one product. It is Apache-2.0 and self-hostable, which is why this course uses it.

pip install opik
opik configure                      # or: opik.configure(use_local=True)

Self-hosting is a clone and a script, serving a UI on localhost:5173 (https://github.com/comet-ml/opik):

git clone https://github.com/comet-ml/opik.git && cd opik && ./opik.sh

Instrumenting is a decorator:

import opik
from opik import track

@track
def execute_tool(name: str, args: dict) -> str:
    return registry.call(name, args)

@track(name="solaris-support-run")
def run_agent(mission: str) -> str:
    return agent.run(mission)

Nested @track functions become nested spans automatically, which means decorating your loop, your model call, and your tool dispatcher gets you the same tree you built by hand.

The reason to consider it over raw OTel is the second half of the product: the same platform holds datasets and judge metrics, so a production trace can be promoted into an eval case in the UI, and judges can be run over live traffic as online evaluation rules.

from opik.evaluation.metrics import Hallucination

metric = Hallucination()
score = metric.score(
    input="What is the capital of France?",
    output="Paris",
    context=["France is a country in Europe."],
)

That closes the loop Chapter 4 described — traces feeding cases, judges annotating traces — without you building the plumbing.

The recommendation, unchanged: instrument with the OpenTelemetry API and the GenAI conventions, then choose a backend. Use a vendor SDK where it buys you a workflow you would otherwise build, and keep the portable instrumentation underneath so that decision stays reversible.

Production checklist

Before this goes anywhere real:

  • BatchSpanProcessor, not SimpleSpanProcessor, so exporting is off the request path.
  • Sampling policy: 100% of errors, step-cap exhaustions, and negative feedback; 1–10% of successes.
  • Content capture off unless deliberately enabled, with redaction in front of it.
  • Truncation on every attribute that can hold a tool result or a message.
  • Trace ID surfaced to the caller — in a response header or the UI — so a user report arrives with the trace attached.
  • Alerts on step-cap rate, tool error rate per tool, p99 latency, and cost per successful run.
  • A quality dashboard fed by judge scores over sampled traces, separate from the operational one.

What you should be able to do now

  • Instrument an agent loop with nested OpenTelemetry spans — root run, model calls, tool calls — using GenAI semantic convention attribute names read from package constants rather than string literals.
  • Attach token, cost, latency, argument, result, and error attributes to the right spans, and set ERROR status on soft failures that never raise, including step-cap exhaustion.
  • Apply redaction and truncation at the instrumentation boundary, and keep full content capture behind an explicit switch.
  • Build a local trace viewer and read a trace top-down to a root cause: root status, first unexpected span, arguments, result, then consequences.
  • Derive system metrics — call counts, error spans, repeated calls, tokens, cost — as group-bys over span attributes, and recognise that a missing metric means a missing attribute.
  • Export to any OTLP backend or a hosted platform by changing configuration only, and explain why instrumenting against the standard keeps that decision reversible.
  • Turn a diagnosed production failure into a case in the Chapter 3 harness so it can never silently return.

Further reading