All articles

// Knowledge.log — 技術記事

Tool Call Telemetry for MCP Agents

Track latency, errors, and payload size per tool call in events.jsonl, query it with DuckDB, and enforce a separate CI error gate.

A coding agent finishes its review successfully but leaves behind questions that are much less comfortable than the final summary: how many times did it read the same files, which commands failed, and how long did it spend waiting for Bash instead of inspecting code?

MCP does not provide that accounting out of the box. It standardizes tool invocation, not the bookkeeping performed by your harness. To answer those questions, we will observe tools/call, write a local events.jsonl file, and query it with DuckDB. The result separates call volume, latency, and bytes by tool without pretending those numbers are tokens or dollars.

Versions and limits of the example

The baseline used here is:

  • MCP 2026-07-28;
  • Python SDK mcp 2.1.1;
  • Python 3.10 or later, with 3.11 as a valid runtime choice;
  • DuckDB 1.5.5 as a query helper.

Both the SDK and DuckDB require Python 3.10 or later. There is no joint compatibility matrix between them: they are two independent requirements that meet at the same minimum version. The MCP tools specification defines tools/list, tools/call, and their results; the Python SDK implements the server. DuckDB is not part of the protocol.

Install the dependencies in a virtual environment:

python3.11 -m venv .venv
. .venv/bin/activate
python -m pip install "mcp[cli]==2.1.1" "duckdb==1.5.5"

In MCP 2026-07-28, the modern discovery path is server/discover. For a client using this SDK, set mode="2026-07-28" when you do not want to rely on automatic negotiation. The old initialize method belongs to the 2025-11-25 generation; mixing the two makes the telemetry confusing before it even starts helping.

What a tool call actually tells you

A client invokes a tool through the JSON-RPC method tools/call, sending name and arguments. Two failure channels must remain separate:

  • ToolError is a tool execution error. The JSON-RPC call produces a result with isError: true and content the model can use to correct its next attempt.
  • MCPError is a protocol error, such as invalid parameters rejected by the host. There is no tool result or isError value for the model to interpret.
  • an uncaught exception also becomes a result with is_error=True, but the client receives only a generic message; the traceback remains in the server log.

Returning a string such as "erro: livro ausente" is not a replacement for ToolError: the protocol still considers it a success. It is the kind of success that improves the dashboard and makes everything else worse.

The official middleware documentation uses the asynchronous signature (ctx, call_next). This API is provisional and may change in a minor 2.x release. Middleware receives every message, including discovery and listing requests, so filtering on ctx.method == "tools/call" is required if you want one row per tool invocation.

Middleware that generates events.jsonl

The example below uses MCPServer and the official server.middleware list. It measures a monotonic clock with perf_counter, records ToolError as an error result, and keeps MCPError in the protocol channel. prompt_sha and tools_sha come from the bytes sent by the harness itself; they are not MCP fields.

from __future__ import annotations

import asyncio
import json
import os
import time
from datetime import datetime, timezone
from pathlib import Path
from typing import Any

from mcp import MCPError
from mcp.server.mcpserver import MCPServer
from mcp.server.mcpserver.exceptions import ToolError

EVENTS = Path(os.getenv("EVENTS_FILE", "events.jsonl"))
WRITE_LOCK = asyncio.Lock()
CATALOG = {"Duna": "Frank Herbert"}


def json_bytes(value: Any) -> bytes:
    return json.dumps(
        value,
        ensure_ascii=False,
        separators=(",", ":"),
        default=str,
    ).encode("utf-8")


def field(params: Any, name: str, default: Any) -> Any:
    if isinstance(params, dict):
        return params.get(name, default)
    return getattr(params, name, default)


async def append_event(event: dict[str, Any]) -> None:
    line = json.dumps(event, ensure_ascii=False, separators=(",", ":"))
    async with WRITE_LOCK:
        with EVENTS.open("a", encoding="utf-8") as output:
            output.write(line + "\n")


async def capture_tool_calls(ctx, call_next):
    if ctx.method != "tools/call":
        return await call_next(ctx)

    params = ctx.params  # raw e ainda não validado pelo handler
    tool = field(params, "name", "<unknown>")
    arguments = field(params, "arguments", {})
    started = time.perf_counter()

    base = {
        "schema": "events.v1",
        "ts": datetime.now(timezone.utc).isoformat(timespec="milliseconds")
        .replace("+00:00", "Z"),
        "tool": tool,
        "bytes_in": len(json_bytes(arguments)),
        "prompt_sha": os.getenv("PROMPT_SHA"),
        "tools_sha": os.getenv("TOOLS_SHA"),
        "mcp_method": "tools/call",
    }

    try:
        result = await call_next(ctx)
    except MCPError:
        await append_event({
            **base,
            "latency_ms": round((time.perf_counter() - started) * 1000, 3),
            "ok": False,
            "is_error": None,
            "error_channel": "protocol",
            "bytes_out": 0,
        })
        raise
    except Exception:
        await append_event({
            **base,
            "latency_ms": round((time.perf_counter() - started) * 1000, 3),
            "ok": False,
            "is_error": None,
            "error_channel": "crash",
            "bytes_out": 0,
        })
        raise

    is_error = bool(getattr(result, "is_error", False))
    content = getattr(result, "content", [])
    await append_event({
        **base,
        "latency_ms": round((time.perf_counter() - started) * 1000, 3),
        "ok": not is_error,
        "is_error": is_error,
        "error_channel": "tool_result" if is_error else None,
        "bytes_out": len(json_bytes(content)),
    })
    return result


mcp = MCPServer("catalogo", middleware=[capture_tool_calls])


@mcp.tool()
def get_author(title: str) -> str:
    if title not in CATALOG:
        raise ToolError(f"Livro {title!r} não encontrado no catálogo.")
    return CATALOG[title]

The try block is not decoration: without it, an MCPError exits call_next before the event is written. A ToolError, on the other hand, returns as a result and reaches the final block with is_error=true. Schema errors may be converted by the SDK into a correctable result before the tool function runs.

Writing directly to this file is enough for a single process. In production, with multiple processes or hosts, send events to one collector or use a sink that preserves each record atomically; the asyncio.Lock protects only concurrency within the same process. Monitor collector health with a dropped-event counter, queue size, and an alert for missing events while runs are active. An audit log that vanishes silently has admirable composure but limited practical value.

bytes_in and bytes_out measure the serialization performed by the harness. They are neither protocol fields nor a guaranteed copy of the transport frame. If the team needs exact wire bytes, the measurement belongs in the transport layer.

A small, versioned schema

A minimal row looks like this:

{"schema":"events.v1","ts":"2026-09-07T12:00:00.000Z","tool":"Read","latency_ms":18.4,"ok":true,"is_error":false,"bytes_in":128,"bytes_out":2048,"prompt_sha":"...","tools_sha":"...","mcp_method":"tools/call"}

The schema field lets you change columns without reinterpreting historical data. prompt_sha and tools_sha should be hashes of the exact bytes sent by the harness, calculated in binary mode; git hash-object identifies a Git object and answers a different question. For production correlation, add run_id and attempt in the next schema version instead of reconstructing a run from timestamps that happen to be nearby.

You should also decide what not to record. Arguments and content may contain source code, secrets, or personal data; record sizes and identifiers by default, not raw payloads. Safe monitoring includes the redaction rate, sink failures, and tool cardinality, with retention and access policies defined outside the agent process.

Querying operational cost with DuckDB

Here, “cost” means call count, accumulated time, and bytes calculated by the harness. MCP does not charge tokens per tool or return a dollar cost for tools/call. Provider tokens and spending remain in usage.json, behind a separate gate.

The DuckDB JSON documentation supports reading NDJSON directly with read_ndjson:

WITH calls AS (
    SELECT
        CASE
            WHEN tool IN ('Read', 'Grep') THEN 'inspect'
            WHEN tool IN ('Bash', 'Edit') THEN 'mutate'
            ELSE 'other'
        END AS bucket,
        tool,
        latency_ms,
        bytes_in,
        bytes_out,
        ok
    FROM read_ndjson('events.jsonl')
    WHERE schema = 'events.v1'
      AND mcp_method = 'tools/call'
)
SELECT
    bucket,
    tool,
    count(*) AS calls,
    round(100.0 * count(*) / sum(count(*)) OVER (), 1) AS call_share_pct,
    round(sum(latency_ms), 1) AS total_ms,
    round(quantile_cont(latency_ms, 0.95), 1) AS p95_ms,
    sum(bytes_in + bytes_out) AS payload_bytes,
    count(*) FILTER (WHERE NOT ok) AS errors
FROM calls
GROUP BY bucket, tool
ORDER BY calls DESC, tool;

The distinction between Read/Grep and Bash/Edit is a harness taxonomy. It shows whether a run spent its calls and waiting time inspecting or changing the project, but it does not justify converting bytes into tokens. A concrete response to excessive repeated reads might be caching immutable results by run_id or improving context packing. You can then monitor the inspect share, p95 latency, and cache hit rate without recording the content that was read.

When Bash or Edit fails frequently, do not increase retries blindly. Restrict commands, validate arguments before the effect, and track error_rate by tool and tools_sha version. That gives you a way to roll back a problematic tool definition instead of blaming the model for a schema that changed underneath it.

An error gate in CI, without reading tokens

The 20% threshold below is an example of local policy, not an MCP constant. The job evaluates only tools/call events and never opens usage.json:

- name: Recusar taxa alta de erro nas tools
  shell: bash
  run: |
    python - <<'PY'
    import sys
    import duckdb

    errors, total = duckdb.sql("""
      SELECT count(*) FILTER (WHERE NOT ok), count(*)
      FROM read_ndjson('events.jsonl')
      WHERE schema = 'events.v1'
        AND mcp_method = 'tools/call'
    """).fetchone()

    error_rate = errors / total if total else 0.0
    print(f"tool_error_rate={error_rate:.3f} ({errors}/{total})")
    sys.exit(1 if error_rate > 0.20 else 0)
    PY

The harness must publish events.jsonl before this step; GitHub Actions cannot see tool calls on its own. In production, also export total, errors, and unexpected file absence as metrics. An empty file should not become an automatic pass when the run claims it used tools: validate the expected run count or require a completion marker.

Keep the gates orthogonal:

GateInputQuestion answered
tool-errorevents.jsonlDid tools fail beyond the limit?
cost_capusage.json or provider costDid tokens or spending exceed the cap?

A cheap run with 40% ToolError should fail the first gate. A correct but expensive run may pass it and fail the second. Combining both into an average produces an elegant number that decides nothing.

retry_max belongs to the harness

retry_max does not exist in either the specification or the SDK. It is a local policy applied by the harness when it receives is_error=true. Execution errors remain visible to the model so it can correct its arguments; protocol errors stay with the host and should not be presented as another tool attempt.

A simple boundary can be written like this:

async def call_with_local_retry(call_tool, request, retry_max: int = 1):
    # retry_max é política local; MCP não possui esse campo.
    for attempt in range(retry_max + 1):
        result = await call_tool(request)
        if not result.is_error:
            return result
        if attempt == retry_max:
            return result
        request = await revise_arguments_from_tool_error(request, result.content)

Use automatic retries only for read tools or operations proven to be idempotent. For Bash, Edit, and any other side effect, require a request_id, validate the intent, and reject the request with MCPError before the effect when policy does not allow it. After retry_max, record the final event and continue to the execute-verify-stop flow without a fourth attempt “just to confirm.” The execute-verify-stop guide covers that side-effect boundary in detail.

The safe way to observe retries is to include run_id, attempt, and the verification outcome without copying sensitive arguments. Monitor attempts per call, tools that exhaust the limit, and effects rejected before execution. If retries keep increasing without reducing is_error, fix the tool schema, description, or validation; raising retry_max only extends the diagnosis.

Pitfalls and verification

Before enabling the gate across the repository, run a controlled task that produces at least one success and one known ToolError. Check these points together:

  1. server/discover and tools/list calls do not appear as tools;
  2. get_author("Duna") produces ok=true and is_error=false;
  3. a missing title produces a result with is_error=true, not a JSON-RPC error;
  4. parameters rejected by policy produce error_channel="protocol" and no effect;
  5. the DuckDB query separates inspect from mutate and sums only local measurements;
  6. CI returns a nonzero status only when errors / total > 0.20;
  7. usage.json remains the only input to the token and provider-cost gate.

OpenTelemetry can complement the file with one span per message, but the default middleware does not send traces anywhere unless opentelemetry-sdk and an exporter are configured. If you adopt OTel, alert on export failures and missing spans; constructing MCPServer alone is not evidence that Jaeger or another backend received any data.

The recommendation is conditional but firm: adopt events.jsonl and the error gate when the harness controls the tools/call boundary, can correlate every run, and preserves events reliably. If you do not yet have a run_id, a serialized sink, or a stable definition of success, start in observation mode. Blocking pull requests with incomplete telemetry turns the guardrail into the incident.

Next step

Implement the middleware in observation mode first, force one valid call and one ToolError, and run the DuckDB query. Once the file is complete and correlated by run, enable the threshold in CI. Keep cost_cap where it belongs: reading usage.json, without assigning MCP a bill it never issued.

ai-agentsmcpdevex

// Continue.training — 次のステップ

Knowledge only counts when it becomes practice.

Go back to the article, run the examples, and share what you learned.

Explore more articles