# Debugging AI Agents: The Observability We Wished We Had on Day One

> An agent burned $4 and 90 tool calls on a task that should have taken three, and we were staring at a blank terminal. This is the instrumentation that turned guesswork into a two-minute diagnosis — Octomind's /info, /report, /context, the zstd session log, RUST_LOG tracing, --format jsonl, and OctoHub in front to capture every upstream request.

The agent had been running for six minutes. The spinner was still spinning. By the time I killed it, `/info` put the bill at **$4.18**, and `/report` counted eighty-nine tool calls on a task I'd estimated at three calls and a few cents. It had read the same file eleven times. It had grepped for a symbol, gotten an empty result, rephrased the grep, gotten another empty result, and kept doing that — politely, confidently, expensively — because nothing in the loop told it to stop.

The worst part wasn't the four dollars. It was that I had no idea _why_ until I went looking. The agent doesn't throw a stack trace when it goes wrong. It doesn't crash. It just quietly does the wrong thing, reports success, and hands you a bill. From the outside, a brilliant run and a catastrophic one look identical: text streaming past, tools firing, a final answer.

This post is the instrumentation I wish I'd had wired up before that run instead of after. All of it ships in [Octomind](https://github.com/Muvon/octomind), our open-source Rust agent runtime, and the last section adds [OctoHub](https://github.com/Muvon/octohub) in front to capture the one thing the agent itself can't show you: the raw bytes that actually went to the model.

---

## Why Agents Fail Silently

Traditional software fails loudly. A null deref, a 500, a failed assertion — the failure has a shape, a location, a line number. Agent failures have none of that, because from the runtime's perspective nothing failed. Every API call returned 200. Every tool exited 0. The model produced grammatical, plausible text at every step. The _aggregate_ behavior was wrong, but no individual operation was.

In practice the failures cluster into four shapes, and each one is invisible at exactly the moment you'd want to catch it:

- **Wrong tool, right confidence.** The model reaches for `grep` when it should have read the file, or hits a generic shell when there's a precise tool sitting right there. It doesn't hesitate — wrong tool selection looks exactly like correct tool selection from the outside. (We wrote a whole piece on narrowing the tool surface to fight this: [custom MCPs belong in your repo](/blog/custom-mcps-belong-in-your-repo).)
- **Context truncation.** The conversation grew past the window, compression kicked in, and a fact the agent needed got summarized away. Now it's reasoning from a lossy memory and you can't see the seam.
- **Runaway loops.** Empty result → rephrase → empty result → rephrase. Each turn is individually reasonable. The pattern is the bug, and you only notice it from the tool-call count.
- **Token blowups.** A tool dumped a 200KB file into context, or a single tool-call argument ballooned, and now every subsequent turn re-sends all of it. Cost goes superlinear and the only symptom is the invoice.

You cannot debug what you cannot see. So the first job is to make the run observable — after the fact and during.

---

## Level 0: `/info` — Where Did the Money Go

The fastest question to answer is "what did this session actually cost, and in what shape." Inside any interactive session, `/info`:

```
╭ /info
│ session  my-feature-x
│ model       openrouter:anthropic/claude-sonnet-5
│ tokens      214,883 total
│ breakdown   18,402 in · 9,114 out · 184,201 cache rd · 2,890 cache wr · 276 reasoning
│ cost        $4.18661
│ throughput  41.3 tok/s
╰ /info  my-feature-x
```

Every field here is a diagnostic. The one that cracked my runaway case open was the **breakdown** row. `184,201 cache rd` against `18,402 in` means the same context was being re-read on nearly every turn — the signature of a loop that keeps appending without ever resolving. The tool-call count that confirmed it lives one level down, in `/report`.

`/info` also breaks the spend out beyond the main loop — the compression model's own tokens and cost, cache marker placement and read/write totals, any sub-agents, and the supervisor each get their own section — so when the bill is high you can see whether it was the main conversation or a background process that ate it.

If the session has compressed at all, `/info` shows a **compression** block: how many compressions fired, messages removed, tokens saved, average ratio. That's your truncation early-warning. If you see three project-level compressions in a short session, the agent has been forgetting things, and that's worth knowing before you trust its conclusions.

---

## Level 1: `/report` — Cost Per Request, Not Per Session

`/info` is the session total. `/report` is the itemized receipt — one row per user request, reconstructed from the session log:

```
╭ /report
│ #   request                          cost      tools  task     ai       proc
│ ──  ───────────────────────────────  ────────  ─────  ───────  ───────  ───────
│  1  add a health-check endpoint      $0.04120      3   18s      12s      1s
│  2  wire it into the router          $0.02980      2   11s      9s       1s
│  3  why is the test flaky            $3.98120     84   5m 31s   3m 40s   20s
│ ──  ───────────────────────────────  ────────  ─────  ───────  ───────  ───────
│  Σ  3 request(s)                     $4.05220     89   6m 00s   4m 01s   22s
╰ /report  3 request(s) · $4.05220
```

There it is. Request 3 — "why is the test flaky" — is the entire bill. Eighty-four tool calls for one question. Two well-behaved requests bracket one disaster, and without the per-request split they all blur into the same session total. `/report` is how you find _which prompt_ sent the agent off the rails, which is the question you actually need answered before you can fix anything.

The columns separate `task` time (the whole request, end to end) from `ai` time (just the model calls). When `task` hugely exceeds `ai`, your tools are slow. When they track each other, the model is doing a lot of round-trips — the loop signature again.

---

## Level 2: `/context` — Read What the Agent Is Actually Thinking About

Cost and counts tell you _that_ something went wrong. To see _what_, you read the messages. `/context` dumps the live conversation as structured JSON, with filters:

```
/context              # everything
/context large        # only messages over 1000 chars — find the context hog
/context tool         # only tool results — see what the agent actually got back
/context assistant    # only the model's own turns
```

`/context large` is the one I reach for on token blowups. It surfaces exactly the messages bloating the window — usually one tool result that returned a giant file or a huge JSON blob — and now you know which tool to teach to paginate or truncate. On my flaky-test disaster, `/context tool` showed eighty-odd `grep` results that were all empty. The model never adjusted strategy because nothing told it the strategy wasn't working. Reading the tool results made the loop obvious in about fifteen seconds.

---

## Level 3: The Session Log — The Full, Replayable Record

Everything above reads from one artifact: the session file. Octomind writes every session to

```
~/.local/share/octomind/sessions/<name>.jsonl.zst
```

It's zstd-compressed JSONL — one JSON object per line. Most lines are the raw conversation messages (`role: user|assistant|tool|system`). Interleaved with them are typed markers the runtime needs to reconstruct state on resume:

| Marker                                | What it records                                                       |
| ------------------------------------- | --------------------------------------------------------------------- |
| `STATS`                               | Running totals — cost, API time, tool time — at that point in the run |
| `COMPRESSION_POINT`                   | A compression fired: type, messages removed, tokens saved             |
| `RESTORATION_POINT`                   | A `/done` checkpoint — prior messages collapse on reload              |
| `KNOWLEDGE_ENTRY`                     | A fact extracted during compression, re-injected on resume            |
| `COMMAND`                             | A runtime command (`/model`, `/role`, `/effort`…) replayed on resume  |
| `PLAN_SNAPSHOT` / `SCHEDULE_SNAPSHOT` | The active plan / schedule, so they survive a restart                 |

This file is the ground truth. `/report` is literally generated by decompressing it and walking the `STATS` and `USER`/`COMMAND` entries to bucket cost between requests. You can do the same thing yourself:

```bash
zstd -dc ~/.local/share/octomind/sessions/my-feature-x.jsonl.zst \
  | jq -r 'select(.role == "tool") | "\(.content | length)\t\(.name)"' \
  | sort -n | tail
```

That one-liner ranks tool results by size straight out of the log — your token hogs, without even opening a session. Because the log is append-only JSONL, it's also a perfect replay artifact: resume the exact session with `octomind run --resume my-feature-x`, or grab the most recent one for the current directory with `--resume-recent`, and the runtime rebuilds state from these same lines.

---

## Level 4: `RUST_LOG` — When You Need to See Inside the Runtime

The session log shows _what the conversation was_. When you need to see _what the runtime did_ — why an MCP server didn't load, why a tool was skipped, what the provider actually returned — turn on tracing. Octomind is built on the `tracing` crate, gated behind the standard `RUST_LOG` environment variable. In CLI mode there's deliberately **no** tracing subscriber unless you ask for one — users get clean colored output, not a firehose. Set `RUST_LOG` and the firehose turns on:

```bash
# Everything at debug
RUST_LOG=debug octomind run

# Scope it to one module — far more useful in practice
RUST_LOG=octomind::mcp=debug octomind run

# Multiple scopes, mixed levels
RUST_LOG=octomind::session=debug,octomind::mcp=trace octomind run
```

Scoping matters. `RUST_LOG=debug` on a busy session is unreadable; `RUST_LOG=octomind::mcp=debug` when a tool won't show up tells you precisely which candidate was accepted or rejected and why. This is the level where "the agent can't see my tool" stops being a mystery.

In the structured-output modes — ACP and WebSocket — stdout and stderr are reserved for the protocol, so tracing goes to files instead:

```
~/.local/share/octomind/logs/acp-debug.log        ← ACP tracing
~/.local/share/octomind/logs/acp-errors.jsonl     ← ACP errors, structured
~/.local/share/octomind/logs/websocket-debug.log  ← WebSocket tracing
```

If you're running Octomind behind an editor over ACP and something's wrong, those files are where the evidence lives.

---

## Level 5: `--format jsonl` — Pipe the Run Into Your Own Tooling

Everything so far is for a human reading a terminal. The moment you put an agent in CI or a pipeline, you need the run as a stream of structured events you can assert on. `octomind run --format jsonl` emits one JSON object per line — the same internal event stream the WebSocket server uses — tagged by `type`:

```bash
echo "audit the auth module" | octomind run developer:general --format jsonl
```

Each line is a discrete event. The variants you'll care about:

| `type`        | Carries                                                                                                                          |
| ------------- | -------------------------------------------------------------------------------------------------------------------------------- |
| `assistant`   | A chunk of the model's response text                                                                                             |
| `thinking`    | Reasoning content, separate from the answer                                                                                      |
| `tool_use`    | `tool`, `tool_id`, `server`, `params` — the agent is about to act                                                                |
| `tool_result` | `tool`, `content`, `success` — what came back                                                                                    |
| `cost`        | `session_tokens`, `session_cost`, `input_tokens`, `output_tokens`, `cache_read_tokens`, `cache_write_tokens`, `reasoning_tokens` |
| `error`       | A failure message                                                                                                                |
| `injected`    | A non-user turn — scheduled timer, background agent, skill — with its `source_kind`                                              |
| `skill`       | A skill activated, used, or forgotten                                                                                            |

Now the failure modes become assertions. Count `tool_use` events and fail the build if a single request exceeds a threshold — that's your runaway-loop tripwire. Watch the `cost` event's `session_cost` and alert past a budget. Tail `tool_result` for `success: false`. The agent that used to fail silently now fails in a way `jq` can catch:

```bash
echo "run the migration check" \
  | octomind run --format jsonl \
  | jq -c 'select(.type == "tool_use") | .tool' \
  | sort | uniq -c | sort -rn
```

That prints a tool-call histogram for the whole run. If `shell` is at the top with a count of 60, you've found your loop before it found your wallet — and it's a one-liner in a CI step, not a person watching a spinner.

---

## Level 6: OctoHub — Capture Every Upstream Request

There's one thing none of the above can show you, because it happens below the agent: the **exact bytes** Octomind sent to the provider and the exact bytes that came back. The agent's view is its own messages. It cannot show you the wire-level request — the resolved model, the full serialized payload, the provider's raw response, the real latency. When you suspect the problem is in the translation layer (a system prompt that's not what you think, a tool schema the provider mangled, a model that's not the one you configured), you need to see the wire.

[OctoHub](https://github.com/Muvon/octohub) is our LLM proxy, and full request/response logging is its reason to exist. Point Octomind at it instead of the provider, and every completion lands in a database with the input, the output, and the metrics attached. Run it:

```bash
./octohub   # listens on 127.0.0.1:8080 by default
```

It speaks both `POST /v1/completions` (its native shape) and `POST /v1/chat/completions` (classic OpenAI, drop-in for any OpenAI-compatible client), and both hit the same engine and write to the same `completions` table with the same record `id`. After a run, pull the raw records back with the admin API:

```bash
curl "http://127.0.0.1:8080/v1/admin/completions?limit=50" \
  -H "Authorization: Bearer <master-key>"
```

Each record carries the full picture the agent couldn't:

```json
{
  "id": "cmpl_<uuid>",
  "session_id": "<uuid>",
  "input_model": "my-model",
  "resolved_model": "gpt-5.5",
  "provider": "openai",
  "usage": {
    "input_tokens": 10,
    "output_tokens": 5,
    "total_tokens": 15,
    "cost": 0.0001,
    "request_time_ms": 320
  },
  "input": [...],
  "output": [...],
  "created_at": 1700000000
}
```

`input_model` vs `resolved_model` alone catches a whole class of "why is it behaving differently" bugs — you asked for one model, an alias resolved to another. The `input` and `output` arrays are the literal payloads, so a tool schema the provider choked on is right there to read. `request_time_ms` is the provider's real latency, separate from anything Octomind added. And `GET /v1/admin/usage` aggregates it all by API key and time bucket, which is how you go from "the agent is expensive" to "this key, this model, this hour" without guessing. (If you run agents against several providers at once, the proxy is also where that gets sane — see [running one agent across many models](/blog/running-one-ai-agent-across-many-models).)

The proxy turns the model boundary from an opaque edge into a logged, queryable surface. Default storage is SQLite — `db_url = "sqlite://octohub.db"`, or set `OCTOHUB_DB_URL` — so there's no infrastructure to stand up before you can start reading requests.

---

## When the Agent Does X, Look at Y

The whole point is to convert "the agent did something baffling" into a known lookup. This is the table taped above my desk:

| Symptom                              | First look                                         | What you're looking for                       |
| ------------------------------------ | -------------------------------------------------- | --------------------------------------------- |
| Session cost out of nowhere          | `/info`                                            | `cache rd` ≫ `in` in the breakdown row        |
| One prompt cost everything           | `/report`                                          | The single row carrying the bill              |
| Context window full / model "forgot" | `/info` compression block, then `/context large`   | Compression count, and the oversized message  |
| Loop / repeated tool calls           | `/report` tools column, or `jsonl` + `uniq -c`     | Same tool, same args, no progress             |
| Tool not available to the agent      | `RUST_LOG=octomind::mcp=debug`                     | Why the candidate was skipped                 |
| Tool result looks wrong              | `/context tool`                                    | The actual bytes the model received           |
| Behaves like a different model       | OctoHub `GET /v1/admin/completions`                | `input_model` vs `resolved_model`             |
| Provider error or weird latency      | OctoHub record `input`/`output`, `request_time_ms` | The raw payload and real timing               |
| Need a CI tripwire                   | `--format jsonl`                                   | Count `tool_use`, watch `cost`, catch `error` |
| Reproduce an exact run               | `octomind run --resume <name>`                     | Replay from `<name>.jsonl.zst`                |

---

## The Two-Minute Diagnosis

Here's how the flaky-test disaster would have gone with this wired up from the start, instead of the six-minute mystery it actually was.

Spinner runs long. `/report` — request 3 is $3.98 and 84 tool calls; the other two are fine. So it's that prompt. `/context tool` — eighty empty `grep` results, the model never changing strategy. There's the loop, and there's why. Total time to root cause: about ninety seconds, no four dollars required, because in a real pipeline the `jsonl` tool-call histogram would have tripped a threshold and killed the run at tool call twenty.

None of this is exotic. It's the same instinct as logging, metrics, and tracing in any system you'd put in production — applied to a system whose failures are quiet by nature. The agent won't tell you it's lost. But the run is fully observable if you ask it the right way: `/info` for the shape, `/report` for the culprit, `/context` for the reasoning, the session log for the record, `RUST_LOG` for the runtime, `--format jsonl` for the machine, and OctoHub for the wire.

Wire it up before the expensive run, not after.

— Don

---

_[Octomind](https://github.com/Muvon/octomind) and [OctoHub](https://github.com/Muvon/octohub) are open source under Apache-2.0. If a debugging surface you need is missing, [open an issue](https://github.com/Muvon/octomind/issues) — the observability in this post largely exists because we kept getting surprised by our own agents._