{
  "trace_id": "sess_8f3a-2c1b-49ab",
  "turn_number": 7,
  "tool_name": "search_codebase",
  "input_hash": "sha256:9e6b...c104",
  "output_hash": "sha256:4f2a...8810",
  "latency_ms": 412,
  "token_delta": { "input": 8421, "output": 64, "cached": 0 },
  "stop_reason": "tool_use"
}

import { trace, SpanStatusCode } from "@opentelemetry/api";

const tracer = trace.getTracer("harness");

async function runTurn(messages: Message[]): Promise<Response> {
  return tracer.startActiveSpan("turn", async (span) => {
    span.setAttribute("turn_number", messages.filter(m => m.role === "tool").length);
    const modelSpan = tracer.startSpan("model.call");
    try {
      const response = await callModel(messages);
      modelSpan.setAttribute("token_delta", response.usage.total_tokens);
      modelSpan.setAttribute("stop_reason", response.stopReason);
      modelSpan.end();
      if (response.toolUse) {
        const toolSpan = tracer.startSpan(`tool.${response.toolUse.name}`);
        try {
          const result = await executeTool(response.toolUse);
          toolSpan.setStatus({ code: SpanStatusCode.OK });
          return response;
        } catch (e) {
          toolSpan.recordException(e);
          toolSpan.setStatus({ code: SpanStatusCode.ERROR, message: e.message });
          throw e;
        } finally {
          toolSpan.end();
        }
      }
      return response;
    } finally {
      span.end();
    }
  });
}

def replay(session_log: list[TurnRecord], model: ModelProvider) -> ReplayResult:
    messages = [system_prompt()]
    diverged_at = None
    for i, turn in enumerate(session_log):
        # Reconstruct the model call with the recorded input
        replayed = model.complete(messages, seed=turn.seed)
        if hash(replayed.tool_call) != turn.input_hash:
            diverged_at = i  # non-determinism: model produced a different call
            break
        messages.append(replayed.to_message())
        # Use the recorded tool output, not a re-execution
        messages.append(turn.recorded_tool_result)
    return ReplayResult(messages=messages, diverged_at=diverged_at)

from opentelemetry import trace
from opentelemetry.semconv._incubating.attributes import GenAIAttributes

tracer = trace.get_tracer("harness")

@tracer.start_as_current_span("model.call")
def call_model(messages, model_name):
    span = trace.get_current_span()
    span.set_attribute(GenAIAttributes.GEN_AI_SYSTEM, "anthropic")
    span.set_attribute(GenAIAttributes.GEN_AI_REQUEST_MODEL, model_name)
    response = provider.complete(messages, model=model_name)
    span.set_attribute(GenAIAttributes.GEN_AI_USAGE_INPUT_TOKENS, response.usage.input_tokens)
    span.set_attribute(GenAIAttributes.GEN_AI_USAGE_OUTPUT_TOKENS, response.usage.output_tokens)
    span.set_attribute(GenAIAttributes.GEN_AI_RESPONSE_FINISH_REASON, response.stop_reason)
    return response

function diffSessions(passing: TurnRecord[], failing: TurnRecord[]): DiffPoint | null {
  const n = Math.min(passing.length, failing.length);
  for (let i = 0; i < n; i++) {
    const p = passing[i], f = failing[i];
    if (p.tool_name !== f.tool_name) return { turn: i, kind: "tool_choice", passing: p, failing: f };
    if (p.input_hash !== f.input_hash) return { turn: i, kind: "tool_input", passing: p, failing: f };
    if (p.output_hash !== f.output_hash) return { turn: i, kind: "tool_output", passing: p, failing: f };
  }
  if (passing.length !== failing.length) return { turn: n, kind: "length", passing: null, failing: null };
  return null; // identical
}

function withObservability(loop: Loop): Loop {
  return {
    ...loop,
    callModel: async (messages) => {
      const start = Date.now();
      const response = await loop.callModel(messages);
      emit({
        trace_id: getCurrentTraceId(),
        turn_number: getTurnCount(),
        latency_ms: Date.now() - start,
        token_delta: response.usage,
        stop_reason: response.stopReason
      });
      return response;
    },
    executeTool: async (toolCall) => {
      const start = Date.now();
      const result = await loop.executeTool(toolCall);
      emit({
        trace_id: getCurrentTraceId(),
        turn_number: getTurnCount(),
        tool_name: toolCall.name,
        input_hash: sha256(JSON.stringify(toolCall.input)),
        output_hash: sha256(JSON.stringify(result)),
        latency_ms: Date.now() - start
      });
      return result;
    }
  };
}

# Module 10 — Observability and Debugging

**Course**: Master Course · **Module**: 10 · **Duration**: 45 min · **Prerequisites**: Modules 1–9

> *A harness you can't observe is a harness you can't improve.*

---

## Learning Objectives

1. Implement the 6 observability layers (logs, traces, token accounting, replay, metrics, session diffing).
2. Apply the 5 post-mortem questions to debug a harness failure.
3. Use replay-driven debugging to reproduce failures deterministically.
4. Emit the 8-field per-turn payload and export it through OpenTelemetry into a backend you can actually query.
5. Diagnose "invisible-state" bugs that only surface in sessions longer than 30 turns.

---

# 10.1 — Observability Layers

*What to capture, why each layer exists, and how they stack. Module 1.4's payload is the floor; the other five layers build on it.*

## The six layers

| Layer | What it captures | Use case |
| --- | --- | --- |
| **Structured logs** | Tool calls with inputs, outputs, timestamps | Post-mortem debugging |
| **Trace/spans** | Full execution tree with latency per step | Performance profiling |
| **Token accounting** | Token usage per message, per tool, per session | Cost attribution |
| **Replay** | Ability to re-run a session step-by-step | Bug reproduction |
| **Metrics export** | OpenTelemetry, Prometheus counters | Production monitoring |
| **Session diffing** | Compare two sessions to understand behavioral change | Regression testing |

Module 1.4's per-turn payload (`trace_id`, `turn_number`, `tool_name`, `input_hash`, `output_hash`, `latency_ms`, `token_delta`, `stop_reason`) is the structured-log layer — the foundation. The other five layers build on it. **A loop that emits nothing is below the floor; a loop with payload + one of the five is at the floor; production wants payload plus all five.**

> **Read this in real code: Tau's event union (DD-21).** Tau is the reference implementation for "events as the observability layer." Instead of building a separate telemetry system, Tau's 14-member typed event union (`AgentStart`, `TurnStart`/`End`, `MessageStart`/`Delta`/`End`, `ThinkingDelta`, `ToolExecutionStart`/`Update`/`End`, `Retry`, `QueueUpdate`, `Error`, `AgentEnd`) IS the trace. Every model is a frozen Pydantic dataclass with `ConfigDict(extra="forbid")` — the contract is closed and type-checked, so a frontend cannot receive an event it doesn't know about and adding an event is a breaking change caught by the type system. The same event stream drives five consumers: print mode (terminal transcript), Rich (live rendering), Textual (interactive TUI), JSON export (structured log), and HTML transcript rendering. See `src/tau_agent/events.py`.

## Layer 1 — Structured logs (the payload, fully specified)

The per-turn payload is a JSON object. Make every field present on every turn; default nulls rather than omitting fields, so downstream parsers don't have to handle missing keys.

```json
{
  "trace_id": "sess_8f3a-2c1b-49ab",
  "turn_number": 7,
  "tool_name": "search_codebase",
  "input_hash": "sha256:9e6b...c104",
  "output_hash": "sha256:4f2a...8810",
  "latency_ms": 412,
  "token_delta": { "input": 8421, "output": 64, "cached": 0 },
  "stop_reason": "tool_use"
}
```

Two engineering points on this shape. **First, the hashes are the dedup signal.** Same `input_hash` across two consecutive turns with the same `output_hash` means the model is stuck in a loop — it called the same tool with the same arguments and got the same result and did not change course. Module 7.2's stuck-loop detector is built on exactly this signal. **Second, `token_delta` is an object, not a scalar.** Splitting input/output/cached lets you attribute cost correctly: cached input tokens are billed at one-tenth the rate of fresh input tokens on most providers, so a scalar total over-attributes cost on cache-heavy sessions.

## Layer 2 — Traces and spans

Spans nest. A top-level agent span contains turn spans; each turn span contains a model-call span and, if a tool fired, a tool-execution span. The structure mirrors the execution tree and is what a backend like Jaeger, Honeycomb, or Datadog renders as a waterfall.

```typescript
import { trace, SpanStatusCode } from "@opentelemetry/api";

const tracer = trace.getTracer("harness");

async function runTurn(messages: Message[]): Promise<Response> {
  return tracer.startActiveSpan("turn", async (span) => {
    span.setAttribute("turn_number", messages.filter(m => m.role === "tool").length);
    const modelSpan = tracer.startSpan("model.call");
    try {
      const response = await callModel(messages);
      modelSpan.setAttribute("token_delta", response.usage.total_tokens);
      modelSpan.setAttribute("stop_reason", response.stopReason);
      modelSpan.end();
      if (response.toolUse) {
        const toolSpan = tracer.startSpan(`tool.${response.toolUse.name}`);
        try {
          const result = await executeTool(response.toolUse);
          toolSpan.setStatus({ code: SpanStatusCode.OK });
          return response;
        } catch (e) {
          toolSpan.recordException(e);
          toolSpan.setStatus({ code: SpanStatusCode.ERROR, message: e.message });
          throw e;
        } finally {
          toolSpan.end();
        }
      }
      return response;
    } finally {
      span.end();
    }
  });
}
```

The span hierarchy is the trace; the trace is the profile. Latency outliers jump out immediately: a turn that took 8.2s when the median is 400ms is visible in the waterfall, and the nested span tells you whether the time was in the model call or the tool call. Without traces, you have a number (latency) but no attribution.

## Layer 3 — Token accounting

Per-turn `token_delta` is necessary but not sufficient. The production view aggregates across the session: total tokens consumed, cost per turn, cost per tool, cost per task type. This is cost attribution — without it, you cannot answer "which kinds of tasks are expensive?" or "did the prompt change in module 9 save us money?".

The aggregate view derived from the per-turn payload:

| Slice | What it answers |
| --- | --- |
| Per task | Which task types are most expensive? |
| Per tool | Which tools cost the most to call (large inputs)? |
| Per turn | Where does the cost spike in a session? |
| Per model | Did the model upgrade change cost? (Module 10.4's replay use) |

Cost attribution turns observability from a debugging tool into a budgeting tool. A team that cannot attribute cost to task type is flying blind on spend.

## Layer 4 — Replay

Replay is the substrate of deterministic debugging. The structured logs (with input/output hashes, or full content if your policy permits) let you reconstruct the exact context at each turn and re-run the session turn by turn.

```python
def replay(session_log: list[TurnRecord], model: ModelProvider) -> ReplayResult:
    messages = [system_prompt()]
    diverged_at = None
    for i, turn in enumerate(session_log):
        # Reconstruct the model call with the recorded input
        replayed = model.complete(messages, seed=turn.seed)
        if hash(replayed.tool_call) != turn.input_hash:
            diverged_at = i  # non-determinism: model produced a different call
            break
        messages.append(replayed.to_message())
        # Use the recorded tool output, not a re-execution
        messages.append(turn.recorded_tool_result)
    return ReplayResult(messages=messages, diverged_at=diverged_at)
```

Two replay modes, with different purposes. **Faithful replay** uses the recorded tool outputs (as above) and reproduces the model's path exactly — useful for debugging what the model saw at turn N. **Counterfactual replay** re-executes tools against live state (or substitutes a different model) — useful for testing whether a model upgrade or a tool change would have produced a different outcome. Both modes depend on the payload having captured enough to reconstruct context; without it, replay is impossible.

## Layer 5 — Metrics export (OpenTelemetry)

For production monitoring, export metrics and traces via OpenTelemetry (OTel). OTel is the CNCF-backed standard schema for LLM calls, tool calls, and agent workflows, adopted by Google Cloud, AWS, Azure, and Datadog. **Using OTel avoids observability vendor lock-in — you can switch backends (Datadog, Honeycomb, Jaeger) without changing instrumentation.**

The OTel GenAI semantic conventions extend the base spec with LLM-specific attributes: `gen_ai.system`, `gen_ai.request.model`, `gen_ai.usage.input_tokens`, `gen_ai.usage.output_tokens`, `gen_ai.response.finish_reason`. These map almost one-to-one onto the per-turn payload fields, so instrumenting for OTel is largely a matter of emitting the payload as span attributes.

```python
from opentelemetry import trace
from opentelemetry.semconv._incubating.attributes import GenAIAttributes

tracer = trace.get_tracer("harness")

@tracer.start_as_current_span("model.call")
def call_model(messages, model_name):
    span = trace.get_current_span()
    span.set_attribute(GenAIAttributes.GEN_AI_SYSTEM, "anthropic")
    span.set_attribute(GenAIAttributes.GEN_AI_REQUEST_MODEL, model_name)
    response = provider.complete(messages, model=model_name)
    span.set_attribute(GenAIAttributes.GEN_AI_USAGE_INPUT_TOKENS, response.usage.input_tokens)
    span.set_attribute(GenAIAttributes.GEN_AI_USAGE_OUTPUT_TOKENS, response.usage.output_tokens)
    span.set_attribute(GenAIAttributes.GEN_AI_RESPONSE_FINISH_REASON, response.stop_reason)
    return response
```

The agent-level layer (tasks, agents, teams, memory) is still maturing — the community ATSC draft extends OTel to cover turns, handoffs, HITL events, and memory lineage. For now, the **model-call and tool-call layers are stable; the agent-workflow layer is emerging.** Build the stable layers today; design your span names so the agent-workflow layer slots in when the spec lands.

## Layer 6 — Session diffing

Compare a failing session to a passing session. Where do they diverge? The divergence point is where the bug was introduced — often a context difference (Module 3 rot), a tool-output difference (Module 2 formatting), or a model-version difference.

```typescript
function diffSessions(passing: TurnRecord[], failing: TurnRecord[]): DiffPoint | null {
  const n = Math.min(passing.length, failing.length);
  for (let i = 0; i < n; i++) {
    const p = passing[i], f = failing[i];
    if (p.tool_name !== f.tool_name) return { turn: i, kind: "tool_choice", passing: p, failing: f };
    if (p.input_hash !== f.input_hash) return { turn: i, kind: "tool_input", passing: p, failing: f };
    if (p.output_hash !== f.output_hash) return { turn: i, kind: "tool_output", passing: p, failing: f };
  }
  if (passing.length !== failing.length) return { turn: n, kind: "length", passing: null, failing: null };
  return null; // identical
}
```

The diff's `kind` field points directly at the cause. `tool_choice` divergence means the model decided differently given (approximately) the same context — investigate context rot or model version. `tool_input` divergence means the model called the same tool differently — investigate prompt drift. `tool_output` divergence means the same call produced different results — investigate non-deterministic tools, flaky networks, or data changes. **Without session diffing, regression testing of agent behavior is folklore; with it, regression is a locate-the-divergence exercise.**

---

# 10.2 — Debugging Harness Failures

*The 5-question post-mortem. Most debugging stops at question 2; the real cause is usually in questions 1, 3, or 5.*

## The 5 post-mortem questions

When a harness fails, answer these 5 questions — in order:

1. **What did the model SEE?** (the full context at the moment of failure)
2. **What did the model DECIDE?** (its reasoning / tool call)
3. **What did the tool RETURN?** (the result inserted into context)
4. **What did the harness DO with that?** (the loop's response — append, retry, halt?)
5. **What was in CONTEXT at the time of failure?** (the accumulated state — Module 3)

Most debugging stops at question 2 ("the model made a bad decision"). The real cause is usually in questions 1, 3, or 5: the model saw the wrong thing (bad context), or the tool returned something misleading, or the context had rotted. The discipline of working through all five — using the structured logs to answer each — is what separates guessing from diagnosing.

## A worked debug walkthrough

A real failure mode, traced through the five questions with observability data.

**Symptom**: An agent that should write a passing test suite enters an infinite retry loop on turn 18 and burns the token budget.

- **Q1 (saw)**: Open the structured log for turn 17. The model's input context was 31,200 tokens — above the 30k context-position performance cliff (Module 3, the "Lost in the Middle" finding, arXiv:2307.03172). The most recent tool output (the test failure it was trying to fix) was buried in position 8 of the context, not at the end.
- **Q2 (decided)**: The model re-ran `bash pytest` with the same arguments it had used on turn 16. The `input_hash` confirms identical arguments.
- **Q3 (returned)**: The test output was 6,400 tokens (Module 2's 67.6% rule in action — tool output dominating context). The truncation policy was not applied because the test runner produced structured output, not stdout.
- **Q4 (harness did)**: The loop appended the result and continued. No compaction triggered (threshold was 80% of window; context was at 62%).
- **Q5 (context)**: The accumulated history contained 9 prior test runs, none truncated. The relevant signal — which test was failing — was repeated 9 times.

**Root cause**: Not a model decision failure. A context-management failure: the loop did not mask prior tool outputs (Module 3's observation masking), so the failing-test signal was buried under repeated noise, and the model kept reaching for the same fix because the feedback it needed was in context-position jail. **The fix lives in Module 3, not in the prompt.** Without the structured logs, this would have been filed as "the model is dumb" — the most common misdiagnosis in agent engineering.

## Replay-driven debugging

Reproduce the failure deterministically by replaying the logged session step-by-step. The structured logs (with input/output hashes) let you reconstruct the exact context at each turn. **Replay against a different model to test whether a model upgrade fixes (or causes) the bug** — counterfactual replay is how you de-risk model-version upgrades. Replay against the same model with observation masking turned on to test whether the fix works before shipping it.

## The "invisible state" problem

Bugs that only appear in sessions longer than 30 turns. The harness works fine in testing (short sessions) and fails in production (long sessions). The cause is usually context rot (Module 3) — the accumulated history degrades the model's grip on the task. **Without long-session observability, these bugs are invisible until production.** The defense is to instrument for session length, run the same task at multiple session lengths in CI, and alert when turn-count-to-completion drifts upward — the leading indicator of context rot before it produces a hard failure.

---

# 10.3 — The Observability Wrapper Pattern

*You can add observability to any loop without modifying the harness core, by wrapping the model-call and tool-execution functions.*

The loop's interface (`callModel`, `executeTool`) is the extension point. Everything else plugs in around it. This is the same pattern used in Module 6 (permission gates) and Module 11 (security checks) — wrap, do not fork.

```typescript
function withObservability(loop: Loop): Loop {
  return {
    ...loop,
    callModel: async (messages) => {
      const start = Date.now();
      const response = await loop.callModel(messages);
      emit({
        trace_id: getCurrentTraceId(),
        turn_number: getTurnCount(),
        latency_ms: Date.now() - start,
        token_delta: response.usage,
        stop_reason: response.stopReason
      });
      return response;
    },
    executeTool: async (toolCall) => {
      const start = Date.now();
      const result = await loop.executeTool(toolCall);
      emit({
        trace_id: getCurrentTraceId(),
        turn_number: getTurnCount(),
        tool_name: toolCall.name,
        input_hash: sha256(JSON.stringify(toolCall.input)),
        output_hash: sha256(JSON.stringify(result)),
        latency_ms: Date.now() - start
      });
      return result;
    }
  };
}
```

The wrapper is non-invasive: the loop's core logic is untouched, and observability can be added, removed, or swapped (console emit in dev, OTel in prod) by changing the wrapper. **A harness whose core loop knows about OTel has coupled concerns; a harness whose loop knows nothing about telemetry and is wrapped has separated them.**

---

## Anti-Patterns

### The un-observable loop
A loop that emits no structured per-turn data. When it fails (and it will), you cannot reproduce the failure. Cured by the observability wrapper above — there is no excuse to ship a loop without it.

### Logging only on error
Events emitted only when something fails. You cannot debug a failure without the turns leading up to it — the cause is almost always upstream of the error. Cure: emit on every turn; filter at the consumer.

### The scalar token counter
A single cumulative `tokens_used` field. Cannot attribute cost to a turn, a tool, or a task. Cure: per-turn `token_delta` as an object (input/output/cached); aggregate at the consumer.

### Console logs as telemetry
`console.log` calls scattered through the loop. Unstructured, un-queryable, lost on process exit. Cure: structured JSON emission to a sink you can query (file, OTel collector, log aggregator).

---

## Key Terms

| Term | Definition |
| --- | --- |
| **Structured logs** | Tool calls with inputs/outputs/timestamps (Module 1.4's payload) |
| **Trace/spans** | Execution tree with per-step latency; nested model/tool spans |
| **Replay** | Re-run a logged session step-by-step; faithful vs counterfactual modes |
| **Session diffing** | Compare two sessions to find divergence (tool_choice / tool_input / tool_output) |
| **5 post-mortem questions** | Saw / Decided / Returned / Harness-did / Context-was |
| **Invisible state** | Bugs appearing only in long (>30 turn) sessions |
| **OpenTelemetry GenAI conventions** | CNCF standard for LLM call attributes; backend-agnostic export |
| **Cost attribution** | Aggregating `token_delta` by task/tool/turn for budgeting |

---

## Lab Exercise

See `07-lab-spec.md`. Instrument a custom harness with OpenTelemetry — emit the 8-field payload as span attributes and export a trace to a local Jaeger or Honeycomb instance. Intentionally introduce a bug (a non-idempotent tool that produces different output on retry); use structured logs to find it WITHOUT reading the model's output (only the observability data). Then run the same task twice, change one tool's output format between runs, and use session diffing to locate the divergence turn.

---

## References

1. **Module 1.4** — the per-turn payload; the structured-log foundation this module builds on.
2. **OpenTelemetry GenAI Semantic Conventions** — the CNCF standard for LLM call attributes (`gen_ai.*`).
3. **Module 3** — context rot and the "Lost in the Middle" finding (arXiv:2307.03172) as the cause of invisible-state bugs and the 67.6% tool-output dominance.
4. **Module 7.2** — stuck-loop detection, built on the `input_hash`/`output_hash` dedup signal.
5. **Module 8** — checkpointing as the substrate for replay and session diffing.
6. **Module 9** — verification as related to observability (both detect deviation from intent).
7. **Tau (DD-21)** — the 14-member typed event union as the reference observability architecture; `src/tau_agent/events.py`.
8. **Module 11** — observability data feeds the security audit trail (which ASI risks were realized, and when).