Debug MCP Tool Calls: Trace What Your Agent Fetched

When Your Agent Lies, the Tool Boundary Knows Why

Your agent confidently reported that the product page listed no prices. The page does list prices. Somewhere between the model deciding to call a tool and the answer landing in the chat, the data went wrong — a redirect swallowed the fetch, a selector matched nothing, or the agent passed a URL without a scheme and the tool silently “recovered” into fetching the wrong thing. You will never find out which by staring at the chat transcript.

The fix is boring and effective: instrument the tool-call boundary. Every tool invocation gets a structured log record with the tool name, the exact arguments the model produced, the raw response, and a timing measurement. Thread a trace ID through the whole loop and you can reconstruct any run end to end. This post builds that instrumentation from scratch against a minimal MCP server, then uses it to diagnose a realistic failure.

If you want background on MCP tool design first, MCP Tools for AI Agents: Auth Scopes and Failure Modes covers the protocol side. Here we stay on the debugging side.

Set Up a Minimal MCP Client with a Traceable Tool Server

Start with the smallest thing that can fail: a local MCP server exposing one tool, fetch_page, that retrieves a URL and returns the page title plus the HTTP status code. In the examples below the tool talks to a scraping API so it can handle real pages — but the instrumentation works identically if you swap in plain httpx.

# server.py
import re
import httpx
from mcp.server.fastmcp import FastMCP

mcp = FastMCP("traceable-fetch")

API_BASE = "https://api.finedata.ai"
API_KEY = "fd_your_api_key"

@mcp.tool()
def fetch_page(url: str) -> dict:
    """Fetch a web page and return its title and HTTP status."""
    resp = httpx.post(
        f"{API_BASE}/api/v1/scrape",
        headers={"Authorization": f"Bearer {API_KEY}"},
        json={
            "url": url,
            "formats": ["rawHtml"],
            "timeout": 60,
        },
        timeout=90,
    )
    resp.raise_for_status()
    data = resp.json()

    html = data.get("data", {}).get("rawHtml", "") or ""
    m = re.search(r"<title[^>]*>(.*?)</title>", html, re.IGNORECASE | re.DOTALL)
    return {
        "url": url,
        "status": data.get("status"),
        "title": (m.group(1).strip() if m else None),
    }

if __name__ == "__main__":
    mcp.run(transport="stdio")

The client side is a standard stdio session. Run the server as a subprocess and open the connection:

# client.py
import asyncio
from mcp import ClientSession, StdioServerParameters
from mcp.client.stdio import stdio_client

async def main():
    params = StdioServerParameters(
        command="python",
        args=["server.py"],
    )
    async with stdio_client(params) as (read, write):
        async with ClientSession(read, write) as session:
            await session.initialize()
            result = await session.call_tool(
                "fetch_page", {"url": "http://example.com"}
            )
            print(result.content)

asyncio.run(main())

That’s the whole baseline. One tool, one call, one result. Everything from here is instrumentation layered on top of this boundary — which is exactly the point. You should not need to modify the client protocol handling or the tool logic to get visibility.

Wrap Every Tool Call with Structured Request/Response Logging

Where do you log? Not inside the tool function, and not inside the client’s transport. Log at the dispatch boundary, where you still have both the arguments the model chose and the response the tool produced. A decorator around the tool implementation gives you that without touching call sites:

# tracing.py
import functools
import json
import time
import uuid
import sys

def traced_tool(fn):
    @functools.wraps(fn)
    def wrapper(**kwargs):
        call_id = uuid.uuid4().hex[:12]
        started = time.perf_counter()
        record = {
            "ts": time.time(),
            "call_id": call_id,
            "tool": fn.__name__,
            "args": kwargs,
        }
        try:
            result = fn(**kwargs)
            record["ok"] = True
            record["response_bytes"] = len(json.dumps(result).encode())
            record["response"] = result
            return result
        except Exception as exc:
            record["ok"] = False
            record["error"] = f"{type(exc).__name__}: {exc}"
            raise
        finally:
            record["duration_ms"] = round(
                (time.perf_counter() - started) * 1000, 1
            )
            print(json.dumps(record, default=str), file=sys.stderr)
    return wrapper

Two details matter. First, logs go to stderr, because the stdio transport uses stdout for protocol messages — writing JSON lines to stdout will corrupt the MCP stream and hang your session. I have seen people lose an afternoon to this. Second, the record captures the arguments as received, not as the tool author intended them. That distinction is the entire reason this exercise pays off.

Apply it to the server:

@mcp.tool()
def fetch_page(url: str) -> dict:
    """Fetch a web page and return its title and HTTP status."""
    return _fetch_page_impl(url)

@traced_tool
def _fetch_page_impl(url: str) -> dict:
    ...  # same body as before

Two sequential calls now produce this on stderr:

{"ts": 1737000000.0, "call_id": "a1b2c3d4e5f6", "tool": "_fetch_page_impl", "args": {"url": "http://example.com"}, "ok": true, "response_bytes": 96, "response": {"url": "http://example.com", "status": 200, "title": "Example Domain"}, "duration_ms": 412.3}
{"ts": 1737000001.1, "call_id": "f6e5d4c3b2a1", "tool": "_fetch_page_impl", "args": {"url": "https://store.example.com/products"}, "ok": true, "response_bytes": 88, "response": {"url": "https://store.example.com/products", "status": 200, "title": "Products — Example Store"}, "duration_ms": 1104.7}

Notice the latency difference already: 412 ms versus 1105 ms. Free diagnostics, before we’ve written any timing-specific code.

Propagate Trace IDs Across the Agent Loop and Tool Calls

Per-call logs answer “what happened in this call.” They do not answer “which agent turn was this part of.” For that you need a correlation ID generated once per session (or per user turn) and attached to every tool call that turn produces.

MCP requests support a _meta field, but the simplest robust approach — and the one I’d actually ship — is to pass the trace ID as an explicit tool argument. It’s visible in every log line, survives any SDK version, and the model can’t accidentally drop it because the client injects it, not the model:

# client.py (revised)
import uuid

async def run_turn(session, user_message: str):
    trace_id = uuid.uuid4().hex[:16]
    # ... send user_message to your agent/LLM, get tool_calls back ...
    for call in agent_tool_calls:
        args = dict(call.arguments)
        args["_trace"] = trace_id          # injected by the client
        result = await session.call_tool(call.name, args)
        # feed result back to the agent loop...

On the server, pop it out before the tool sees it, and stamp it into the record:

@traced_tool
def _fetch_page_impl(url: str, _trace: str = None) -> dict:
    ...

# in traced_tool, before calling fn:
record["trace_id"] = kwargs.pop("_trace", None)

Now a single agent turn that reasons through three chained calls renders as one reconstructable story:

{"trace_id": "9c8b7a6b5c4d3e2f", "call_id": "01", "tool": "_fetch_page_impl", "args": {"url": "http://example.com"}, "ok": true, "response": {"status": 200, "title": "Example Domain"}, "duration_ms": 398.1}
{"trace_id": "9c8b7a6b5c4d3e2f", "call_id": "02", "tool": "_fetch_page_impl", "args": {"url": "https://store.example.com/products"}, "ok": true, "response": {"status": 200, "title": "Products — Example Store"}, "duration_ms": 1188.4}
{"trace_id": "9c8b7a6b5c4d3e2f", "call_id": "03", "tool": "_fetch_page_impl", "args": {"url": "https://store.example.com/products/pdp-4471"}, "ok": false, "error": "HTTPStatusError: 404", "duration_ms": 655.0}

Same trace_id, three calls, one turn. When the user says “your answer about the product price was wrong,” you grep the trace ID and see exactly what the agent actually fetched, in order, with timings. That beats replaying the conversation and guessing.

Inspect Payloads: Truncation, Redaction, and Full-Body Capture

So far the tool returned small summaries. Real tools return page bodies, and page bodies are where logging goes wrong in two directions: megabytes of HTML per call drowning your logs, or an Authorization header ending up in a log file that ships to a third-party log service. Both are self-inflicted.

Make capture explicit and tunable:

# capture.py
from dataclasses import dataclass, field

@dataclass
class CaptureConfig:
    mode: str = "truncated"            # "headers_only" | "truncated" | "full"
    max_body_bytes: int = 2048
    redact_headers: list = field(
        default_factory=lambda: ["authorization", "cookie", "set-cookie", "Authorization"]
    )
    keep_first_line_only: bool = True  # for HTML: keep the first line + byte count

capture = CaptureConfig()

def shape_response(resp: dict) -> dict:
    out = {}
    for k, v in resp.items():
        if k == "headers":
            out[k] = {
                h: ("[REDACTED]" if h.lower() in capture.redact_headers else val)
                for h, val in v.items()
            }
        elif isinstance(v, str) and len(v.encode()) > capture.max_body_bytes:
            if capture.mode == "headers_only":
                out[k] = f"<omitted: {len(v.encode())} bytes>"
            elif capture.mode == "truncated":
                out[k] = v[: capture.max_body_bytes] + f"... <truncated, {len(v.encode())} bytes total>"
            else:
                out[k] = v
        else:
            out[k] = v
    return out

Which mode should you run? This is where I’ll argue with the default instinct. Most people reach for full-body capture “to be safe.” Don’t, at least not by default. Full bodies blow up log volume, and in practice you almost never need the whole page — you need the first 2 KB to see what the server actually returned (a block page, a login redirect, a consent wall), and the parsed fields to see what your extraction did with it. Here’s the honest comparison:

Capture mode	Log volume (per call)	Debug usefulness	PII/secret risk
Headers-only	~200 B	Low — you see status and redirects, nothing about content	Low, if headers are redacted
Truncated body (2 KB)	~2–3 KB	High — enough to identify block pages and wrong-page fetches	Medium — first 2 KB can contain PII on profile pages
Full body	50 KB–2 MB	Marginally higher than truncated	High — full PII, session tokens in HTML

Truncated mode catches roughly 90% of the failure classes I care about: 200 OK block pages (see Your 200 OK Responses Are Actually Block Pages), consent interstitials, geo-redirects, and empty-body responses. Full mode earns its cost only when you’re debugging an extraction bug that depends on content deep in the page — and for that, export the body to a side file keyed by call_id instead of inlining it in the log line.

Reproduce a Failing Web Fetch: From Trace to Root Cause

Time for the payoff. The scenario: the user asks “what does the widget cost on Example Store?” The agent answers “I couldn’t find pricing information on that page.” The user knows the price is right there. Replay the trace.

{"trace_id": "44a3f2e1d0c9", "call_id": "07", "tool": "_fetch_page_impl", "args": {"url": "store.example.com/products"}, "ok": true, "response": {"url": "store.example.com/products", "status": 302, "title": null, "redirect_to": "https://store.example.com/select-region"}, "duration_ms": 289.5}

Read it carefully. Status 302, redirecting to a region-selection page, and a null title because the redirect body has no title worth parsing. The agent received something like {"status": 302, "title": null} — structurally a success, semantically useless. It honestly reported “no pricing information,” because that’s what it was given. The model wasn’t hallucinating; the tool starved it.

But there’s a second bug hiding in that same line, and this is the one structured args capture catches. Look at the URL:

BEFORE (what the agent actually passed):
  "url": "store.example.com/products"

AFTER (what the tool needed):
  "url": "https://store.example.com/products"

No scheme. The model produced a bare host because the conversation context referred to the site that way. The tool didn’t reject it — the scraping API interpreted it leniently, and the request went somewhere the agent didn’t intend. Two failure modes, one log line: a malformed input from the model, and a redirect the tool treated as a normal result.

The fixes follow directly from the trace:

1. Validate at the boundary. Reject url values without a scheme in the tool, and return a structured error the agent can act on: {"error": "invalid_url", "detail": "missing scheme, expected http:// or https://"}. A loud failure is better than a quiet wrong fetch — the model will self-correct on the next turn if you tell it what’s wrong.
2. Surface redirects as first-class results. Don’t let a 302 masquerade as a successful fetch. Return the redirect target and let the agent decide whether to follow it, possibly with a country-pinned exit IP if the region wall is geo-based (Scrape Localized Storefronts With a Country Exit Code covers that pattern).

Neither fix is guessable from the chat transcript. Both are obvious from one JSON log line. That’s the whole argument for this instrumentation.

Measure Tool Call Latency and Timeout Behavior Locally

Wrong answers are one failure class. Slow and hanging calls are the other — and they’re worse, because a tool that takes 90 seconds makes the agent feel “broken” without producing any error at all. Add timing and timeout flags to every record:

# in traced_tool
import signal

class ToolTimeout(Exception):
    pass

def _timeout_handler(signum, frame):
    raise ToolTimeout()

def run_with_timeout(fn, kwargs, timeout_s: float = 60.0):
    old = signal.signal(signal.SIGALRM, _timeout_handler)
    signal.alarm(int(timeout_s))
    try:
        return fn(**kwargs)
    finally:
        signal.alarm(0)
        signal.signal(signal.SIGALRM, old)

And in the record, emit duration_ms plus timed_out: true when the ToolTimeout path fires. (The signal approach is Unix-only and fine for a local harness; in async code use asyncio.wait_for instead.)

With timing in place, a 20-call local benchmark — 10 calls to http://example.com, 10 to https://store.example.com/products — gives you a baseline you can defend:

Target	Calls	p50 latency	p95 latency	Timeouts
example.com	10	402 ms	611 ms	0
store.example.com/products	10	1.19 s	4.62 s	1

The p95 spread is the story here. A 4.6-second p95 on the store domain means the agent’s perceived slowness isn’t the model — it’s the fetch tail latency. One timeout out of ten tells you the 60-second tool ceiling is being hit at all, which is worth knowing before a user reports it. If you want to go deeper on decomposing where those milliseconds go, Break Down Scrape Latency: A Timing Harness You Can Run extends exactly this kind of local measurement.

Export Traces to a Reviewable Format for Post-Run Analysis

stderr lines are great during a session and useless after it. Persist the records as JSONL with a small manifest, so a run is a folder you can open, grep, and hand to a teammate:

# export.py
import json
import time
from pathlib import Path

def export_session(records: list[dict], out_dir: str = "traces") -> Path:
    out = Path(out_dir)
    out.mkdir(exist_ok=True)
    session_id = time.strftime("%Y%m%d-%H%M%S")
    path = out / f"session-{session_id}.jsonl"

    manifest = {
        "session_id": session_id,
        "exported_at": time.time(),
        "total_calls": len(records),
        "failed_calls": sum(1 for r in records if not r.get("ok")),
        "trace_ids": sorted({r.get("trace_id") for r in records if r.get("trace_id")}),
        "tools": sorted({r["tool"] for r in records}),
    }
    (out / f"session-{session_id}.manifest.json").write_text(
        json.dumps(manifest, indent=2)
    )

    with path.open("w") as f:
        for r in records:
            f.write(json.dumps(r, default=str) + "\n")
    return path

Then the questions you actually ask post-run become one-liners. Every failed call:

jq -c 'select(.ok == false)' traces/session-*.jsonl

Every call slower than two seconds:

jq -c 'select(.duration_ms > 2000)' traces/session-*.jsonl

Or in Python, if jq isn’t in your toolbox:

[print(r) for r in map(json.loads, open("traces/session-x.jsonl"))
 if not r.get("ok") or r.get("duration_ms", 0) > 2000]

The manifest matters more than it looks. “12 calls, 3 failed, 2 trace IDs, 1 tool” is the summary you read before opening the detail — and when a bug report comes in three days later, the manifest tells you whether that session is even the right one to inspect.

Wrap-Up

The instrumentation in this post is deliberately unglamorous: a decorator, a trace ID in the args, a truncation config, a JSONL file. No trace UI, no vendor SDK, no distributed tracing standard. My honest position: for a team of any size below “we have a dedicated observability budget,” structured JSONL logs at the tool boundary beat a fancy tracing backend, because they’re grep-able, diff-able, and portable — and the tool boundary is where agent non-determinism meets the real world, which is where these bugs live.

What you end up with:

• Every tool call logged with the exact arguments the model produced, not what you hoped it produced.
• Trace IDs tying multi-step agent turns into reconstructable sequences.
• Payload capture that’s useful without leaking secrets or drowning in HTML.
• Latency and timeout visibility per call, with a local p50/p95 baseline.
• JSONL exports you can filter with one-liners and attach to a bug report.

Gotchas worth repeating: never log to stdout on a stdio transport; never let a redirect or a 200 OK block page count as a successful fetch in your tool’s return shape; and validate model-produced URLs at the boundary instead of trusting the upstream service to interpret them charitably.

Next steps, in order of value: add the trace_id injection to your real client this week — it’s a five-line change. Then add the truncation config before you turn on response capture, not after. And if your tools return parsed fields rather than raw pages, pair this tracing with Audit Field Fill Rates: Measure Extraction Quality Locally so you can tell “the fetch failed” apart from “the fetch worked and the extraction returned garbage.” They look identical from the chat window. The trace knows the difference.