Why logs are not enough for agents

The email reached Meera at 8:10 on a Wednesday morning. Nandini Joshi had been ordering twelve fudge brownies for her son Aarav’s seventh birthday party. Aarav has a tree-nut allergy. On Tuesday evening she had asked CrumbBot, the support assistant on Crumb’s website, whether the fudge brownie was nut-free. CrumbBot said yes, cheerfully, with a little cake emoji.

Something made her phone the Baner store anyway. The store manager went quiet, then read the label aloud: Walnut Fudge Brownie. Contains tree nuts. Since August, every brownie Crumb sells has had chopped walnuts folded through it.

Nobody was hurt. Meera forwarded Nandini’s polite email to Arjun and Priya with one line: “How did this happen, and how do we know it won’t happen again?”

Arjun opened the server logs for Tuesday evening. He found the request in under a minute. It said this, and only this:

2026-10-27 19:42:07 INFO  POST /chat 200 3.2s

A 200 status code means “success”. The request took 3.2 seconds, well inside the team’s 5-second target. By every measure Arjun had, CrumbBot had done a perfect job of telling a mother her son’s birthday treat was safe when it was not.

Arjun’s first attempt: more print statements

Arjun’s instinct was reasonable. If the logs don’t say enough, make them say more. He opened support.py, the file behind the chat endpoint, and added logging around the answer.

import logging

logger = logging.getLogger("crumb.support")

def handle_message(session_id: str, text: str) -> str:
    query = rewrite_query(text)            # Module 09: tidy the question for search
    chunks = retrieve(query, k=4)          # Module 09: top 4 chunks from Chroma
    answer = generate_answer(text, chunks) # one Claude call
    logger.info("answer=%s", answer)       # NEW: log what we said
    return answer

He typed Nandini’s question into the test widget three times. The log now said:

19:58:11 INFO  answer=Yes! Our fudge brownie is nut-free and baked on our nut-free line.
19:58:11 INFO  POST /chat 200 3.4s
19:58:15 INFO  answer=I'm not completely sure. Please check with the store before ordering.
19:58:15 INFO  POST /chat 200 2.9s
19:58:19 INFO  answer=Yes, the fudge brownie contains no nuts. Enjoy the party!
19:58:19 INFO  POST /chat 200 3.1s

“Great,” he said. “Now I can see it’s wrong. Two out of three times.”

Priya was reading over his shoulder. “You could already see it was wrong. Nandini told you. What you need to see is why.”

He added more lines: one after the query rewrite, one listing the chunk ids, one with the token count. Then he looked at production, where about 600 conversations a day flow through CrumbBot, around 40 a minute at the evening peak. His new lines from different customers landed on top of each other:

19:58:40 INFO  query=fudge brownie nut-free tree nut allergy
19:58:40 INFO  query=order CR-58213 delivery status
19:58:41 INFO  chunks=['faq-delivery-02', 'policy-late-01', ...]
19:58:41 INFO  chunks=['recipe-2025-brownie-02', 'faq-allergy-01', ...]
19:58:43 INFO  answer=Your order is out for delivery and should arrive by 8:30 pm.

Which chunk list belonged to which question? Here he could guess. At 40 requests a minute he could not. And even a right guess would not show how long each step took or what the model was actually sent.

“I’m drowning in lines,” he said. “And I still can’t see the one request.”

A receipt versus a parcel timeline

Priya pulled up two things on her phone. The first was a supermarket receipt she had photographed: date, total, “PAID”.

“This is your log line,” she said. “It proves a transaction happened. If the bill was wrong, can the receipt tell you which cashier scanned which item twice?”

“No.”

The second was the tracking page for a parcel she had ordered from Bengaluru. Picked up 10:02. Arrived Hubballi hub 18:40. Delayed: sorting backlog, 6 h 15 m. Out for delivery 09:12. Delivered 13:55.

“This is a trace. Same parcel, every stop, with times. When it arrived a day late, which stop would you blame?”

“Hubballi. Six hours in sorting.”

“You didn’t need to guess. The timeline shows you.” She put the phone down. “An airline has the same idea with a flight’s black box. After an incident, investigators don’t ask the pilot to remember. They replay what the plane recorded.”

“So I need a black box for every chat.”

“For every request. And here’s where my analogy breaks: a parcel follows one fixed route. Your chat request does not. The same question can take a different path every time, because the model at the start rewrites it differently. Your three test runs today probably took three different paths. Without a recording of each one, you can’t tell which path went wrong.”

Rebuilding one request by hand

Nothing about Tuesday’s request had been recorded except the 200. So Priya and Arjun spent the afternoon rebuilding it. They had Nandini’s message from the chat database. They re-ran each step with that exact message, many times, until the final answer matched what she received word for word. This is the chain they ended up with. Keep it in mind: it is the shape every trace in this module will have.

The input. Session sess-7f3a, customer cust-4412, 19:42:04:

“Hi! Is your fudge brownie nut-free? My son Aarav has a tree-nut allergy and I want 12 for his birthday on Saturday.”

Step 1: rewrite the query (412 ms). The pipeline from Module 09 asks Claude to turn the chatty message into a short search query. That call read 180 input tokens and wrote 14 output tokens. A token is the word-piece a model reads and bills by, about 1.3 per English word. The output: fudge brownie nut-free tree nut allergy.

Step 2: retrieve (101 ms). The query is turned into an embedding (a list of numbers that captures meaning, Module 07) in 41 ms, and the vector database finds the four closest chunks in 60 ms. A chunk is a short slice of a document, stored with its own embedding (Module 09). The scores run from 0 to 1; higher means “closer in meaning”.

Arjun read the table twice. “Rank one is last year’s recipe card. And rank four is a blog post from last year saying the brownie has no nuts. Where’s the current allergen table?”

“Not in the top four,” Priya said. “We’ll find out where it went later. For now, notice what the model received.”

Step 3: build the prompt (2 ms). The system prompt, the four chunks and the message are stitched together: 1,912 input tokens.

Step 4: generate the answer (2,651 ms). One call to claude-opus-5-5. It read 1,912 tokens and wrote 96. The answer: “Yes! Our fudge brownie is nut-free and baked on our nut-free line, so it’s a safe choice for Aarav’s party.”

The total. 412 + 101 + 2 + 2,651 = 3,166 ms, plus about 45 ms of web framework overhead: the 3.2 seconds in the log line.

The cost. At the time of writing, claude-opus-5-5 costs $4permillioninputtokensand$20 per million output tokens.

(Using roughly ₹88 to the dollar; the rate moves.) Ninety-three paise to tell a customer something dangerous.

“So the model didn’t make it up,” Arjun said slowly. “It did what Module 09 told it to. Answer only from the context. The context was wrong.”

“The model was faithful. The retrieval failed. And notice how long that took us: a whole afternoon, re-running a non-deterministic system and hoping we matched what really happened. We’re fairly sure. We can’t prove it.”

Logs, metrics and traces

Priya drew three columns on the whiteboard. Engineers call these the three pillars of observability: the ability to answer questions about what your system did, including questions you didn’t think of in advance, from the data it already records.

Logs are individual events with a timestamp. “POST /chat 200 3.2s.” “Payment failed for order CR-58213.” They are cheap and easy to write, and they are good at saying that something happened.

Metrics are numbers measured over time. Requests per minute, error rate, the 95th-percentile latency (the time that 95 out of 100 requests beat). They are tiny to store and perfect for dashboards and alerts. On Tuesday, Crumb’s dashboard showed 612 chats, a 0% error rate and a p95 latency of 4.1 s. Every light was green.

Traces record the causal path of one request: what called what, in what order, how long each piece took, and what went in and out. They are the only pillar that can answer “why did this request do that?”

A trace is made of spans. A span is one timed unit of work. Every span has:

• a name, like retrieve or generate_answer;
• a start and end time, so you know its duration;
• a parent, the span that started it (the first span, the root, has no parent);
• attributes, key-value facts about the work, like top_k=4 or input_tokens=1912;
• a status, OK or error.

Parent and child links turn a flat list of spans into a tree. Here is Tuesday’s request drawn as one.

flowchart TD
  A["handle_message (3.21 s)"] --> B["rewrite_query (0.41 s, 180 in / 14 out tokens)"]
  A --> C["retrieve (0.10 s, top_k 4)"]
  C --> C1["embed_query (0.04 s)"]
  C --> C2["vector_search (0.06 s)"]
  A --> D["build_prompt (1,912 tokens)"]
  A --> E["generate_answer (2.65 s, 1,912 in / 96 out tokens)"]

One more word. Nandini did not send one message. She sent three: the brownie question, then “Great, can I pick them up from Baner on Saturday morning?”, then “Thank you!”. Each message is its own request, so its own trace. A session groups the traces from one conversation, so you can read it the way the customer experienced it. CrumbBot’s session_id is that group’s name.

“Why not put everything in one big trace per conversation?” Arjun asked.

“Because a conversation can last two days, and a trace should describe one unit of work with a clear start and end. Sessions give you both views.”

Opening the hood: a tracer in forty lines

Tools like Langfuse and OpenTelemetry, which you will meet in the next two lessons, can feel like magic. They aren’t. Priya had Arjun write a toy tracer from scratch so he would know what they do underneath. It needs nothing beyond Python 3.12.

The one tricky part is knowing the parent. When retrieve starts, how does it know it is inside handle_message? The answer is a context variable: a value Python keeps per request, even when many requests run at once, which here stores “the span we are currently inside”.

# minitrace.py: a toy tracer, to see what real tracing tools do underneath.
import time
import uuid
from contextlib import contextmanager
from contextvars import ContextVar

_current = ContextVar("current_span", default=None)  # the span we are inside now
SPANS: list[dict] = []                               # every finished span

@contextmanager
def span(name: str, **attributes):
    parent = _current.get()
    record = {
        # Children share the parent's trace id; a root span starts a new trace.
        "trace_id": parent["trace_id"] if parent else uuid.uuid4().hex[:8],
        "span_id": uuid.uuid4().hex[:8],
        "parent_id": parent["span_id"] if parent else None,
        "name": name,
        "attributes": dict(attributes),
        "status": "OK",
        "start": time.perf_counter(),
    }
    token = _current.set(record)        # "we are now inside this span"
    try:
        yield record                    # run the code inside the with-block
    except Exception as exc:
        record["status"] = f"ERROR {exc!r}"
        raise
    finally:
        record["ms"] = round((time.perf_counter() - record["start"]) * 1000)
        _current.reset(token)           # back to the parent
        SPANS.append(record)

def print_tree(trace_id: str, parent_id=None, depth: int = 0) -> None:
    children = [s for s in SPANS if s["trace_id"] == trace_id and s["parent_id"] == parent_id]
    for s in sorted(children, key=lambda s: s["start"]):
        print(f"{'  ' * depth}{s['name']:<{24 - 2 * depth}} {s['ms']:>5} ms  {s['status']}  {s['attributes']}")
        print_tree(trace_id, s["span_id"], depth + 1)

@contextmanager lets you write with span("retrieve"): around any block. When the block starts, the new span reads its parent from the context variable and makes itself current. When the block ends, even with an error, it records its duration, restores the parent and stores itself. That is the whole trick. Real tracers add shipping spans somewhere safe, sampling and a user interface.

Now wrap the pipeline. To keep this runnable without API keys, the steps below sleep for the real durations and return the real values from Tuesday’s request. In Lesson 4 you will wrap the real calls.

# fake_pipeline.py: Tuesday's request, replayed with the toy tracer.
import time
from minitrace import span, print_tree

def rewrite_query(text: str) -> str:
    with span("rewrite_query", model="claude-opus-5-5", input_tokens=180, output_tokens=14):
        time.sleep(0.41)
        return "fudge brownie nut-free tree nut allergy"

def retrieve(query: str, k: int = 4) -> list[tuple[str, float]]:
    with span("retrieve", query=query, top_k=k) as s:
        with span("embed_query"):
            time.sleep(0.04)
        with span("vector_search"):
            time.sleep(0.06)
        hits = [("recipe-2025-brownie-02", 0.86), ("faq-allergy-01", 0.79),
                ("recipe-2025-brownie-05", 0.77), ("blog-2025-08-brownie", 0.74)]
        s["attributes"]["chunks"] = hits      # record what we found, with scores
        return hits

def generate_answer(text: str, hits) -> str:
    with span("generate_answer", model="claude-opus-5-5", input_tokens=1912, output_tokens=96):
        time.sleep(2.65)
        return "Yes! Our fudge brownie is nut-free..."

def handle_message(session_id: str, text: str) -> str:
    with span("handle_message", session_id=session_id) as root:
        hits = retrieve(rewrite_query(text))
        generate_answer(text, hits)
        return root["trace_id"]

trace_id = handle_message("sess-7f3a", "Is your fudge brownie nut-free?")
print_tree(trace_id)

Run it with uv run fake_pipeline.py. Your milliseconds will differ by a few:

handle_message            3168 ms  OK  {'session_id': 'sess-7f3a'}
  rewrite_query            411 ms  OK  {'model': 'claude-opus-5-5', 'input_tokens': 180, 'output_tokens': 14}
  retrieve                 101 ms  OK  {'query': 'fudge brownie nut-free tree nut allergy', 'top_k': 4, 'chunks': [('recipe-2025-brownie-02', 0.86), ...]}
    embed_query             41 ms  OK  {}
    vector_search           60 ms  OK  {}
  generate_answer         2651 ms  OK  {'model': 'claude-opus-5-5', 'input_tokens': 1912, 'output_tokens': 96}

Compare that with POST /chat 200 3.2s. Same request. One tells you it finished. The other tells you it searched for “fudge brownie nut-free tree nut allergy”, got last year’s recipe card at the top with a score of 0.86, and spent 84% of its time waiting for the model.

Why AI apps need this more than ordinary apps

Why was CrumbBot different from the order service Arjun had run for two years on logs and metrics? Priya listed four reasons.

They are non-deterministic. The same input can produce different outputs. Your order service, given order CR-58213, always returns the same status. CrumbBot, given Nandini’s message, said “nut-free” two times out of three. You cannot reproduce a bug reliably later, so you must record it when it happens.

Their failures are soft. A crash raises an exception, turns a metric red and pages someone. A wrong answer returns 200 OK in 3.2 seconds with perfect grammar. The brownie answer was a soft failure: technically successful, actually harmful. Logs and metrics are built to catch hard failures. Only by looking at what went in and what came out can you see a soft one.

They take many steps. Even this simple pipeline has a rewrite, an embedding, a search, a prompt and a model call. An agent (Module 13) loops: the model asks for a tool, your code runs it, the model reads the result and decides again, perhaps five times. Each step can go wrong in ways that only show up in the final answer. The tree shows you which step.

Cost and speed live per step. In Module 21 you cut costs with caching. To know whether that worked for this request, you need tokens and latency per call, not per day.

So for AI apps, a useful trace captures more than a classic one:

Where tracing itself breaks

Tracing is not free, and it creates new risks. Experienced engineers watch three things.

Privacy. Look at Nandini’s message again. A child’s first name, his age, his allergy, a pickup store and a day. Other messages carry phone numbers and home addresses. A trace that records full inputs and outputs is a copy of all of that, in a second system, possibly at a second company.

Volume and cost. A full CrumbBot trace is roughly 10 to 15 KB. At about 1,800 requests a day that is 20 to 30 MB: fine. At a million requests a day, storage becomes a real bill, and teams sample: keep perhaps 10% of traces, plus every error and thumbs down. Lesson 4 shows how.

Slowing the app down. Sending every span over the network before replying would delay every chat, so real tools buffer spans and send them in the background. If your process exits first, those spans are lost. You will meet flush() in Lesson 2.

Try it yourself

Extend the toy tracer so it can explain a failure.

1. In fake_pipeline.py, change rewrite_query to return text.lower() instead of the fixed brownie query. Then make retrieve raise TimeoutError("vector db slow") when the query contains the word “plum”.
2. Call handle_message("sess-9b21", "Is the plum cake eggless?") inside a try block, then call print_tree with the trace id. (Hint: the root span’s trace id is in SPANS even when the call fails. Find the span whose parent_id is None.)
3. Add a session_id filter: write print_session(session_id) that prints every trace whose root span has that session id, oldest first.

Expected result. The tree for the plum-cake request shows handle_message and retrieve with status ERROR TimeoutError('vector db slow'), rewrite_query as OK, and no generate_answer span at all, because the code never reached it. You can see exactly where it stopped.

# Step 1: in rewrite_query, replace the return line with
#     return text.lower()
# then inside retrieve(), at the top of its with-block:
if "plum" in query:
    raise TimeoutError("vector db slow")

# Step 2
try:
    handle_message("sess-9b21", "Is the plum cake eggless?")
except TimeoutError:
    pass
root = next(s for s in reversed(SPANS) if s["parent_id"] is None)
print_tree(root["trace_id"])

# Step 3
def print_session(session_id: str) -> None:
    roots = [s for s in SPANS if s["parent_id"] is None
             and s["attributes"].get("session_id") == session_id]
    for r in sorted(roots, key=lambda s: s["start"]):
        print(f"--- trace {r['trace_id']}")
        print_tree(r["trace_id"])

Common mistakes

• Logging only the final answer. You see that the answer was wrong, never why. Record each step’s inputs and outputs, especially retrieval.
• Treating 200 OK as success. For an AI app, a successful HTTP status says nothing about whether the answer was right. Soft failures need content-level checks, which is what Module 23 is about.
• Recording retrieved chunk text but not ids and scores. Without ids you cannot find the source document to fix. Without scores you cannot tell a clear winner from a near tie.
• One trace per conversation. Long conversations become unreadable blobs. Use one trace per request and group them with a session id.
• Turning on full capture without a privacy plan. It is easy to switch on and hard to clean up later. Decide masking, retention and access first.
• Assuming you can reproduce it later. With a non-deterministic system, the request you fail to record is often the one you can never replay exactly.

Recap

• Logs record events, metrics record numbers over time, and traces record the causal tree of one request. AI apps need all three, but traces answer “why”.
• A trace is a tree of spans. A span is one timed unit of work with a name, start and end, a parent, attributes and a status. A session groups the traces of one conversation.
• AI apps are non-deterministic, fail softly with 200 OK, and take many steps, so you must record each step’s inputs, outputs, tokens, cost and latency as it happens.
• For retrieval, record the query, top_k, chunk ids and scores. For model calls, record the model, tokens, cost, stop reason and prompt version.
• Traces are full of personal data: mask, limit retention and control access before you capture everything.

That evening Arjun explained it to Meera. “The bot didn’t invent the answer. Before it answers, it searches our documents and reads the top four results. On Tuesday the top result was last year’s brownie recipe, from before we added walnuts. The current allergen table wasn’t in the four. The bot read what we gave it and repeated it.”

“And your logs didn’t show that?”

“They showed the request succeeded in 3.2 seconds. That’s all they were built to show. Priya and I rebuilt the request by hand this afternoon, and we’re fairly sure that’s what happened. But we’re guessing, and I don’t want to guess about allergies. I want every request to record its own path, automatically.”

Meera nodded. “Then do it. What does that cost, and where does all that data go?” Arjun opened a browser tab with four tracing tools in it. That is the next lesson.

Go deeper

• OpenTelemetry documentation (the observability concepts pages explain traces, spans and signals): https://opentelemetry.io/docs/
• Langfuse documentation, including its overview of tracing for LLM apps: https://langfuse.com/docs
• Anthropic API docs, for the usage fields that report tokens per call: https://docs.anthropic.com