Structured Logging and Tracing

Mateo in Bogotá gets a message from a customer: "your assistant told me nonsense at about 14:05." He opens the logs and finds one line, ERROR request failed. Which stage failed? Was the answer slow, empty, cut off or refused? Which documents did it see? Did it call the model at all? The line cannot say, and the full prompt, which might say, holds the customer's card number, so it must not be in the log. (An illustrative case.)

This page gives the assistant a memory of what happened that is useful and safe: structured log events, a request trace made of spans, latency, tokens and cost per stage, and a rule for what is never recorded. We build our own small span model first, so the ideas are visible, and then map it to OpenTelemetry. Everything runs offline on a fake clock and a fake model, so the numbers are repeatable; real models and networks are less predictable, which is why the instrumentation exists.

What you will learn

• How to map one request across retrieval, tool, context, cache, model and validation, and give it ids that link logs, traces and evaluation cases.
• How to write structured log events with a fixed schema and redaction at the logging boundary, and which fields are never safe.
• How to record parent and child spans with latency, tokens and estimated cost, save them as a JSON fixture, and read them as a tree.
• How to debug a failed request from its trace, and how to detect slow or failing dependencies without trusting a tiny sample.
• How to decide what to capture, sample and keep, and how our spans map to OpenTelemetry, including context propagation.

What is new, and what is reused

No existing file changes. A new subpackage evidencedesk/observe/ has ten files: events, spans, privacy, pipeline, lab, viewer, debug, health, otel and a __main__. Data is in data/observe/ (seven scenarios, the dependency limits and a golden trace) and tests in test_observe_*.py. The redaction is not rewritten: events.py calls redact_log and SecretGuard from Prompt Injection and Access Boundaries. Cost uses the ledger and the hypothetical price table of Cost and Latency Fundamentals; the cache and its hit and bypass states come from Budgets, Caching, and Usage Limits; the status table and the fail-closed rule come from Safe Failure and Security Regression Tests. The decision lines of the agent trace in Agent Loops, State, and Memory stay as they are: that trace records choices, these spans record time.

Define an end-to-end request trace

A trace is the story of one request. A span is one step of it, with a start, an end, a parent and attributes. Our pipeline has six steps, and each answers a different question when something goes wrong:

All of them sit under one root span, request. Four ids tie everything together: a request id chosen at the edge (the x-request-id of the API), a trace id made by the tracer, a run id if an agent is involved, and a case id when the request comes from an evaluation set. A user id is never one of them; see below.

Create structured application logs

A log line is for a machine first. Free text such as "failed to answer for kwame" cannot be counted, filtered or joined. EventLog writes one JSON object per event with the same keys in the same order every time: ts, level, event, the three ids, a pseudonymous user, duration_ms, outcome and a fields object for the rest. Event names are lower-case and dotted (request.start, span.end), so a typo cannot create a new, unsearchable event. Times come from an injected clock.

Define safe logging fields

Decide per field, once, in code. Everything is one of four kinds:

The guard sits inside emit, not at the call sites, because the one forgotten call site is the one that leaks:

# excerpt of kit/evidencedesk/observe/events.py (EventLog.emit)
        clean: dict[str, Any] = {}
        for name, value in sorted(fields.items()):
            if name in NEVER_LOGGED:
                clean[f"{name}_chars"] = len(str(value))  # the size is useful, the content is not
            elif isinstance(value, str):
                clean[name] = redact_log(value, self.guard)
            elif isinstance(value, (int, float, bool)) or value is None:
                clean[name] = value
            else:
                clean[name] = redact_log(json.dumps(value, sort_keys=True, default=str), self.guard)

A field called question, prompt, answer and so on is replaced by its length. Other text goes through redact_log; a value that is not text is serialised and redacted too, because a secret can sit inside a dict. Two events, one with a card number in the question and one with a key and a bearer token in an error detail:

import json

from evidencedesk.observe.events import EventLog
from evidencedesk.security import SIMULATED_SECRET, SecretGuard
from evidencedesk.usage import ManualClock

log = EventLog(ManualClock(1000.0), SecretGuard({"api_key": SIMULATED_SECRET}))
log.emit("request.start", request_id="req-001", user_id="kwame", model="fake-model",
         question="My card 4111 1111 1111 1111 was charged twice")
log.emit("error.seen", level="warning", request_id="req-001", code="server",
         detail=f"provider said: bad key {SIMULATED_SECRET}; Bearer abcdefgh12345")
for record in log.records():
    print(json.dumps({k: v for k, v in record.items() if v not in ("", None)}))

{"ts": 1000.0, "level": "info", "event": "request.start", "request_id": "req-001", "user": "u-8a4a64f5", "fields": {"model": "fake-model", "question_chars": 45}}
{"ts": 1000.0, "level": "warning", "event": "error.seen", "request_id": "req-001", "fields": {"code": "server", "detail": "provider said: bad key [secret:[secret] Bearer [secret]"}}

The card number never reached the line, only question_chars. The user is u-8a4a64f5, the same every time for Kwame, and not reversible without the salt (the salt here is a demo value; a real one is a secret). Look at the key: the old redactor masked it, but its placeholder [secret:api_key] was then rewritten by its own name=value rule. Nothing leaked, the result is just ugly. Test redaction on your own formats and read the output; a redactor is a pattern list and cannot be complete, so the first defence is not to log the field. Also record an exception's class or a stable code, never its message: messages carry paths, SQL and keys.

Build a local trace representation

A Span has a trace id, a span id, a parent id, a name, start and end times, a status, an error code and a flat dictionary of attributes. Tracer.span(...) is a context manager. The current span lives in a ContextVar, so a span opened inside another becomes its child, and this keeps working across threads and async code; this is context propagation inside one process.

# excerpt of kit/evidencedesk/observe/spans.py (Tracer.span)
    def span(self, name: str, remote: dict[str, str] | None = None, **attrs: Any) -> Iterator[Span]:
        parent, joined = self.current(), parse_traceparent((remote or {}).get("traceparent", ""))
        trace_id, parent_id = (parent.trace_id, parent.span_id) if parent else joined or (self.ids.trace_id(), None)
        span = Span(trace_id, self.ids.span_id(), parent_id, name, round(self.clock(), 6), attrs=dict(attrs), _tracer=self)
        self.spans.append(span)
        if "request_id" in span.attrs:
            self.request_ids[trace_id] = str(span.attrs["request_id"])
        token = self._current.set(span)
        try:
            yield span
        except BaseException as exc:
            span.status, span.error_type = "error", str(getattr(exc, "kind", type(exc).__name__))  # a stable code, never the message
            raise
        finally:
            span.end = round(self.clock(), 6)
            self._current.reset(token)
            if self.log:
                self.log.emit("span.end", level="error" if span.status == "error" else "info", trace_id=span.trace_id,
                              span_id=span.span_id, duration_ms=round(span.duration * 1000, 1), outcome=span.status,
                              request_id=self.request_ids.get(trace_id, ""), span=span.name)

Read the three exits. On an exception the span is marked error with a stable code (an exception class, or its kind when it has one, such as the LLMError of Adapters, Configuration, and Error Handling) and the exception continues upward; finally always closes the span, so a crash cannot leave one open. A failure that is not an exception, such as a rejected reply, calls span.fail(code). The remote argument takes a W3C traceparent header, which is how a span in another service joins this trace; we use it in the OpenTelemetry section. Now one real request, run from the first scenario in data/observe/scenarios.jsonl on a fake clock:

from evidencedesk.observe import viewer
from evidencedesk.observe.lab import Lab, load_scenarios, run_scenario

rows = {r["id"]: r for r in load_scenarios()}
lab, reply = run_scenario(rows["ob01"])
trace = lab.tracer.last()
print(reply.status, reply.code, "| spans:", len(trace.spans), "| problems:", trace.problems())
print(viewer.tree(trace))

answered ok | spans: 7 | problems: []
request                +0.000s  0.486s  code=ok model_calls=1 status=answered
├─ retrieval           +0.000s  0.030s  hits=3 k=3 top_score=0.56
├─ tool                +0.030s  0.050s  code=ok ok=True tool=lookup_document
├─ context             +0.080s  0.004s  evidence=3 input_tokens_est=326
├─ cache               +0.084s  0.400s  status=miss
│  └─ model            +0.084s  0.400s  cost=0.001446 model=fake-model tokens_in=326 tokens_out=39 usage_estimated=True
└─ validation          +0.484s  0.002s  code=ok

The tree is the first useful debugging tool. Offsets show that stages run in series; the cache span contains the model span because CachedClient calls the model only on a miss. problems() checks that the trace is well formed: one root, every parent present, every child inside its parent's time window. The same trace is a plain JSON fixture, written by python -m evidencedesk.observe ob01 --json and compared with a fresh run by a test, so the format cannot change silently:

sed -n 1,18p kit/data/observe/trace_ob01.json

{
 "trace_id": "c0ffee00000000000000000000000001",
 "spans": [
  {
   "trace_id": "c0ffee00000000000000000000000001",
   "span_id": "5a00000000000001",
   "parent_id": null,
   "name": "request",
   "start": 1000.0,
   "end": 1000.486,
   "status": "ok",
   "error_type": "",
   "attrs": {
    "case_id": "ob01",
    "code": "ok",
    "model_calls": 1,
    "question_chars": 36,
    "request_id": "ob01",

Times are fake-clock seconds and attribute keys are sorted. Loading a fixture runs the same checks, so a hand-edited trace with two roots or an orphan is refused.

Instrument latency by pipeline stage, then tokens and cost

Every stage is a span, so its latency is its duration. The fake clock moves by fixed amounts: 0.03 s for retrieval, 0.05 s for the tool, and for the model SlowClient from Cost and Latency Fundamentals. Real stages vary, which is why a real system looks at percentiles, below. Use self time, the duration minus the children: the cache span lasts as long as the model call it contains, and adding both would count it twice. stage_table reports mean and maximum self time per stage. Twenty-four synthetic requests, where from the thirteenth the fake model is slow and every fourth call times out:

from evidencedesk.observe.lab import synthetic_traffic

busy = Lab()
synthetic_traffic(busy)  # 24 requests; from the 13th the fake model is slow and every fourth call times out
traces = busy.tracer.traces()
for name, window in [("first 12", traces[:12]), ("last 12", traces[12:])]:
    print(name, [(stage, ms) for stage, _, ms, _ in viewer.stage_table(window)][:3])

first 12 [('model', 400.0), ('tool', 50.0), ('retrieval', 30.0)]
last 12 [('model', 1625.0), ('tool', 50.0), ('retrieval', 30.0)]

Mean self time for the model grows from 400 ms to 1625 ms, and the other stages do not move: the trace says where, not why. The model span also carries tokens and cost. It is filled from the same UsageRecord and cost_of as the ledger, not recomputed, so the two cannot disagree. A cache hit has no model span and no ledger record:

from decimal import Decimal

from evidencedesk.usage import cost_of

Q = rows["ob01"]["question"]
fresh = Lab()
fresh.ask(Q)
fresh.ask(Q)  # the same question again
first, second = fresh.tracer.traces()
model = next(s for s in first.spans if s.name == "model")
rec = fresh.ledger.records[0]
print("span  :", model.attrs["tokens_in"], model.attrs["tokens_out"], model.attrs["cost"])
print("ledger:", rec.input_tokens, rec.output_tokens, cost_of(rec).quantize(Decimal("0.000001")), "| estimated:", rec.estimated)
print("second:", [(s.name, s.attrs.get("status")) for s in second.spans if s.name in ("cache", "model")], "| ledger records:", len(fresh.ledger.records))

span  : 326 39 0.001446
ledger: 326 39 0.001446 | estimated: True
second: [('cache', 'hit')] | ledger records: 1

Tokens here are estimated (4 characters per token) because the fake model reports none, and the span says so with usage_estimated=True. Prices are the invented credits of the price table; with a real provider they would come from the current pricing page. One honest gap: a failed model call opens a span but has no usage, so it adds no cost, while call_billed in Budgets, Caching, and Usage Limits assumes a failed retryable try still cost its input. Record failed attempts if your provider bills them.

Trace a failed request

The seven scenarios are a regression set for the observability itself. Each has a fake-model mode (a clean reply, a cut-off, broken JSON, a citation that was never retrieved, a timeout, a slow retrieval) and the code, status and failing stage we expect. status is not new: it is status_of from Safe Failure and Security Regression Tests, which makes a code nobody listed a failure. debug.explain reads the trace, takes the root's code, finds the stage in a table of known causes and names the slowest stage.

from evidencedesk.observe import debug

for row in load_scenarios():
    lab, reply = run_scenario(row)
    t = lab.tracer.last()
    d = debug.explain(t)
    print(f"{row['id']} {row['mode']:<14} {reply.code:<17} {reply.status:<8} stage={d.stage if d else '-':<10} total={t.root.duration:.3f}s")

ob01 ok             ok                answered stage=-          total=0.486s
ob02 ok             no_evidence       refused  stage=retrieval  total=0.030s
ob03 truncated      truncated         failed   stage=validation total=0.486s
ob04 bad_json       invalid_json      failed   stage=validation total=0.486s
ob05 unknown_cite   unknown_citation  failed   stage=validation total=0.486s
ob06 timeout        timeout           failed   stage=model      total=2.084s
ob07 slow_retrieval ok                answered stage=-          total=1.686s

Five of seven did not answer, and only one of the five (the timeout) raised an exception. The others are valid-looking replies that fail validation, which is why validation spans are marked failed with fail(). A request that merely ran long (ob07, a slow retrieval) is not a failure and is not diagnosed; slowness is the next section's job. The command line shows the timeout as a debugger would:

python -m evidencedesk.observe ob06

request                +0.000s  2.084s  code=timeout model_calls=1 status=failed
├─ retrieval           +0.000s  0.030s  hits=3 k=3 top_score=0.56
├─ tool                +0.030s  0.050s  code=ok ok=True tool=lookup_document
├─ context             +0.080s  0.004s  evidence=3 input_tokens_est=326
└─ cache               +0.084s  2.000s  ERROR=timeout
   └─ model            +0.084s  2.000s  model=fake-model ERROR=timeout
request ob06: timeout (user saw: failed)
  stage:  model
  cause:  the model call did not answer in time
  check:  is it one request or every request? see dependency health
  slowest stage: model

The tree shows the model span closing after 2.0 s with ERROR=timeout and, one line up, the cache span that contained it. The retrieval was fine, with three hits, so the evidence is not the cause. What the trace cannot tell you is why the provider was slow, or whether the same happened to other users: that needs the dependency view below. The table of causes is a list of hypotheses to check next, grown from incidents.

Correlate logs, traces, and evaluation cases

Correlation means one id in every place. Each span-end log line carries the request id, trace id and span id; the root span carries the case id; the user appears only as a pseudonym. From an evaluation failure you can find the request, the trace and its log lines, and from an error line you can find the span:

lab, _ = run_scenario(rows["ob05"])
trace = lab.tracer.last()
mine = [r for r in lab.log.records() if r["request_id"] == "ob05"]
print("eval case:", trace.root.attrs["case_id"], "| log lines:", len(mine), "| all share the trace id:", {r["trace_id"] for r in mine} == {trace.trace_id})
for r in mine:
    print(f"  {r['event']:<14} {r['fields'].get('span', ''):<10} {r['outcome']:<6} {r['level']}")
bad = next(r for r in mine if r["outcome"] == "error")  # from a log line back to the span
print("first error line is span:", next(s.name for s in trace.spans if s.span_id == bad["span_id"]))

eval case: ob05 | log lines: 9 | all share the trace id: True
  request.start                    info
  span.end       retrieval  ok     info
  span.end       tool       ok     info
  span.end       context    ok     info
  span.end       model      ok     info
  span.end       cache      ok     info
  span.end       validation error  error
  request.end               failed warning
  span.end       request    ok     info
first error line is span: validation

The request.end line is written inside the root span, before the root closes, which is why span.end request comes last. If your logs and traces live in different systems, this join key is the only thing between you and an hour of guessing. Choose the ids before the first incident, and pass the request id into every layer instead of letting each layer invent its own.

Decide what to capture, sample, and keep

Prompts, retrieved passages and answers are the most useful debugging data and the most sensitive. CapturePolicy has three modes. off (the default) records sizes only. inline puts redacted, truncated text on the span; it suits pre-production, where the data is synthetic. external puts the redacted text in a separate store with its own access rules and shorter retention, and the span keeps a reference. Same request, three policies:

from evidencedesk.observe.privacy import EXTERNAL, INLINE, OFF

for name, policy in [("off", OFF), ("inline", INLINE), ("external", EXTERNAL)]:
    lab = Lab(policy)
    lab.ask(Q)
    m = next(s for s in lab.tracer.spans if s.name == "model")
    shown = {k: (v[:24] + "..." if isinstance(v, str) and len(v) > 24 else v) for k, v in m.attrs.items() if k.startswith(("prompt", "completion"))}
    print(f"{name:<9}", shown, "| separate store:", len(lab.tracer.store.items))

off       {'prompt_chars': 839, 'completion_chars': 156} | separate store: 0
inline    {'prompt_chars': 839, 'prompt_text': '<evidence source="kc-ret...', 'completion_chars': 156, 'completion_text': '{"answer": "You can retu...'} | separate store: 0
external  {'prompt_chars': 839, 'prompt_ref': 'ref-0002', 'completion_chars': 156, 'completion_ref': 'ref-0003'} | separate store: 3

Security note (as of 2026-10-12): The OpenTelemetry GenAI conventions call model instructions, user messages and model outputs sensitive and say instrumentation should not capture them by default but should offer an opt-in. They describe three patterns: do not record (the default), record on span attributes, or store externally and record references, which they recommend for production with sensitive data. They name the environment variable OTEL_INSTRUMENTATION_GENAI_CAPTURE_MESSAGE_CONTENT as an example switch, not a universal one. Metadata such as model name and token counts is not marked sensitive. We found no statement that the core SDK redacts content or enforces the opt-in, so assume it does not. Check the current documentation.

A trace for every request is rarely affordable or needed. Sampler decides from a hash of the trace id, so all spans of a trace agree, and adds a tail rule: keep a trace that failed or was slow whatever the rate. The tail rule needs the finished trace, so it runs in-process; a collector can do the same later.

from collections import Counter

from evidencedesk.observe.privacy import Sampler

for sampler in [Sampler(rate=0.25), Sampler(rate=0.0)]:
    print(sampler, sorted(Counter(sampler.decide(t)[1] for t in traces).items()))

Sampler(rate=0.25, keep_errors=True, slow_s=None) [('dropped', 16), ('error', 3), ('sampled', 5)]
Sampler(rate=0.0, keep_errors=True, slow_s=None) [('dropped', 21), ('error', 3)]

At rate 0.25 five of the 21 healthy traces are kept (an approximation, not exactly one in four) and all three failures; at rate 0 only the failures remain. Sampling hides the typical request, so never compute rates from sampled traces; use counters (next page). Finally, keep content shorter than metadata: Retention holds example values (3 days for content, 30 for metadata), which are placeholders for your own policy. Log and trace retention, deletion and access come back on Monitoring, Budgets, and Incidents.

Detect slow or failing dependencies

Retrieval, the tool and the model are dependencies: they can be slow or fail while our code is fine. health.check compares the nearest-rank 95th percentile of span durations and the error rate of each with limits from data/observe/limits.json, and reports not_enough_data below eight samples, because a percentile of three numbers is one number. The limits are examples to tune on your own measurements.

from evidencedesk.observe import health
from evidencedesk.observe.lab import DATA

limits = health.Limits.load(DATA / "limits.json")
for name, window in [("first 12", traces[:12]), ("last 12", traces[12:]), ("all 24", traces), ("first 3", traces[:3])]:
    print(f"{name:<9}", [(f.stage, f.kind, f.observed, f.limit) for f in health.check(window, limits)])

first 12  []
last 12   [('model', 'slow', 2.0, 1.0), ('model', 'failing', 0.25, 0.2)]
all 24    [('model', 'slow', 2.0, 1.0)]
first 3   [('retrieval', 'not_enough_data', 0.0, 8.0), ('tool', 'not_enough_data', 0.0, 8.0), ('model', 'not_enough_data', 0.0, 8.0)]

The first window is healthy. The last twelve are slow and failing. The all-time window still sees the slowness but not the failures, because three errors in 24 is 12.5 percent and diluted: a long window hides a new problem. Alert on a recent window. Three requests are too few to judge anything. Synthetic traffic proves the code; it does not tell you what your limits should be.

Introduce OpenTelemetry concepts

OpenTelemetry is a vendor-neutral standard and SDK for traces, metrics and logs. Our model already has its concepts: a span with a parent and attributes, a trace id shared by a request's spans, a status, and context propagation (the traceparent header). The SDK adds a tracer provider that makes tracers, span processors that hand finished spans to an exporter, and resource attributes about the service. We use only the in-memory exporter, so nothing leaves the process. The mapping from our names is a small table:

Tool note (as of 2026-10-12): The kit pins opentelemetry-api and opentelemetry-sdk 1.45.1 (released 2026-10-06, Apache-2.0, Python 3.10 or newer); this is an optional dependency of observe/otel.py only. The InMemorySpanExporter is in the SDK source but not on the documentation pages we read, which show a console exporter with a batch processor; a synchronous SimpleSpanProcessor suits tests. The GenAI semantic conventions now live in their own repository and have status Development, so every gen_ai.* name above can change. gen_ai.tool.name appears on the MCP conventions page, so VERIFY that it applies to a tool span as used here. gen_ai.provider.name takes a registry value such as a provider's name; our fake uses its own value. VERIFY every name and the SDK call signatures against the current documentation before relying on them.

export replays a finished local trace through the real SDK with the fake-clock timestamps, parents first. Printed: the main spans of a good request, then the failed model span of the timeout:

ATTRIBUTES = {
    "model": {"model": "gen_ai.request.model", "tokens_in": "gen_ai.usage.input_tokens", "tokens_out": "gen_ai.usage.output_tokens",
              "tokens_cached": "gen_ai.usage.cache_read.input_tokens"},
    "tool": {"tool": "gen_ai.tool.name"},
}
OPERATION = {"request": "invoke_workflow", "retrieval": "retrieval", "tool": "execute_tool", "model": "chat"}  # values of gen_ai.operation.name
PROVIDER = "evidencedesk.fake"  # our own value for gen_ai.provider.name: a fake is not a provider in the registry

from evidencedesk.observe import otel

provider, exporter = otel.make_provider()
otel.export(run_scenario(rows["ob01"])[0].tracer.last(), provider)
for s in exporter.get_finished_spans():
    if s.name in ("request", "tool", "chat fake-model"):
        print(f"{s.name} ({s.kind.name})")
        print("".join(f"    {k} = {v}\n" for k, v in sorted(s.attributes.items()) if k.startswith("gen_ai")), end="")
exporter.clear()
otel.export(run_scenario(rows["ob06"])[0].tracer.last(), provider)
spans = exporter.get_finished_spans()
bad = next(s for s in spans if s.status.status_code.name == "ERROR" and s.name.startswith("chat"))
parent = next(s.name for s in spans if s.context.span_id == bad.parent.span_id)
print(bad.name, bad.status.status_code.name, bad.attributes["error.type"], "| parent span:", parent)

request (INTERNAL)
    gen_ai.operation.name = invoke_workflow
tool (INTERNAL)
    gen_ai.operation.name = execute_tool
    gen_ai.tool.name = lookup_document
chat fake-model (CLIENT)
    gen_ai.operation.name = chat
    gen_ai.provider.name = evidencedesk.fake
    gen_ai.request.model = fake-model
    gen_ai.usage.cache_read.input_tokens = 0
    gen_ai.usage.input_tokens = 326
    gen_ai.usage.output_tokens = 39
chat fake-model ERROR timeout | parent span: cache

Names, operation values, token attributes and parent links arrived as planned; the failed model span has status ERROR and error.type timeout, and its parent is the cache span. Replaying is a teaching shortcut. In a service you would call the tracer where the work happens, with the OpenTelemetry API instead of ours, and the idea of the with block is the same. Now propagation: service A writes the current span into a traceparent header (version, 32-hex trace id, 16-hex span id, flags), service B reads it, and B's span joins A's trace as a child:

hop = otel.propagation_demo(provider)
version, trace_id, span_id, flags = hop["header"].split("-")
print(version, len(trace_id), len(span_id), "| joined the same trace:", hop["same_trace"], "| parent is service-a:", hop["b_parent_is_a"])

00 32 16 | joined the same trace: True | parent is service-a: True

That is the whole mechanism by which one trace crosses an HTTP call, a queue message or a subprocess. OpenTelemetry does not make a trace useful: the span names, the attributes and the privacy rules above still decide that.

Mini-lab: trace a complete RAG request

The finished lab is one request with retrieval, tool, context, cache, model and validation spans, a log line per span, a JSON fixture and a text tree. Five test files cover it: log schema and redaction, span model and propagation, the scenarios and the golden trace, health and diagnosis, and the OpenTelemetry mapping (skipped when the SDK is missing). Wall-clock seconds are stripped with sed:

python -m pytest kit/tests/test_observe_{events,spans,pipeline,health,otel}.py | tail -n 1 | sed 's/ in [0-9.]*s//'

61 passed

Then open test_observe_pipeline.py: one test shows that with the default policy no question or answer text appears in any trace or log, another that logs and traces share ids, another that the golden file matches a fresh run. What they cannot show: that real stage times have this shape, that a real model fails in these seven ways only, or that your redaction covers your data. Each real incident becomes a new scenario row.

Where this shows up at work

Aiko in Osaka runs a support assistant for a logistics firm (an illustrative case). Her team once debugged slow answers by reading prompts in a log file; a review found customer addresses in it. They moved to this design: ids and sizes in logs, content off by default, traces for failures always and for one request in twenty otherwise, and a short-lived external store opened by two people for a specific incident. The next slow-answer report took ten minutes: the trace showed 90 percent of the time in the retrieval span.

Common mistakes

• Logging the prompt "just for now". Content outlives the incident and reaches people who should not see it. Log sizes, use the opt-in capture, and keep content out of normal logs.
• Adding nested durations. A parent contains its children. Report self time or you count the model twice.
• A new id in every layer. Then logs, traces and evaluation cases cannot be joined. Take the id at the edge and pass it down.
• Judging from a tiny or sampled set. Percentiles of a few points, and rates from sampled traces, mislead. Set a minimum sample and count with counters.
• Trusting attribute names from memory. The GenAI conventions are in Development; copy names from the current page and test your mapping.

Try it yourself

1. Easy. Revisit Cost and Latency Fundamentals. Sum the cost attribute of all model spans in the 24 traffic traces and compare with the ledger total. Predict whether they match and how many model spans and ledger calls there are.
2. Medium. Revisit Budgets, Caching, and Usage Limits. Use Sampler(rate=0.0, slow_s=1.5) on the same traces. Predict how many are kept, and why for each.
3. Hard. Revisit Safe Failure and Security Regression Tests. Write a privacy regression check: run all seven scenarios and report which ones put the question or the answer text into any trace or log, once with the default policy and once with inline capture.

Answers

Easy. They match, because the span copies the ledger's cost. There are 24 model spans but 21 ledger calls: the three timed-out calls opened a span and produced no usage record.

total = sum(Decimal(s.attrs["cost"]) for t in traces for s in t.spans if s.name == "model" and "cost" in s.attrs)
print(total, busy.ledger.summary().cost.quantize(Decimal("0.000001")), "| model spans:", sum(s.name == "model" for t in traces for s in t.spans),
      "| ledger calls:", busy.ledger.summary().calls)

0.028044 0.028044 | model spans: 24 | ledger calls: 21

Medium. Three traces fail (the timeouts), and the nine slow-model requests last 1.586 s, above 1.5 s, so 12 of 24 are kept: the whole degraded half and nothing else.

sampler = Sampler(rate=0.0, slow_s=1.5)
decisions = [sampler.decide(t) for t in traces]
print(sorted(Counter(reason for _, reason in decisions).items()), "| kept:", sum(keep for keep, _ in decisions))

[('dropped', 12), ('error', 3), ('slow', 9)] | kept: 12

Hard. The default policy leaks nothing. Inline capture leaks in every scenario, so this check, run in CI, would stop someone switching it on by default. It only searches for the needles you give it; it is a regression test for known text, not proof of safety.

def leaks(policy):
    found = []
    for row in load_scenarios():
        lab, _ = run_scenario(row, policy)
        blob = lab.tracer.last().to_json() + "".join(lab.log.lines)
        found += [row["id"] for needle in (row["question"], "unridden") if needle in blob]
    return found


print("default policy:", leaks(OFF))
print("inline capture:", sorted(set(leaks(INLINE))))

default policy: []
inline capture: ['ob01', 'ob02', 'ob03', 'ob04', 'ob05', 'ob06', 'ob07']

Pass checklist:

• Easy: equal totals, 24 versus 21, and you can explain the three missing records.
• Medium: 3 errors plus 9 slow traces, 12 kept; you named the tail rules.
• Hard: an empty list for the default, all seven ids for inline capture, and you said what the check cannot see.

Summary

• A trace maps one request across retrieval, tool, context, cache, model and validation; a request id, trace id, run id and case id join logs, traces and evaluation cases, and a user appears only as a pseudonym.
• Log structured events with a fixed schema; apply redaction and the never-log list inside the logger, and keep an exception's code, not its message.
• Build the local span model first: parents and children, status, attributes, a JSON fixture and a text tree. Use self time, and take tokens and cost from the usage record.
• Debug from the trace: find the failing stage, then check the cause. Judge dependencies on a recent window with a minimum sample size.
• Content capture is opt-in, redacted and preferably external; sample with a rule that always keeps failures; map to OpenTelemetry names from the current page and propagate context with traceparent.

Next: Monitoring, Budgets, and Incidents turns these traces and logs into counters, dashboards, alerts, retries, safe degradation, budget limits and an incident checklist.