One traced request shows where the framework acts for you

A framework-backed agent spends most of a request outside the code you wrote. The runtime is executing nodes, writing state, deciding whether to re-run something, opening and closing spans, and calling your tools, and none of that appears in your application log for the ordinary reason that none of it happens in your application. Your log records the moments your own functions chose to record. Everything between those moments is invisible by default, and "invisible by default" is a fine condition right up to the first time the two accounts disagree.

The disagreement that makes this concrete is a duplicate side effect: a payment provider holding two charges for one customer action while the handler that issues charges logged exactly one call. Both records are correct. Reconciling them requires a third account of the run, produced by whatever sat between the runtime and the network, and that account has to be arranged before the trouble rather than during it. What follows is how to produce it, how to read it, and what it can and cannot settle once you have it.

Turn it on before you need it#

Most of these runtimes ship a tracing integration that is two environment variables away, and it is worth enabling even if you also export OpenTelemetry, the vendor-neutral standard for emitting spans that every serious observability backend accepts, because the built-in one knows things about the internals that a generic exporter does not. The generic exporter is still the one that will save you, since it is the only way the agent's spans end up in the same trace as the HTTP calls your tools make. The setup that matters is short.

from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor
from opentelemetry.exporter.otlp.proto.http.trace_exporter import OTLPSpanExporter
from opentelemetry.instrumentation.requests import RequestsInstrumentor

provider = TracerProvider()
provider.add_span_processor(BatchSpanProcessor(OTLPSpanExporter()))
trace.set_tracer_provider(provider)
RequestsInstrumentor().instrument()   # every outbound HTTP call becomes a child span

tracer = trace.get_tracer("billing-agent")


class SpanCallback(BaseCallbackHandler):
    """One span per node entry, one per model call, one per tool call."""

    def on_chain_start(self, serialized, inputs, *, run_id, parent_run_id=None, **kw):
        span = tracer.start_span(f"node:{serialized.get('name', 'chain')}")
        span.set_attribute("agent.thread_id", self.thread_id)
        span.set_attribute("agent.step", self.step)
        self._open[run_id] = span

    def on_tool_start(self, serialized, input_str, *, run_id, **kw):
        span = tracer.start_span(f"tool:{serialized['name']}")
        span.set_attribute("tool.args", input_str[:2000])
        self._open[run_id] = span

    def on_tool_end(self, output, *, run_id, **kw):
        span = self._open.pop(run_id)
        span.set_attribute("tool.result_bytes", len(str(output)))
        span.end()

RequestsInstrumentor is the line that does the disproportionate work. Without it you see that your tool ran; with it you see the HTTP request the tool made, its status code and its duration, nested inside the tool span.

Why that nesting is worth a line of setup takes one more step to see. Counting executions of your function and counting requests the provider received are two different measurements over two different populations, and a system where they always agree is a system where retries only ever happen inside your own code. Once a client library, a sidecar or a runtime can replay a request, the two counts come apart, and the only way to notice is to have both of them. That is what the instrumented HTTP client buys: a per-attempt record on the wire side, sitting under a per-invocation record on the function side, in one tree where the discrepancy is a difference in child count rather than an argument in a meeting.

The other half of instrumentation is the checkpointer, which most runtimes do not trace by default because writing state is considered internal. Wrapping it is a dozen lines and it is worth it, because checkpoint writes are the clock of the run: they tell you which steps the runtime believes completed, and a resumed run is only explicable if you can see which checkpoint it resumed from.

class TracedSaver(PostgresSaver):
    def put(self, config, checkpoint, metadata, new_versions):
        with tracer.start_as_current_span("checkpoint.put") as span:
            span.set_attribute("agent.thread_id", config["configurable"]["thread_id"])
            span.set_attribute("checkpoint.step", metadata.get("step", -1))
            result = super().put(config, checkpoint, metadata, new_versions)
            span.set_attribute("checkpoint.bytes", self._last_write_size)
            return result

Note which half of the checkpointer that wraps. put is the write; the matching read is not wrapped here, and the consequence shows up later in the trace as time the runtime spent that no span claims. Wrapping only the interesting method is a reasonable place to start and a thing to remember when the durations stop adding up.

One step, in the order the runtime performs it#

With those spans in place, a single step of the agent has a shape you can hold in your head, and the shape explains why so much happens outside your handler. The runtime reads state, opens a span, runs your node, your node calls a tool, the tool makes an HTTP request, and only after your node returns does the state get written.

Two properties of that ordering carry most of the operational consequences. The checkpoint is written after the node returns, which means a node that performs an effect and then crashes has performed the effect without recording that it did — the state store still says step 5, and a resume will run the node again. And the retry decision, wherever it lives, sits between the runtime and your node, so a re-run of the node is invisible to the node itself: your function is simply called a second time with the same arguments, in the same process, with no parameter that tells it which attempt this is.

Follow the first of those to its conclusion, because it is a design decision rather than a law and it is worth knowing which. The runtime could write the checkpoint before running the node instead. It does not, and the reason is that a checkpoint written before a step claims the step succeeded before anybody knows whether it did, so a crash would leave a run that skips work it never performed. Writing afterwards makes the opposite error instead: work that happened is not recorded, and the resume repeats it. Between losing work and repeating work, a general-purpose runtime picks repeating, because repeating is recoverable by the caller and losing is not. That choice is correct and it is also the whole source of duplicate effects, which is why the fix lives in your tools rather than in a setting.

The second property is what makes the duplicate hard to see rather than hard to cause. Your function receives the same arguments on attempt two that it received on attempt one. Nothing in its signature, its arguments or its process differs. A function cannot detect a condition it is given no information about, so no amount of care inside the handler will produce a handler that knows it is a repeat. That is why the naive mental model — one logical tool call equals one execution equals one log line — is wrong on a framework, and it is the mechanical reason a duplicated charge can leave a single log line: the handler logs once per return, and only one attempt returned.

Two decisions about telemetry volume are worth making at the same time as the instrumentation, since both get made badly under pressure later. Tool arguments and results are the highest-value attributes and also the ones most likely to contain personal data or to be 400 KB long, so truncating at a couple of kilobytes and redacting known-sensitive fields at the span layer is the version that survives a privacy review. Sampling is the other: head-based sampling, where the decision to keep or drop a trace is taken at the first span and before anything interesting has happened, at 10% will throw away the trace you need, because the interesting runs are rare by construction, so tail-based sampling that keeps every trace containing an error span, every trace above a latency threshold, and a small fraction of the rest keeps the storage bill bounded while retaining the ones an investigation is about.

Reading an unattributed interval#

Here is the trace for run_9f21c0 after instrumentation was added, reconstructed on the next occurrence of the same failure. Durations are wall-clock, and the tree is the whole run.

trace 4f9c1d2e…   thread_id=run_9f21c0                 total 52.4s
└─ graph.invoke                                             52.4s
   ├─ node:model              step 4                         2.1s   in=6412 out=118
   ├─ checkpoint.put          step 4                        31ms    bytes=41208
   ├─ node:tools              step 5                        45.4s   ← 31.0s unattributed
   │  └─ tool:charge_subscription                           14.4s   charge=ch_3Qa1RwB
   │     └─ POST api.stripe.com/v1/charges                  14.3s   201
   ├─ checkpoint.put          step 5                        28ms    bytes=44902
   └─ node:model              step 6                         1.9s   in=7104 out=64

The arithmetic that produces the arrow is one subtraction, and it is the only technique in this chapter. A parent span covers an interval; its children cover sub-intervals of it; subtract the children from the parent and what is left is time the parent spent doing something nobody instrumented. The node:tools span is 45.4 seconds and its only child is 14.4 seconds, so thirty-one seconds inside that node produced no child span at all — 31.0 of them, at the precision the tree reports. The payment provider's records place ch_3Qa1RtK at 14:22:07, which falls inside that hole. Something ran the charge, waited, gave up, and ran it again, and it did so at a level where no instrumentation existed — either above the tool span, in the runtime's own retry machinery, or below it, in a client that never returned a response for the first attempt.

The same subtraction applied to the root of that tree finds a second and much smaller residual, and it is worth doing because it demonstrates the limit of the method rather than a second fault. The five children of graph.invoke do not add up to graph.invoke, and the missing seconds are the runtime's own work between nodes: reading the previous checkpoint, merging a node's output into state, choosing the next edge. The wrapper written earlier in this chapter traced put and left the matching read alone, so the read has no span by construction. A residual is therefore evidence of uninstrumented work and not, on its own, evidence of a retry. What makes the 31.0-second one an incident is its size and the fact that a charge exists inside it.

That is what converts an unfalsifiable statement into a measurable one. "Something retried" becomes "31.0 seconds elapsed between the node opening and the tool span starting, and a charge exists in that window", and the second version constrains what can have happened. A 30-second gap followed by a successful attempt is the signature of a client timeout configured at 30 seconds; a gap of 0.5 or 1.5 seconds is the signature of a backoff schedule; a gap measured in minutes is the signature of a queue redelivery. The reasoning runs from a configured constant to an observed duration and back: a layer whose timeout is set to some value will produce gaps of about that value when it fires, so an observed gap is a fingerprint of the layers whose constants match it. The number is evidence about which layer, and it is only available because the parent span existed.

The other thing the trace gives you is the checkpoint sequence, which rules out an entire family of explanations. There is one checkpoint.put for step 5, written once, at the end. The run did not resume from an earlier checkpoint, so this was not a recovery replaying a completed step — a genuinely different failure mode, which would have shown two graph.invoke spans in two traces sharing a thread_id, with a checkpoint.get returning step 4 in the second one. Distinguishing "retried within one invocation" from "the whole invocation ran twice" takes about four seconds when the checkpoint writes are spans and is close to impossible when they are not.

Why the guard in the handler cannot work#

The first fix everybody proposes is a guard: keep a set of what has already been charged in this run, and skip if it is there.

_charged: set[str] = set()          # module-level, per process

def charge_subscription(customer_id: str, amount_cents: int) -> str:
    key = f"{customer_id}:{amount_cents}"
    if key in _charged:
        return json.dumps({"status": "already_charged"})
    receipt = payments.charge(customer_id=customer_id, amount_cents=amount_cents)
    _charged.add(key)
    return json.dumps({"charge_id": receipt.id})

This does not hold, for reasons the trace makes plain, and it is worth taking them one at a time because each of the three is a separate defect and each survives fixing the other two. The set is only populated after payments.charge returns, and the first attempt never returned — it timed out with the charge already created on the provider's side, so the guard's own bookkeeping never learned about it. Even if the ordering were fixed, the state is in one process's memory, and a retry driven by a queue redelivery or by a resume after a deploy runs in a different process with an empty set.

The third defect is the one worth dwelling on, because it is the shape of mistake this whole class of problem is made of. The guard's key is customer:amount, which is a guess at what constitutes "the same charge", and that string is a quantity that stays fixed across exactly the variation the guard needs to detect. A duplicate of one charge and a legitimate second upgrade of the same amount on the same day produce identical keys, so the guard cannot separate them, and it does not fail loudly — it suppresses the second one either way. A defence built on a value that does not vary with the dangerous property is not a weak defence; it is a coin flip wearing a conditional. The guard suppresses the symptom in the one arrangement where the duplication was already visible, and does nothing in the arrangements where it is not.

The correct altitude is the outbound call itself. Payment APIs, and most APIs that create things, accept an idempotency key: a caller-supplied string that the provider stores alongside the result, so that a second request carrying the same key returns the first request's response instead of creating a second charge. That moves deduplication to the only participant that can see both attempts, which is the provider.

def charge_subscription(customer_id: str, amount_cents: int, *, idem_key: str) -> str:
    receipt = payments.charge(
        customer_id=customer_id,
        amount_cents=amount_cents,
        idempotency_key=idem_key,        # provider returns ch_3Qa1RtK on the retry
    )
    return json.dumps({"charge_id": receipt.id, "idempotency_key": idem_key})

The keyword-only idem_key is deliberate: it makes the key an input to the tool rather than something the tool invents, and the difference between those two is the whole problem. A key generated inside the function with uuid4() is regenerated on every attempt, so the two attempts carry different keys and the provider creates two charges, which is precisely the behaviour the guard was meant to prevent, now wearing a header.

State the requirement on the key as a property and it becomes checkable. The key has to be a deterministic function of something that is identical across the duplicate and different across genuinely distinct charges. Both halves are load-bearing. A key that is too stable — a constant, or a hash of the customer alone — collapses distinct charges into one and silently drops a legitimate payment. A key that is too fresh — anything generated at call time — separates attempts that were meant to be the same. The customer:amount guard failed the first half; uuid4() fails the second; and every candidate source of a key can be judged against those two conditions before a line of it is written.

A trace is not an audit log#

Spans are sampled, they expire — seven to thirty days on most backends — and they are stored by a system whose failure is not your failure, which makes them unsuitable as the record of whether a customer was charged. The durable record of effects belongs in your own database with the same retention as the money it describes. Tracing tells you what happened during an investigation; it does not tell you what happened during a reconciliation four months later, and conflating the two is how teams end up unable to answer a finance question at all.

Streaming complicates the picture in a way worth anticipating rather than discovering. When the model streams, the node's span stays open while tokens arrive, and a tool call is only fully formed once its argument JSON has finished streaming, which means the interval between "the model started emitting a tool call" and "the tool actually ran" can be several hundred milliseconds of span with nothing in it. That is a residual of the same shape as the one this chapter reads as evidence, produced by an entirely innocent mechanism, so the subtraction alone does not separate them. Recording the time to first token and the time to a complete tool-call block as separate span events costs two lines and removes an entire category of misreading, because otherwise a slow stream and a slow tool look the same from the outside.

The deeper limit is that a trace records what happened and not who decided it. The window is measured, the layers that could have produced a window that size are enumerable, and the trace does not say which one acted. Narrowing it further needs evidence from outside your process, and the same gap that a timeout produces above the tool can be produced by a retry inside a client below it — two different layers, one indistinguishable duration.

Naming that layer is where the work goes next, and it matters because the key derived above needs a source. If the runtime re-ran the node, the thing both attempts share is the checkpoint the node started from. If the HTTP client retried, both attempts share the request the tool built. If a queue redelivered the message, both share the message id. If the model emitted the tool call twice after a timeout, they share almost nothing, because the second one is a genuinely new decision.

Each of those candidates implies a different source for the key, and picking wrong produces a key that varies exactly when it needed to be stable — the failure mode the last section defined, arrived at by a careful route. The trace has narrowed the field to a thirty-one-second window and to a short list of mechanisms whose configured constants are consistent with it. What it has not done is name one, and the layers that could have acted leave different marks in places other than the trace.