Chapter 128 · Production

Observability: traces, spans and what to log

The span tree for one run, the eleven attributes that make a trace answer questions, sampling that keeps the interesting runs, and the three dashboards worth building.

8 min read

Chapter 89 built a trace for a human reading one run. Chapter 124 built an immutable record for an investigator. This is the third artifact: aggregate telemetry, for the questions that are about thousands of runs at once.

They are genuinely three things. Trying to make one serve all three produces something too heavy to emit on every request and too lossy to investigate with.

The span tree

// One run, as spans. The shape matters more than the library: a flat log
// cannot answer "where did the time go", which is the question this
// artifact exists for.
run  (2.9 s)
├── resolve_identity        (12 ms)
├── rewrite_query           (180 ms)   model call
├── retrieve                (61 ms)
│   ├── embed_query         (22 ms)
│   ├── vector_search       (31 ms)
│   └── rerank              (8 ms)
├── assemble_context        (4 ms)
├── step_1                  (1.4 s)
│   ├── generate            (1.1 s)    model call
│   └── tool:lookup_order   (290 ms)
│       ├── authorise       (3 ms)
│       └── http            (284 ms)
├── step_2                  (1.0 s)
│   └── generate            (1.0 s)    model call
└── validate_response       (24 ms)
    ├── schema              (1 ms)
    └── citations           (23 ms)

Two properties to insist on. Tool calls are children of the step that made them, so a slow run shows whether the model or the backend was slow. And validation is its own span, because citation checking against a database is not free and it hides inside "generation" otherwise.

Eleven attributes

// On the run span. Everything here is something a query has actually
// needed, and nothing here is content.
interface RunAttributes {
  'agent.run_id': string
  'agent.user_group': string        // not user_id — see below
  'agent.question_shape': string    // digits replaced, chapter 123's normaliser
  'agent.intent': string            // chapter 102's strata
  'agent.steps': number
  'agent.tools_called': string      // comma-joined names
  'agent.terminated_by': 'natural' | 'step_limit' | 'time_limit' | 'spend_limit' | 'error'
  'agent.refused': boolean
  'agent.refusal_reason'?: string
  'agent.tokens_in' | 'agent.tokens_out': number
  'agent.cost_usd': number
  'llm.model_id': string            // resolved
  'config.prompt_hash': string
  'config.corpus_snapshot': string
}

// user_group rather than user_id, deliberately. Telemetry backends are
// widely readable, retained inconsistently and often third-party, and
// chapter 121 listed traces as a leak path. The audit log holds the
// user_id; the telemetry holds the group, which is what aggregate
// questions need.

terminated_by is the highest-value single attribute in the list. A shift in its distribution is the earliest signal of almost every control-flow regression chapter 90 catalogued, and it costs one enum on one span.

An error rate tells you about the runs that failed. The termination distribution tells you about the runs that succeeded differently, which is where a non-deterministic system degrades first.

What never goes in telemetry

const NEVER = [
  'The question text. Use the shape; the audit log has the text.',
  'Retrieved chunk content. Ids only.',
  'The answer. A hash and a length.',
  'Tool arguments. A hash, plus the names of the fields present.',
  'Recalled memory statements. Ids only.',
]

// The field-names-present trick is worth stealing. It answers "is the
// model passing the optional date range" without recording any value.
'tool.args_fields': Object.keys(args).sort().join(',')   // "customerId,period"

Sampling

Head sampling at a fixed rate throws away exactly the runs worth keeping.

// Tail sampling: decide after the run, when its properties are known.
export function keepTrace(run: CompletedRun): boolean {
  if (run.error) return true
  if (run.terminatedBy !== 'natural') return true
  if (run.refused) return true
  if (run.flags.length) return true                    // injection suspected, etc.
  if (run.durationMs > P99_THRESHOLD) return true
  if (run.costUsd > 0.10) return true
  if (run.steps > 5) return true
  return Math.random() < 0.02                          // 2% baseline for the boring ones
}

Atlas keeps 100% of the interesting runs and 2% of the rest, which is 7.3% of traffic and about a fortieth of the storage of keeping everything. The baseline 2% matters: without it there is no normal to compare an anomaly against, and every trace in the store looks alarming.

Three dashboards

More than three and none of them get read.

// 1. Is it working? The on-call view, five panels.
const HEALTH = [
  'request rate and error rate',
  'latency p50 / p95 / p99',
  'terminated_by distribution',          // the regression tripwire
  'citation validation failures',
  'canary status',
]

// 2. What is it costing? Chapter 130's view.
const COST = [
  'spend per hour, against the ceiling',
  'cost per answer, p50 and p95',
  'tokens in / out, split by prompt, context and generation',
  'spend by intent — which question types are expensive',
]

// 3. What is it doing? The weekly review.
const BEHAVIOUR = [
  'intent mix over time',
  'refusal rate by reason',             // chapter 111
  'tool call frequency and failure rate',
  'steps per run, distribution not mean',
  'share of answers using memory recall',
]

// Distribution rather than mean, on every per-run count. A mean of 2.3
// steps hides a bimodal population of one-step lookups and nine-step
// investigations, and the thing that breaks is always the tail.

The derived metric worth emitting

// Most signals come free from the spans. One does not and is worth the
// code: the share of runs whose answer cited a chunk from outside the
// caller's usual groups. Chapter 125's incident ran for five days
// because nothing watched it.
const outOfProfile = citedChunks.filter((c) => !usualGroups.has(c.aclGroup)).length
span.setAttribute('agent.cited_out_of_profile', outOfProfile)

It is not a permission failure — the filter did its job and the access is legitimate. It is a change in pattern, which is what an ACL misconfiguration looks like from the outside, and it is the one security signal that lives naturally in telemetry rather than in the audit log.

Connecting the three artifacts

// One id, carried everywhere, so a dashboard anomaly reaches the trace
// and the trace reaches the audit record.
const runId = crypto.randomUUID()
// telemetry span attribute, audit row primary key, trace filename, and
// returned to the user in the interface footer so a complaint arrives
// with it already attached.

The last clause is the cheapest operational improvement in the chapter. A user reporting "this answer is wrong" with a run id turns a twenty-minute search into a lookup, and chapter 129 depends on having it.

Key points

Three artifacts, not one: a human-readable trace, an immutable audit record, and aggregate telemetry. One cannot do all three.
Make tool calls children of the step that made them, and give validation its own span.
Carry user_group rather than user_id in telemetry. Backends are widely readable and inconsistently retained.
terminated_by is the highest-value attribute: a shift in its distribution is the earliest signal of a control-flow regression.
Never put question text, chunk content, answers, tool arguments or memory statements in telemetry. Record the field names present, not the values.
Tail-sample. Keep every error, non-natural termination, refusal, flagged, slow, expensive or long run, plus 2% of the rest — 7.3% of traffic at a fortieth of the storage.
Keep the 2% baseline. Without a normal, every retained trace looks alarming.
Build three dashboards: is it working, what is it costing, what is it doing. Plot distributions, never means, for per-run counts.
Emit the share of answers citing outside the caller's usual groups. It is a pattern change, not a permission failure, and it is what an ACL misconfiguration looks like from outside.
Carry one run id through all three artifacts and show it to the user, so a complaint arrives with it attached.

Next: debugging a bad answer after the fact — using all three.