Tutorial

MCP Fundamentals: Observability

Production asks the same questions of an MCP server as of any distributed system: what ran, how long, did it fail. Extend the complete, audience-protected notes server with one deliberately slow tool, watch MCP-standardized log and progress messages stream beside its result, then export FastMCP's OpenTelemetry spans to Jaeger and propagate a client-chosen trace ID across the authenticated protocol boundary.

Three modules in, the notes server speaks the MCP protocol, exposes tools, resources, and prompts, and accepts only notes.access tokens bound to its audience. Production's first question is the unglamorous one: when it misbehaves at 2am, what do I look at? The answer has the familiar service skeleton - logs, latency, distributed traces - plus MCP's standardized messages and correlation semantics on the response stream.

This module builds both layers hands-on: first the protocol-native stream

  • log lines and progress updates a tool emits while it runs, arriving as SSE frames your curl can watch in real time - then the OpenTelemetry layer, where the framework already emits spans for every protocol exchange and you wire them to Jaeger, including the spec's trace-context propagation that lets a client-chosen trace ID thread through the server.

Each tutorial starts a fresh playground; disks are not carried from one module to the next. To make the series cumulative, this play seeds server-obs.py with Module 3's canonical, complete protected server and seeds the same Keycloak realm. You will add only the observability slice.

Prerequisites

  • Module 1, Module 2, and Module 3, or equivalent familiarity with MCP sessions, primitives, and Bearer-protected calls. (Context is introduced here, not Module 2.)
  • Module 1's curl fluency - the SSE stream reading habit pays off here.
  • curl, jq, and a tolerance for hex IDs.
The three observability layers of an MCP server - the protocol stream, OpenTelemetry spans flowing to Jaeger, and plain server logs

Three layers, one story: the protocol stream tells the client what is happening right now; spans tell you what happened; plain logs catch what neither can.

The protocol's own telemetry channel

Everything in this section comes from one insight you already own from module 1 (MCP is Just HTTP POSTs): a tools/call POST can be answered with an SSE stream, and nothing in the spec says that stream must carry only the final result.

If your SSE is rusty, here it is in one breath: Server-Sent Events is an ordinary HTTP response that refuses to end. The server answers the POST immediately with Content-Type: text/event-stream, then keeps the connection open and pushes small text events down it while the tool works. Each event is a two-line block - event: names the frame type, data: carries the JSON-RPC payload - and curl -N just means "print each event the moment it arrives, do not buffer". Keep those two roles apart: SSE is the pipe, frames are the cargo traveling inside it.

While the tool runs, the server can interleave three kinds of frames:

  • log messages - notifications/message frames with a severity level, a logger name, and free-form data (RFC 5424 severities, from debug to emergency). They answer what is the tool doing right now.
  • progress updates - notifications/progress frames. They answer how far along is it, and they are tied to the request via a token the caller supplies - why that matters in a moment.
  • and finally the JSON-RPC result.

FastMCP exposes this as a Context object your tool receives as a parameter. ~/mcp-lab/server-obs.py already contains Module 3's complete server: audience and scope validation, add_note, note_stats, note_get with ToolError, static and templated resources with ResourceError, review_notes, and tool annotations. Do not rewrite that inherited code. Add asyncio and Context to its imports:

import asyncio
from fastmcp import Context, FastMCP

Then insert this one focused tool before the if __name__ == "__main__"

@mcp.tool(annotations={"readOnlyHint": True, "openWorldHint": False})
async def slow_report(ctx: Context, steps: int = 3) -> dict:
    """A deliberately slow audit that reports progress and logs as it works.

    Args:
        steps: How many audit steps to run (1-5).
    """
    results = []
    for i in range(1, steps + 1):
        await asyncio.sleep(0.5)
        await ctx.info(f"audit step {i}/{steps}: scanning notes")
        if i % 2 == 0:
            await ctx.debug(f"step {i}: cache hit, no rescan needed")
        await ctx.report_progress(progress=i, total=steps)
        results.append(f"step {i} ok")
    return {"audit": results, "total": steps}

Three details that make this file more than a loop:

  • ctx: Context as the first parameter - the framework injects it; it never appears in the tool's inputSchema, so the model never sees it.
  • ctx.info(...) and ctx.debug(...) become notifications/message frames on the wire.
  • ctx.report_progress(...) is opt-in from the caller's side - the ticks only flow if the request carries a _meta.progressToken. Why that is good design in a moment.

Start it and run the slow tool with streaming enabled. Note the _meta.progressToken in the request below: the caller invents the label tok-1 and ships it as a return address for progress ticks - watch it come back in the stream:

cd ~/mcp-lab
uv run --with 'fastmcp==4.0.0' python server-obs.py
INFO     Starting MCP server 'notes-obs' with transport 'http' on http://127.0.0.1:8000/mcp
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
Terminal 2

Module 3's OAuth dance is condensed into auth-env.sh: sourcing it mints a fresh notes-cli token with HTTP Basic and the RFC 8707 resource parameter. The MCP calls remain expanded so the two boundaries stay visible: Authorization proves access on every request; mcp-session-id carries protocol state after initialization.

source ~/mcp-lab/auth-env.sh
SID=$(curl -sD- -o /dev/null -X POST "$MCP_URL" \
  -H "Authorization: Bearer $TOK" \
  -H 'Content-Type: application/json' \
  -H 'Accept: application/json, text/event-stream' \
  -d '{"jsonrpc":"2.0","id":1,"method":"initialize","params":{"protocolVersion":"2025-06-18","capabilities":{},"clientInfo":{"name":"curl","version":"1.0"}}}' \
  | grep -i '^mcp-session-id:' | tr -d '\r' | cut -d' ' -f2)
curl -s -o /dev/null -X POST "$MCP_URL" \
  -H "Authorization: Bearer $TOK" \
  -H 'Content-Type: application/json' -H 'Accept: application/json, text/event-stream' \
  -H "mcp-session-id: $SID" \
  -H 'MCP-Protocol-Version: 2025-06-18' \
  -d '{"jsonrpc":"2.0","method":"notifications/initialized"}'
curl -s -N -X POST "$MCP_URL" \
  -H "Authorization: Bearer $TOK" \
  -H 'Content-Type: application/json' -H 'Accept: application/json, text/event-stream' \
  -H "mcp-session-id: $SID" \
  -H 'MCP-Protocol-Version: 2025-06-18' \
  -d '{"jsonrpc":"2.0","id":3,"method":"tools/call","params":{"name":"slow_report","arguments":{"steps":2},"_meta":{"progressToken":"tok-1"}}}' \
  | tee ~/mcp-lab/telemetry.sse
event: message
data: {"jsonrpc":"2.0","method":"notifications/message","params":{"level":"info","data":{"msg":"audit step 1/2: scanning notes","extra":null}}}

event: message
data: {"jsonrpc":"2.0","method":"notifications/progress","params":{"progressToken":"tok-1","progress":1.0,"total":2.0}}

event: message
data: {"jsonrpc":"2.0","method":"notifications/message","params":{"level":"info","data":{"msg":"audit step 2/2: scanning notes","extra":null}}}

event: message
data: {"jsonrpc":"2.0","method":"notifications/message","params":{"level":"debug","data":{"msg":"step 2: cache hit, no rescan needed","extra":null}}}

event: message
data: {"jsonrpc":"2.0","method":"notifications/progress","params":{"progressToken":"tok-1","progress":2.0,"total":2.0}}

event: message
data: {"jsonrpc":"2.0","id":3,"result":{"content":[{"text":"{\"audit\":[\"step 1 ok\",\"step 2 ok\"],\"total\":2}","type":"text"}],"isError":false,"structuredContent":{"audit":["step 1 ok","step 2 ok"],"total":2}}}

With curl -N (unbuffered) you are watching this happen live: two log lines and two progress ticks streamed out of the running tool, then the answer, all inside one HTTP response. HTTP POST responses can stream too; MCP's contribution is standardizing the JSON-RPC message types and the correlation semantics clients use while that stream is open.

Progress is opt-in - and that is the design

Two kinds of frames just streamed past you, and they are easy to blur together. Split them first: they answer different questions and obey different switches.

  • Log frames (notifications/message, emitted by ctx.info and ctx.debug) answer what is the tool doing right now. The caller controls their volume with logging/setLevel - that is the next section.
  • Progress frames (notifications/progress, emitted by ctx.report_progress) answer how far along is it. Whether they exist at all is decided per request by the caller, with _meta.progressToken.

Prove the second switch: run the same call without the progress token - and without the tee, so telemetry.sse keeps the complete stream the grader checks.

curl -s -N -X POST "$MCP_URL" \
  -H "Authorization: Bearer $TOK" \
  -H 'Content-Type: application/json' -H 'Accept: application/json, text/event-stream' \
  -H "mcp-session-id: $SID" \
  -H 'MCP-Protocol-Version: 2025-06-18' \
  -d '{"jsonrpc":"2.0","id":3,"method":"tools/call","params":{"name":"slow_report","arguments":{"steps":2}}}'
event: message
data: {"jsonrpc":"2.0","method":"notifications/message","params":{"level":"info","data":{"msg":"audit step 1/2: scanning notes","extra":null}}}

event: message
data: {"jsonrpc":"2.0","id":3,"result":{...}}

Read the asymmetry carefully: the progress ticks are gone, but the log lines still arrive and so does the result. Exactly one frame type obeyed the switch - the logs were never gated on it.

Why is progress the picky one? Because a progress tick is addressed mail, and the token is its return address. The caller invents a label - tok-1 - and ships it in _meta with the request. Every tick the server sends carries that exact label back, so a client with five tool calls in flight knows which tick belongs to which call. No token in the request means no return address - nobody to address the update to - so the server sends none. Compare with REST: the server decides whether you get telemetry. MCP flips it: the client declares, per request, which updates it wants to receive and how to correlate them. A headless batch job skips the token and receives pure results; a chat UI sends a token per call and renders a progress bar from the ticks.

The level dial

Log volume is also client-controlled. The logging/setLevel request tells the server the minimum severity to ship:

curl -s -X POST http://127.0.0.1:8000/mcp \
  -H "Authorization: Bearer $TOK" \
  -H 'Content-Type: application/json' -H 'Accept: application/json, text/event-stream' \
  -H "mcp-session-id: $SID" \
  -H 'MCP-Protocol-Version: 2025-06-18' \
  -d '{"jsonrpc":"2.0","id":4,"method":"logging/setLevel","params":{"level":"info"}}'
event: message
data: {"jsonrpc":"2.0","id":4,"result":{}}

An empty result - the protocol's way of saying "acknowledged". Now re-run slow_report: the info lines still arrive, the debug line ("cache hit") is filtered server-side before it ever leaves. Severity levels follow RFC 5424 (the syslog scale): debug, info, notice, warning, error, critical, alert, emergency - and a noisy tool can no longer flood a quiet caller.

Timeline of one tools/call SSE stream showing interleaved log messages, progress notifications, and the final result

One POST, six frames, in order. MCP gives the streamed response a shared message vocabulary and request-correlation contract.

2026 compatibility: protocol logging is deprecated

This lab deliberately pins protocol version 2025-06-18. Under that protocol, notifications/message and logging/setLevel are client-facing compatibility behavior and are correct to exercise. In the 2026-07-28 revision, protocol Logging is deprecated in favor of OpenTelemetry, logging/setLevel disappears, and log level moves to per-request _meta. Keep the compatibility path for pinned 2025 clients, but build operational collection around OpenTelemetry.

Spans: what your framework already emits

FastMCP emits OpenTelemetry spans natively - but only writes them if you configure an SDK and an exporter. First, look at what the spans contain by pointing them at a collector. Jaeger's all-in-one image gives you a collector, storage, query API, and UI in one container; the playground already started it (UI on port 16686, OTLP on 4318).

Add the four-line SDK block at the top of server-obs.py - above the FastMCP import, so the provider exists before any span is created:

from opentelemetry import trace
from opentelemetry.exporter.otlp.proto.http.trace_exporter import OTLPSpanExporter
from opentelemetry.sdk.resources import Resource
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor

provider = TracerProvider(resource=Resource.create({"service.name": "notes-mcp"}))
provider.add_span_processor(
    BatchSpanProcessor(OTLPSpanExporter(endpoint="http://127.0.0.1:4318/v1/traces"))
)
trace.set_tracer_provider(provider)

The direct dependencies are pinned to metadata resolved for this module. OpenTelemetry's MCP/GenAI semantic conventions are still Development and version-sensitive (opentelemetry-semantic-conventions==0.65b0 is resolved transitively here), so do not treat individual attribute names as a stable production contract yet.

uv run --with 'fastmcp==4.0.0' \
  --with 'opentelemetry-sdk==1.44.0' \
  --with 'opentelemetry-exporter-otlp-proto-http==1.44.0' \
  python server-obs.py
INFO     Starting MCP server 'notes-obs' with transport 'http' on http://127.0.0.1:8000/mcp
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)

No other code changes - the framework already emits spans around every protocol operation; the SDK block merely gives them somewhere to go. Now prove the whole pipeline in two moves: generate a span, then ask Jaeger what it received.

Move 1 - generate a span. The restart invalidated the old session. Source the helper to refresh the five-minute token, then run the familiar initialize, notify, call choreography. Every MCP request carries Bearer; every post-initialize request also carries the negotiated protocol header.

source ~/mcp-lab/auth-env.sh
SID=$(curl -sD- -o /dev/null -X POST "$MCP_URL" \
  -H "Authorization: Bearer $TOK" \
  -H 'Content-Type: application/json' \
  -H 'Accept: application/json, text/event-stream' \
  -d '{"jsonrpc":"2.0","id":1,"method":"initialize","params":{"protocolVersion":"2025-06-18","capabilities":{},"clientInfo":{"name":"curl","version":"1.0"}}}' \
  | grep -i '^mcp-session-id:' | tr -d '\r' | cut -d' ' -f2)
curl -s -o /dev/null -X POST "$MCP_URL" \
  -H "Authorization: Bearer $TOK" \
  -H 'Content-Type: application/json' -H 'Accept: application/json, text/event-stream' \
  -H "mcp-session-id: $SID" \
  -H 'MCP-Protocol-Version: 2025-06-18' \
  -d '{"jsonrpc":"2.0","method":"notifications/initialized"}'
curl -s -X POST "$MCP_URL" \
  -H "Authorization: Bearer $TOK" \
  -H 'Content-Type: application/json' -H 'Accept: application/json, text/event-stream' \
  -H "mcp-session-id: $SID" \
  -H 'MCP-Protocol-Version: 2025-06-18' \
  -d '{"jsonrpc":"2.0","id":5,"method":"tools/call","params":{"name":"add_note","arguments":{"text":"first traced note","tag":"otel"}}}'
event: message
data: {"jsonrpc":"2.0","id":5,"result":{"content":[{"text":"{\"saved\":1,\"total\":1}","type":"text"}],"isError":false,"structuredContent":{"saved":1,"total":1}}}

The protocol exchange is familiar, now with Module 3's authorization boundary intact. What is new is invisible: for each request, FastMCP wrapped the handling in an OpenTelemetry span, and the four lines you added at the top of the file exported it over OTLP to Jaeger. You wrote no logging statements and created no spans by hand - you only gave the spans somewhere to go.

Move 2 - ask Jaeger what it received. Jaeger's all-in-one serves two things on port 16686: the web UI you could open in a browser, and a plain JSON query API that curl can drive - the API is what we will use. First question: which services have reported traces to you?

sleep 6
curl -s 'http://127.0.0.1:16686/api/services' | jq -c '.data'
["jaeger-all-in-one","notes-mcp"]

Read the answer: jaeger-all-in-one is Jaeger tracing its own collector; notes-mcp is your server - it has become a service in a tracing backend. (The sleep 6 is not about the tool call - it waits out the exporter: BatchSpanProcessor buffers spans and flushes every five seconds by default.)

Second question: what exactly is inside those traces? Ask Jaeger for recent traces from notes-mcp; the jq keeps only the tools/call spans and, within them, only the tags whose names start with mcp. or gen_ai.:

curl -s 'http://127.0.0.1:16686/api/traces?service=notes-mcp&limit=20' \
  | jq -c '[.data[].spans[] | select(.operationName | startswith("tools/call")) | {operationName, tags: [.tags[] | select(.key | test("mcp\\.|gen_ai\\.")) | {key, value}]}]' \
  | head -c 900
[{
  "operationName": "tools/call add_note",
  "tags": [
    {"key": "gen_ai.tool.name", "value": "add_note"},
    {"key": "mcp.method.name", "value": "tools/call"},
    {"key": "mcp.protocol.version", "value": "2025-06-18"},
    {"key": "mcp.session.id", "value": "8e5a94041d3841d08e3c333427d76e3f"},
    {"key": "span.kind", "value": "server"}
  ]
}]

Read that as an SRE would:

  • operationName: "tools/call add_note" - what ran.
  • gen_ai.tool.name - the Development GenAI semantic-conventions tag; it is useful today but may move as those conventions stabilize.
  • mcp.session.id - the correlation key to module 1's session header.
  • mcp.protocol.version - which dialect was spoken.
  • span.kind: server - standard OTel: this span served a request.

And initialize shows up as its own span. Latency, error status, throughput per tool - all of it is now a Jaeger query away, which is exactly what the deprecation notice above meant: OpenTelemetry is where MCP's operational story is headed.

Distributed tracing across the protocol boundary

Here is the piece that makes MCP observability genuinely interesting. Because the caller is often another program (or another LLM pipeline), the interesting question is not "what did the server do" but "how did this user request traverse host, server, and upstream APIs". The answer is trace-context propagation - and the MCP spec defines exactly how (SEP-414): the client puts a W3C traceparent string in _meta, and the server's span joins that trace instead of starting its own.

You can prove it with curl, because you can be the upstream system. The session from Move 1 is still active; refresh TOK and initialize again first if five minutes have passed.

TRACE_ID=$(openssl rand -hex 16)
SPAN_ID=$(openssl rand -hex 8)
TP="00-$TRACE_ID-$SPAN_ID-01"
echo "your trace: $TRACE_ID"
curl -s -o /dev/null -X POST "$MCP_URL" \
  -H "Authorization: Bearer $TOK" \
  -H 'Content-Type: application/json' -H 'Accept: application/json, text/event-stream' \
  -H "mcp-session-id: $SID" \
  -H 'MCP-Protocol-Version: 2025-06-18' \
  -d "{\"jsonrpc\":\"2.0\",\"id\":9,\"method\":\"tools/call\",\"params\":{\"name\":\"add_note\",\"arguments\":{\"text\":\"propagated trace\",\"tag\":\"otel\"},\"_meta\":{\"traceparent\":\"$TP\"}}}"
sleep 6
curl -s "http://127.0.0.1:16686/api/traces/$TRACE_ID" \
  | jq -c '{found: (.data | length), spans: [(.data[0].spans // [])[].operationName]}'
your trace: b082492b19513d8ebf1312340427e14a
{"found":1,"spans":["tools/call add_note"]}

You chose a random 128-bit trace ID, and the server's span - created inside a framework you did not modify - landed under it. That is the whole contract: traceparent in, server-side child spans out, same trace. A real host does the identical thing for every model call, so one Jaeger waterfalls shows: model call → tool selection → tools/call → server work. The 02222222 debug story becomes a picture.

Flow diagram from curl with a traceparent through the FastMCP server span out over OTLP into Jaeger's UI and API

From a raw curl command to a queryable trace, with the spec's _meta propagation carrying your trace ID across the protocol boundary.

What to actually watch in production

With both layers in place, a REST developer's operational instincts transfer almost unchanged:

  • Latency per operation. Spans give you p50/p99 per tools/call tool - the MCP equivalent of per-endpoint latency dashboards.
  • In-band errors are invisible to status-code dashboards. Module 1's isError: true results ride inside HTTP 200s - so 5xx-based alerting misses them. Alert on span status (FastMCP records tool errors on the span) and on tool-result error flags, not HTTP codes alone.
  • Session churn. mcp.session.id tags let you follow one caller's whole conversation; 404-after-DELETE patterns (module 1) show up as session restart storms - the same metric session-tracking gives you in web apps.
  • The stream is part of the story. Long-lived SSE responses are long-lived HTTP requests; watch connection duration and open-stream counts, exactly as you would for websockets.
  • Plain logs still matter. Uvicorn's access log lines (every frame you have seen scroll in Terminal 1) plus stderr logging for framework-internal failures. Protocol logging tells the client; stderr tells you; spans tell your dashboards.

Summary

You now have the series' complete server in one process: the MCP protocol; tools, resources, and prompts; audience-bound notes.access authorization; and observability. The slow tool wrote log and progress messages into its authenticated response stream; the caller correlated progress with a token; FastMCP's spans reached Jaeger; and _meta propagated a client-chosen trace ID. Protocol logging remains client-facing compatibility behavior for the pinned 2025 protocol, while OpenTelemetry is the durable operational path.

Reminder of the single tools/call stream with interleaved telemetry frames

The frame timeline from earlier in the module - now read it as: one request, one trace, and a client-controlled channel, all at once.

That closes the series loop. Every module started from a fresh play and seeded the canonical code from its predecessor rather than relying on preserved disk state. You began with one JSON-RPC POST; you end owning the protocol, all three server primitives, audience-bound auth, and observability in one cumulative server.

Where to go from here:

About the Author

Alfonz Bakarbessy

Alfonz Bakarbessy

Find this author online

More tutorials you might like

Harden Access to OpenClaw with Pomerium (cover image)

Harden Access to OpenClaw with Pomerium

Put OpenClaw, a self-hosted AI assistant with shell and file access, behind a web route and an SSH route, both gated by the same identity and Pomerium's context-aware policy. OpenClaw runs in trusted-proxy mode, trusting signed identity headers instead of its own login, while Pomerium's native SSH proxy signs short-lived certificates for shell access.

Learn by doing, not just by reading or watching

Sign up for a free account to start a VM playground right on this page, track your progress, and get notified about new learning materials.

Sign up for free