Why Observability Matters
An agent gave a wrong answer that looked right - and two right answers that were right only by luck. From the answers alone you cannot tell. Build a tiny tracer in 60 lines, see the bug in one line of the trace, and learn what every trace should record.
What you will be able to do
- Explain why you cannot debug an agent from its final answer
- Say what observability, logs, metrics and traces are
- Read a trace as a tree of runs: name, input, output, time
- Build a small tracer with LangChain callbacks
- Use a trace to find a bug and to see where time goes
- Know what a trace should record - and what it should not
The idea, in plain English
An agent is many steps: the model chooses, our code parses, a tool runs, the model answers. The user sees only the last step - the final answer. When the answer is wrong, it could be any step’s fault. When the answer is right, it could still be right by luck.
Observability means being able to see inside a running system - what it did, in what order, with what data, and how long each part took. For an agent, the most useful tool is a trace: a record of every step of one run, arranged as a tree.
In this lesson we bring back a real bug from Lesson 4.4 and ask three questions. The answers look fine. Then we build a tiny tracer - about 60 lines using LangChain callbacks - and the bug appears in a single line. In Lesson 5.2, LangSmith does the same job for you, with a web interface and no tracer code. All runs: LangGraph 1.2.14, langchain-core 1.6.9, mcp 2.3.0, llama3 on Ollama.
Worked example: The Lesson 4.4 agent with its old bug: "What time is it in Paris?" -> "2:52 PM UTC in Paris" - wrong, but it reads fine. A trace finds why in one line.
1 - What the user sees
"According to the current time, it is October 9th, 2026, 2:52 PM UTC in Paris." A clear, confident sentence. Paris was at 16:52.
The same wrong answer, seen two ways. Real runs of the Lesson 4.4 agent with its old silent-fallback bug.
Words you will see in this module
Observability has its own words. Here are the ones this module uses.
ObservabilityBeing able to see inside a running system: what happened, with what data, and how long it took.LogA line of text a program writes, like "wrote shopping.txt". Good for single events.MetricA number measured over time: requests per minute, average answer time, errors per day.TraceThe full record of ONE run: every step, in order, as a tree, with inputs, outputs and times.Run (or span)One step inside a trace - a model call, a tool call, a graph node.LatencyHow long something takes. Here: milliseconds (ms) per step.CallbackA function LangChain calls for you when something happens - a step starts, a step ends.An everyday example: a parcel that arrives broken
A parcel arrives broken. Who broke it - the shop, the warehouse, the truck, or the delivery person? If all you have is the broken parcel, you can only guess and blame.
Parcel companies solve this with tracking. Every time the parcel is handled, someone scans it: time, place, condition. Now you can see that it left the warehouse fine and arrived at the truck broken. You know where to look.
A trace is parcel tracking for an agent. Each step is "scanned" - what came in, what went out, how long it took. When the final answer is broken, the trace tells you which step broke it.
Three answers that look fine
We took the Lesson 4.4 agent and put back its bug: when llama3’s arguments are not a JSON object, the code silently uses {} instead. With no timezone, the time server answers in UTC. We used the older prompt from 4.4, which makes llama3 send plain text - and the bug fired in all three runs.
Read the three answers as a user would. Tokyo: correct - llama3 knew Tokyo is UTC+9 and did the maths itself. India: correct - it added 5:30. Paris: wrong - "2:52 PM UTC in Paris", when Paris was at 16:52. All three are calm, confident sentences.
So: one answer is wrong, and two are right only because the model happened to fix the bug’s damage. Without seeing inside, you would ship this. A user in Paris would get the wrong time - and every answer would still look fine.
What time is it in Tokyo? (6.0 s)
ai get_current_time {}
tool 2026-10-09 14:51:36 UTC
ai According to the current time, it is 2026-10-09 14:51:36 UTC, which is equivalent to approximately 23:51 (11:51 PM) in Tokyo, considering the city is 9 hours ahead of UTC.
What time is it in Paris? (4.3 s)
ai get_current_time {}
tool 2026-10-09 14:51:41 UTC
ai According to the current time, it is October 9th, 2026, 2:51 PM UTC in Paris.
What time is it in India? (5.2 s)
ai get_current_time {}
tool 2026-10-09 14:51:46 UTC
ai According to the current time, it is 14:51:46 UTC, which is equivalent to 20:21:46 IST (Indian Standard Time) considering India is UTC+5:30.Tip: Even this printout is a small trace: it shows each tool call. And it already tells you something - every call has empty arguments {}. But it does not show WHY. For that we need the model’s raw output too.
A trace is a tree of runs
A trace records one run of your agent. Each step is a run with a name, a kind (graph node, model call, tool call), an input, an output and a duration. Runs are nested: the whole graph contains the agent node; the agent node contains the model call. So a trace is a tree.
Reading a trace is like reading an outline. The top line is the whole run and its total time. Each indented line is a step inside it. To find a bug, walk down the tree and compare each step’s output with the next step’s input. Where they stop matching, the bug is between them.
Name and kindagent (a graph node), llama3 (a model call), get_current_time (a tool).ParentWhich run it happened inside - this makes the tree.InputThe prompt, or the tool’s arguments.OutputThe model’s reply, or the tool’s result.DurationHow long it took - to find slow steps.ErrorIf it failed, the error. (Our bug did not fail - which is why it hid.)Example 1 - a tracer in 60 lines
LangChain has callbacks: when you pass a callback handler in the config, LangChain calls its methods every time a step starts or ends - graph nodes (on_chain_start), model calls (on_chat_model_start, on_llm_end) and tools (on_tool_start, on_tool_end). Each call comes with a run_id and the parent_run_id of the step it is inside.
Our TinyTracer stores each step with its parent, input, output and duration, then prints the tree. It hides LangChain’s small helper steps and keeps what matters: the graph, its nodes, model calls and tool calls. You do not need to write this for real projects - LangSmith (Lesson 5.2) does it, better. But writing it once shows you there is no magic in a trace.
import time
from langchain_core.callbacks import AsyncCallbackHandler
class TinyTracer(AsyncCallbackHandler):
"""Records every step of a run as a tree: what ran, inside what, with what, how long."""
def __init__(self):
self.runs = {} # run_id -> one record
self.order = [] # run_ids in start order
def _start(self, run_id, parent_run_id, kind, name, inputs):
self.runs[run_id] = {"kind": kind, "name": name, "parent": parent_run_id,
"inputs": inputs, "outputs": None, "start": time.perf_counter(), "ms": None}
self.order.append(run_id)
def _end(self, run_id, outputs):
r = self.runs.get(run_id)
if r:
r["outputs"], r["ms"] = outputs, (time.perf_counter() - r["start"]) * 1000
# graph nodes and other steps
async def on_chain_start(self, serialized, inputs, *, run_id, parent_run_id=None, **kw):
self._start(run_id, parent_run_id, "chain", kw.get("name") or "chain", "")
async def on_chain_end(self, outputs, *, run_id, **kw):
self._end(run_id, "")
# model calls
async def on_chat_model_start(self, serialized, messages, *, run_id, parent_run_id=None, **kw):
text = " | ".join(m.content for m in messages[0])
self._start(run_id, parent_run_id, "llm", "llama3", f"{len(text)} chars of prompt")
async def on_llm_end(self, response, *, run_id, **kw):
msg = response.generations[0][0].message
out = msg.tool_calls[0]["args"] if getattr(msg, "tool_calls", None) else msg.content
self._end(run_id, str(out))
# tools
async def on_tool_start(self, serialized, input_str, *, run_id, parent_run_id=None, **kw):
self._start(run_id, parent_run_id, "tool", serialized.get("name", "tool"), input_str)
async def on_tool_end(self, output, *, run_id, **kw):
self._end(run_id, str(getattr(output, "content", output)))
def print_tree(self, keep=("LangGraph", "agent", "tools")):
"""Print the steps as a tree. Hide LangChain's inner helper steps; keep nodes, models, tools."""
shown = [rid for rid in self.order
if self.runs[rid]["kind"] != "chain" or self.runs[rid]["name"] in keep]
def depth(rid): # count only ancestors we print
d, p = 0, self.runs[rid]["parent"]
while p in self.runs:
d += p in shown
p = self.runs[p]["parent"]
return d
for rid in shown:
r = self.runs[rid]
ms = f"{r['ms']:6.0f} ms" if r["ms"] is not None else " ... "
line = f"{' ' * depth(rid)}{r['kind']:5} {r['name']:17} {ms}"
if r["kind"] in ("llm", "tool"):
out = " ".join(str(r["outputs"]).split()) # one line
line += f" in: {str(r['inputs'])[:22]:22} out: {out[:62]}"
print(line)tracer = TinyTracer()
result = await graph.ainvoke({"messages": [HumanMessage("What time is it in Paris?")]},
{"recursion_limit": 12, "callbacks": [tracer]}) # <- the only change
print("FINAL ANSWER:", result["messages"][-1].content, "\n")
tracer.print_tree()The trace finds the bug
Here is the trace of the Paris question. Walk down it. The first model call’s output: {"action": "get_current_time", "arguments": "Europe/Paris"}. llama3 did its job - it wanted Paris. The next line, the tool’s input: {}. Paris disappeared between the model and the tool.
What sits between them? Only our own code: parse_arguments. "Europe/Paris" is not a JSON object, so the buggy version returned {}. One look at two neighbouring lines, and the guessing is over. The model, the server and the timezone data are all innocent.
Below it is the trace of the fixed Lesson 4.4 agent. Same question. Now the model sends {"timezone": ...} as JSON, the tool receives {'timezone': 'Europe/P...'}, and the answer is 4:52 PM - correct.
FINAL ANSWER: According to the current time, it is October 9th, 2026, 2:52 PM UTC in Paris.
chain LangGraph 4059 ms
chain agent 1314 ms
llm llama3 1311 ms in: 393 chars of prompt out: { "action": "get_current_time", "arguments": "Europe/Paris" }
chain tools 32 ms
tool get_current_time 31 ms in: {} out: 2026-10-09 14:52:32 UTC
chain agent 2711 ms
llm llama3 1173 ms in: 454 chars of prompt out: {"action": "get_current_time", "arguments": "Europe/Paris"}
llm llama3 1534 ms in: 151 chars of prompt out: According to the current time, it is October 9th, 2026, 2:52 PFINAL ANSWER: According to the current time in Paris, it is October 9th, 2026, at 4:52 PM.
chain LangGraph 4366 ms
chain agent 1295 ms
llm llama3 1292 ms in: 413 chars of prompt out: {"action": "get_current_time", "arguments": "{\"timezone\": \"
chain tools 32 ms
tool get_current_time 32 ms in: {'timezone': 'Europe/P out: 2026-10-09 16:52:37 CEST
chain agent 3036 ms
llm llama3 1501 ms in: 501 chars of prompt out: {"action": "get_current_time", "arguments": "{\"timezone\": \"
llm llama3 1531 ms in: 178 chars of prompt out: According to the current time in Paris, it is October 9th, 202The trace shows more than bugs
Look at the second agent node in BOTH traces. It contains two model calls. The first one asks for get_current_time again - the same call that already has a result. Our repeat guard from Lesson 4.4 catches it and makes a second, plain model call for the answer. So every question costs three model calls, not two - about 1.5 extra seconds, every time. The answers never told us that.
Look at the times too. Each model call takes 1.2 to 1.5 seconds. The tool takes 32 ms - about 40 times faster. If this agent is slow, making the tool faster will not help. Fewer or faster model calls will. A trace tells you where to spend your effort.
And notice the prompt sizes: 393 characters for the first call, 454 for the second, because the transcript grows with every step. In a long conversation, prompts grow until they become slow and expensive. Lesson 5.3 looks at counting this properly.
BugModel output "Europe/Paris" -> tool input {} : the parser lost it.Hidden cost3 model calls per question; the third exists only because of the repeat guard.Where time goesModel calls 1.2-1.5 s each; the MCP tool 32 ms.GrowthPrompt size grows with each step: 393 -> 454 characters.Logs, metrics and traces - which question each answers
You need all three, for different questions. A log answers "did this event happen?". A metric answers "how is the system doing overall?". A trace answers "what exactly happened in THIS run, and why?". For agents, traces matter most - because every run can take a different path.
Log"Was the note written?" - wrote shopping.txt (16 chars). One event at a time.Metric"Are answers getting slower this week?" - average time per question, errors per day.Trace"Why was THIS Paris answer wrong?" - every step of one run, in order, with data.What a trace should record - and what it should not
Record enough to understand a run later: every model call with its prompt and output, every tool call with its arguments and result, timings, errors, and which version of your prompt and code ran. Add who asked and a request id, so a user’s complaint can be matched to its trace.
But traces are full of data, and data can be private. Prompts contain what users typed. Tool results can contain notes, emails, or files. Before you send traces to any service, decide what may leave your system, and remove or mask secrets and personal details. Never put API keys or passwords in prompts or tool arguments - they will end up in the trace.
Watch out: LangSmith (next lesson) is a hosted service: with tracing on, your prompts and outputs are sent to it. That is fine for this course’s demo data. For real users, check your company’s rules first, and mask sensitive fields.
Observability at a glance
TraceEvery step of one run, as a tree.
RunOne step: name, kind, parent, input, output, duration, error.
Add a tracerCallbacks go in the run config.
graph.ainvoke(inputs, {"callbacks": [TinyTracer()]})Model call eventsStart and end of a chat model call.
on_chat_model_start / on_llm_end
Tool eventsStart and end of a tool call.
on_tool_start / on_tool_end
Node eventsGraph nodes and other steps.
on_chain_start / on_chain_end
Find a bugCompare each step’s output with the next step’s input.
Try it yourself
The code does not change. Swap the content string and the program does something else entirely.
“Add TinyTracer to the Lesson 3.8 writing team. Which agent takes the most time?”
“Extend TinyTracer to print, at the end, how many model calls and tool calls the run made.”
“Add on_tool_error and on_llm_error to TinyTracer, then ask about Mars. Do failed tool calls show up?”
“Remove the repeat guard from the fixed agent and trace it again. What does the second agent node look like now?”
“Make TinyTracer replace anything that looks like an email address in inputs and outputs with [email].”
What usually goes wrong
Two of our three answers were right by luck, and the wrong one looked fine. Look at the steps, not only the result.
Our bug raised no error, so error logs were empty. Code that quietly replaces bad data creates wrong answers that only a trace shows.
The tool took 32 ms; each model call over 1 second. Measure before you speed something up.
Everything in a prompt or tool argument ends up in the trace - and with LangSmith, on someone else’s server.
Key points
- A final answer can be wrong but look right - or right by luck. You cannot debug an agent from answers alone.
- A trace records every step of one run as a tree: name, input, output, duration, error.
- To find a bug, compare each step’s output with the next step’s input.
- LangChain callbacks report every node, model call and tool call - a tracer is just a callback handler.
- Traces also show hidden costs (extra model calls) and where time goes.
- Traces contain user data - decide what may leave your system.
Quick check before you move on
Quiz
- 1.
How many model calls did each question cost, and why?
- 2.
Model calls took about 1.3 s; the tool took 32 ms. What should you optimise first?
- 3.
How do you add a callback handler to one graph run?
- 4.
Why can traces be a privacy risk?
Interview questions
Why is observability more important for LLM agents than for normal programs?
Agents are non-deterministic and take different paths per run; failures are often silent and plausible-looking rather than exceptions. You need per-run traces of prompts, model outputs, tool calls and timings to debug, evaluate and control cost.
What should an agent trace capture?
The run tree: each node, model call (prompt, output, tokens, latency, model and parameters) and tool call (arguments, result, latency), errors, plus metadata - request id, user, prompt and code version - with sensitive data masked.
How do LangChain callbacks relate to tracing?
Callbacks fire on start and end of chains, model calls and tools with run and parent ids. A tracer is a callback handler that records these into a tree; LangSmith’s tracer works the same way and sends them to the service.
Comments
Sign in to leave a comment. Your name and photo come from Google; nothing else is shared.
Loading comments...