intermediate30 minby DevFox

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.

AI
DevOps

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.

Why a rerun is not a reproduction

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.

The output is sampled

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.

The input no longer exists

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.

The second one gets far less attention and is the larger problem

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.

What a trace has to contain to be worth having

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.

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.

The raw response, before you parse it

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.

Good — the model's own bytes are recorded first, and the parse becomes another recorded step.

The 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.

The id that ties it to everything else

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.

The trace is now your most sensitive store

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.

Good — the same field, put through a redactor before it is ever written.

By 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.

Cost and latency as first-class signals

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.

Alerting when there is no error rate

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.

Good — pages on the silent outcomes, measured as a share of requests to that feature.

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.

A cheat sheet to keep

Where to go next

You 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.