Observability for Non-Deterministic Systems
Tracing a request through prompts, tools and retries; logging enough to reproduce a bad answer without logging things you should not keep; and watching cost and latency as first-class signals.
Tracing a request through prompts, tools and retries; logging enough to reproduce a bad answer without logging things you should not keep; and watching cost and latency as first-class signals.
A ticket lands at 11:40. "An hour ago your assistant told me our
plan includes phone support. It does not." You open the feature,
paste the same question in, and get a correct answer three times
running. The customer is not making it up. Your logs have one
line about it: POST /answer 200 1.9s.
That run is gone unless it recorded itself while it was happening — and unlike the rest of your stack, you cannot get it back by replaying the input. By the end of this lesson you will know what a trace has to contain to be worth having, why the field everyone omits is the one you need at 11:40, how to keep all of it without keeping things you should not, and what to alert on in a system that fails politely and never raises an exception.
In ordinary software, reproduction is close to free. Same input, same code, same output — so a stack trace and a request body are usually enough to get the bug back on your machine. Two things break that here, and they compound.
Same prompt, different answer.
The model draws from a distribution. Even at the most deterministic settings there is no cross-run guarantee — provider-side batching, hardware, and a floating model alias quietly pointing at a new version all sit outside your process.
You cannot even send the same prompt.
The index was rebuilt overnight. The summary was written from turns you have since trimmed. A tool returned a subscription record that has changed. Someone edited the template at 09:15.
You are not rerunning the request. You are running a different one that happens to share the user's sentence.
So the run has to record itself. A trace is the record of one request as it actually ran: every step, its real inputs, its real outputs, and its timing, written at the moment it happened. A span is one step inside that trace — the retrieval, one tool call, one model call. The trace is not a prettier log line; the difference is that it is organised around a single request's causal chain rather than around whatever each component felt like printing.
A trace that records "called the model, got a response, took 1.9 seconds" tells you nothing you did not already know. The test for every field is the same: an hour later, with the customer waiting, does this let you say why that answer came out? Here is a support-answer feature recording the fields that pass.
def answer_question(question: str, request_id: str) -> Answer:
with tracer.span("answer_question", request_id=request_id,
feature="support_answer") as run:
chunks = index.search(question, limit=6)
run.set(
retrieval_query=question,
chunk_ids=[chunk.id for chunk in chunks],
chunk_scores=[round(chunk.score, 3) for chunk in chunks],
index_version=index.version,
)
messages = build_prompt(question, chunks)
run.set(
prompt_template="support_answer.v7",
messages=redact(messages),
model=settings.model_id,
sampling=settings.sampling_params,
)
started = time.monotonic()
response = provider.complete(messages, **settings.as_kwargs())
run.set(
raw_response=response.text,
stop_reason=response.stop_reason,
input_tokens=response.usage.input_tokens,
output_tokens=response.usage.output_tokens,
cached_tokens=response.usage.cached_input_tokens,
model_latency_ms=int((time.monotonic() - started) * 1000),
)
return parse_answer(response.text, run)Read the list rather than the code. The assembled prompt as actually sent, with the template name and its version, because "the prompt" changed three times this month. The retrieved chunk ids and their scores, plus the index version — ids rather than text, so a chunk that has since been reworded cannot pretend it always said what it says now. Every tool call with its arguments, result and duration. The raw response before anything touches it. The model id and sampling parameters you sent. Token counts, split into input, output and cached. Latency per step, not one total. And a request id that is the same string your web server and your error tracker already use.
This is the field people leave out and then need, every time. The pull to omit it is real: you have a nice typed object at the end of the pipeline, the raw text is long, and logging both feels like storing the same thing twice.
Bad — the record describes what survived parsing, so a bad answer that parsed cleanly leaves no evidence at all.
answer = parse_answer(response.text)
run.set(answer=answer.text, citations=answer.citations)Good — the model's own bytes are recorded first, and the parse becomes another recorded step.
run.set(raw_response=response.text)
try:
answer = parse_answer(response.text)
run.set(parse_ok=True, citations=answer.citations)
except ParseError as error:
run.set(parse_ok=False, parse_error=str(error))
raiseThe two failures the first version cannot explain are the two you actually get. When parsing throws, you have an exception about a missing key and no idea what the model wrote instead. And when parsing succeeds on a wrong answer — the 11:40 case — you cannot tell whether the model invented phone support or whether your own post-processing dropped the hedge, rewrote a field, or picked the wrong branch. Storing the raw text is the difference between a bug you fix and a bug you argue about.
Record the stop reason in the same breath. An answer that ends mid-sentence because it hit the output limit looks, in a parsed object, exactly like an answer that ended because the model was finished.
A trace store that only your AI feature writes to is an island. The value arrives when the id in the trace is the same id in the access log, the database slow-query log, the error tracker and the support ticket.
Take the request id from the edge — generate it in middleware if the client did not send one, put it in a context variable, and attach it to every span and every ordinary log line for the duration. Then return it to the caller. A response header, or a small grey string under the answer in the UI, means the customer who complains can hand you the run instead of a paraphrase of it. That one habit converts "an hour ago it said something wrong" into a primary key.
Traces are expensive to keep at full fidelity, so sample honestly: keep every run that errored, every run that fell back, every run a user flagged, and a fixed slice of the rest. Sampling that drops failures gives you a store where everything looks fine. And when feedback arrives — a thumbs-down, a ticket, a correction — write it back onto the trace by request id. Those flagged runs are the raw material for your golden set, which the lesson on evaluating an AI feature takes properly; here you are only making sure the evidence survives to be used.
Look at what you have built. Every customer question, verbatim. Whole documents out of your knowledge base. Tool results holding account records. This store is more sensitive than the database it was assembled from, because the database has row-level access control and this is a pile of text in a log platform your whole engineering team can search.
Treat redaction as part of the emit path, not as something the log platform does later.
Bad — the unmodified prompt leaves the process, and a downstream scrubber is expected to catch what matters.
run.set(messages=json.dumps(messages))Good — the same field, put through a redactor before it is ever written.
run.set(messages=redact(messages)) # emails, card numbers, idsBy the time a downstream scrubber sees the text, the raw version has already crossed the network, landed on disk and been copied into a backup and probably a search index. Scrubbers match patterns, so they catch the card number and miss the free-text paragraph where the customer explained their medical situation. And when a deletion request arrives you have to find one person's data inside an opaque blob, where structured redacted fields could have been queried and removed.
The other two controls belong in the design rather than in a cleanup ticket. Retention in tiers: full traces live days to weeks, the window in which anyone actually debugs one, while the aggregates — rates, costs, latencies — are small and can live for years. Access control: reading a trace means reading a customer's document, so it needs a named permission and an audit trail, exactly as a database export would.
In most systems cost is a monthly finance problem and latency is one number on a dashboard. Neither survives contact with a feature whose per-request cost varies by a factor of fifty depending on how much context it assembled.
Attribute every model call to a feature and a tenant at emit time, then compute the cost in the same span from the token counts and the rate you were charged. A number calculated at write time is evidence; one derived months later from a price list that has changed since is a guess. Keep cached input tokens separate from fresh ones, because a change in that ratio is the earliest sign that something upstream started busting the cache.
Latency needs the same treatment, broken out per span. A total of 1.9 seconds tells you nothing about whether to work on retrieval, on the prompt size, on a slow tool, or on your own schema-repair loop. Teams routinely spend a sprint shaving the model call when a third of the wall clock was one internal service the trace would have named immediately.
Measuring is where this lesson stops. Making the numbers smaller — caching, routing, batching, trimming context that earns nothing — is the whole subject of the next lesson, and doing any of it before you can measure per feature is how teams optimise the cheap path and leave the expensive one alone.
Here is the uncomfortable part. Your usual alerts watch for things that throw: 5xx rates, exception counts, failed jobs. An AI feature's worst days produce none of those. It returns 200 with a polite refusal, or a confident wrong answer, or a truncated one, at whatever rate the change you shipped this morning caused.
Bad — pages when the provider call raises, which is the failure you were already handling.
if error_rate(feature="support_answer", window="5m") > 0.02:
page("support_answer failing")Good — pages on the silent outcomes, measured as a share of requests to that feature.
rates = span_rates(feature="support_answer", window="30m")
baseline = span_rates(feature="support_answer", window="7d")
for signal in ("refusal", "fallback", "truncation", "empty_retrieval"):
if rates[signal] > max(2 * baseline[signal], 0.05):
page(f"support_answer {signal} rate {rates[signal]:.0%}")A prompt edit that makes the model refuse a third of the time raises zero exceptions, keeps the latency graph flat, and stays invisible until the support queue notices three days later. The first version is green throughout. That gap — between "the system is up" and "the system is doing its job" — is the whole reason this lesson exists.
The signals worth watching count outcomes the system chose rather than errors it hit. Refusal rate: how often the model declined. Fallback rate: how often your second path carried the traffic — a fallback firing quietly is a degradation, not a success story. Truncation rate: stop reason at the output limit. Empty-retrieval rate: no chunk cleared the threshold, so the model answered from nothing. Repair rate: output failed validation on the first attempt. And cost per request, which catches the runaway loop and the prompt that doubled in size on one graph.
Alert on each as a ratio against a trailing baseline for that feature, never a fixed number. Fixed thresholds are wrong the day the traffic mix changes, and a refusal rate that is healthy for billing questions is alarming for document summaries. Keep the denominator honest too: per feature, and per model version if you run more than one, so a canary going bad is not diluted by the traffic that is fine.
RECORD PER RUN WHY YOU WILL WANT IT
request_id # joins trace to app + access logs
trace_id + span ids # the causal chain of one request
feature + tenant # how cost and latency get grouped
prompt_template@version # which text produced this answer
messages, redacted # the assembled prompt, as sent
retrieval query # what you actually searched for
chunk ids + scores # which chunks, and how confident
index version # which corpus answered
tool name + args + result # allow-listed fields only
raw_response # BEFORE parsing — the skipped one
parse_ok + parse_error # did your own code mangle it
stop_reason # finished, or hit the limit
model id, pinned # never a floating alias
sampling parameters # temperature, top_p, max tokens
tokens in / out / cached # the inputs to cost
cost, computed at write time # prices change; the number is proof
latency per span # retrieval vs model vs tools vs you
outcome + fallback fired # what the user was actually shown
feedback, joined later # by request_id, when it arrives
ALERT ON RATES, NOT ERRORS COMPARE TO A TRAILING BASELINE
refusal rate # the model declined to answer
fallback rate # the second path carried traffic
truncation rate # stop_reason was the output limit
empty retrieval rate # zero chunks cleared the threshold
repair rate # output failed validation first try
cost per request # p50 and p95, not the daily total
latency per request # p95 and p99, never the mean
HANDLING RULES
redact at emit # not in a downstream scrubber
allow-list tool fields # deny-lists miss the next secret
retain in tiers # traces for weeks, rollups for years
gate + audit access # a trace is a customer's document
sample honestly # all failures and flags, then a slice
return the request id # so a complaint names one runYou can now answer "it gave me something wrong an hour ago" with the actual run: the prompt as assembled, the chunks that fed it, the tools it called, the bytes it produced before your code touched them, and what it cost. Your alerts fire on a system quietly doing the wrong thing, not only on one that fell over.
Next comes Cost and Latency Engineering, which answers the question this lesson left alone: now that you can see where the money and the seconds go, how do you spend fewer of both — caching, routing to a cheaper model where it is good enough, batching, and streaming for perceived speed. All of it depends on the per-feature numbers you have started recording.
The thing to do today takes ten minutes. Take one real request through your own feature, then open your logs and try to fill in the cheat sheet from them. Every line you cannot answer is a question you will be asked during an incident, with someone waiting. Add the raw response first.