Tracing JSON-RPC frames

An application log records what your code chose to record, which means it starts when a well-formed frame has already been parsed out of the transport and dispatched, and ends when your return value has been handed back for serialisation. A frame is one JSON-RPC message as it crosses the wire: a small JSON object carrying a method name, an id, and either parameters or a result. Everything that can go wrong to a frame outside those two points — a request that never arrived, a request that failed to parse, a response that never reached the socket — happens where your logging is not.

A protocol log closes that gap. It is one line per frame, in both directions, written by code that sits below dispatch and therefore cannot be skipped by a dispatch failure. Two fields in it do almost all the work: the request id, which is the protocol's only correlation key, and a timestamp, which is useful for durations measured by one clock and misleading for anything measured across two.

Your application log stops at the handler boundary#

The reason a server log comes back empty for a call that visibly happened is almost never that the server is broken in some deep way. It is that the events the log describes are bracketed by two events it did not observe.

A request that never arrived produces no log line, and there are several ordinary reasons a request never arrives — the client validated the arguments and declined to send it, the connection was already half-closed, the session identifier was rejected upstream by a proxy that answered with a 404 the client swallowed. A request that arrived but failed to parse produces no log line either, because dispatch never happened. A response your handler returned can fail to reach the wire: it can sit in a block-buffered stdout, it can be written to a socket whose peer stopped reading, it can be dropped by an SSE stream — server-sent events, the long-lived one-way HTTP channel the Streamable HTTP transport uses to push messages back to the client — that a load balancer closed at 60 seconds of idle. In every one of those cases the handler either did not run or ran successfully, and your log agrees with that.

It is worth being exact about what a server's application log does separate, because it is not nothing, and the gap is narrower and sharper than "the log is useless". A request that never arrived leaves no handler enter line. A handler that blocked leaves an enter with no exit. A response that was written and never read leaves an enter and an exit, which is character for character what a completely successful call leaves. So the log tells the first case from the second only by an absence, and it cannot tell the third from the fourth at all. Reasoning from an absence requires knowing the line would certainly have been written, and a dispatch failure is exactly the event that removes that certainty — a missing enter line is equally consistent with a frame that never arrived, a log level set wrong, a line lost in a rotation, and a request routed to a different replica. The distinction the log cannot draw under any circumstances is the one that decides ownership: between a response that reached the client and one that did not, it says the same thing twice.

On the server side, the cheapest version of a frame log does not require touching the server at all, because for a stdio transport you can put a process in the middle:

#!/usr/bin/env python3
"""tee-mcp: run a stdio MCP server with every frame logged to stderr."""
import subprocess, sys, threading, time

proc = subprocess.Popen(sys.argv[1:], stdin=subprocess.PIPE,
                        stdout=subprocess.PIPE, bufsize=0)

def pump(src, dst, direction):
    for line in iter(src.readline, b""):
        ts = time.monotonic()
        print(f"{ts:.6f} {direction} {len(line)}B {line[:400]!r}",
              file=sys.stderr, flush=True)
        dst.write(line)
        dst.flush()

threading.Thread(target=pump,
                 args=(sys.stdin.buffer, proc.stdin, "c->s"),
                 daemon=True).start()
pump(proc.stdout, sys.stdout.buffer, "s->c")

Point the client's command at tee-mcp node ./build/server.js instead of at the server directly and every frame in both directions lands on stderr with a monotonic timestamp and a byte count. For a Streamable HTTP server the same job is a middleware that logs method, id, direction and byte length before the body is handed to the framework's JSON parser. Either way the property that matters is that the log is written by code that cannot be skipped by a dispatch failure.

What two ids and four timestamps establish#

JSON-RPC gives you exactly one correlation key, and it is enough. Every request carries an id, every response carries the same id, and MCP forbids reusing an id within a session, so a matched pair is unambiguous even when six calls are in flight at once. Notifications carry no id at all, which is worth remembering before you go looking for the response to one.

Why the id and not something else is the part worth slowing down on, and the answer follows from the shape of the messages rather than from a convention anybody chose. A JSON-RPC response object carries the protocol version, the id, and either a result or an error. It does not carry the method name. The transport is duplex and the protocol permits several requests to be outstanding at the same time, so at the moment a response lands there is nothing inside it saying which call it answers — the method is gone, and arrival order is no guide either, since a cheap tool dispatched second can answer before an expensive one dispatched first. The id is the only thing left. A log that records direction and method but drops the id can therefore tell you what was called and cannot tell you what answered, and those are two different artefacts: one is a list of events, the other is a set of pairs.

Uniqueness is what makes that pairing a join rather than a guess. Because an id is not reused inside a session, at most one outstanding request can match a given response, so a match is the only pair available and not merely the most plausible one. That is what allows the two logs to be combined mechanically — a dictionary keyed on id, or sort and join on the id column — rather than read side by side by a person scrolling two terminals. It also means an unmatched frame is a finding rather than noise, once the notifications, which never match anything, have been set aside.

Here is a trace of a stalled call, with the client's log on the left of each block and the server's on the right, joined on id 47:

client  09:41:03.118  c->s  req  id=47  tools/call search_invoices  312B
server  09:41:03.121  c->s  req  id=47  tools/call search_invoices  312B
server  09:41:03.124  handler enter  search_invoices
server  09:41:03.196  handler exit   search_invoices  rows=418
server  09:41:03.204  s->c  res  id=47  41827B
client  ————          (nothing)
client  09:41:07.550  c->s  ntf        notifications/cancelled  ...

The server emitted a response of 41,827 bytes for id 47, eighty-three milliseconds after the request arrived at it. The client never logged receiving it. That single asymmetry is the whole diagnosis: the bytes left one process and were not consumed by the other, so the fault is in the client's read path or in the transport between them, and no amount of reading the query handler was ever going to find it.

Both ends of that eighty-three milliseconds were stamped by the same clock, which is what makes the subtraction mean anything: the request was read at 09:41:03.121 and the response was written at 09:41:03.204, and both readings came from the server. Inside that span the server stamped two more events, and the three intervals they cut divide it with nothing left over — three milliseconds from reading the frame to entering the handler, seventy-two milliseconds inside the handler, and eight milliseconds from the handler returning to the response reaching the transport. Those three add back to eighty-three exactly. The absence of a residual is the finding rather than a tidy detail: every millisecond the server spent on request 47 is attributed to a named stage, so no unexplained pause is hiding anywhere inside it, and whatever consumed the interval that follows consumed it somewhere else.

That still leaves one thing the server's log cannot say, and it cannot say it however well instrumented it is. Writing a response hands bytes to the transport, and that call returns once the operating system has accepted them into a buffer, not once the peer has read them. Success at the writing end is a statement about a local buffer. The event that matters — a reader on the far side consuming the frame — happens in another process and is recorded, if anywhere, in another log. So a one-sided log localises nothing about delivery however complete it is, while a pair of them localises a stall to one of four places, and the id is what makes the pair a pair.

Four positions are possible and the trace distinguishes them cleanly:

The fourth row is the one people forget exists. A response that arrived, parsed and was rendered — and after which the agent still did nothing useful — is not a protocol failure at all, and it gets investigated by running the agent and watching, which is the loop chapter 1 set against the raw protocol.

Four is the count because the tree closes rather than because four cases came to mind. Ask three binary questions in order: did the request frame reach the server, did a response frame leave it, did the client log that response arriving. Three such questions branch to eight leaves, and half of them do not exist — a request that never arrived has no response to ask about, and a response never written has no arrival to ask about — so those branches collapse and exactly four leaves remain. The rows are those leaves. What the closure buys is a question you never have to ask. A trace matching none of the four is not evidence of a fifth failure mode; it is evidence that one of the two logs is incomplete, and the reasons for that are ordinary ones: a frame log switched on after the run began, a client that logs only the frames it managed to parse, a proxy that answered on the server's behalf and left no line in either.

None of those four rows can be produced by the instruments people reach for first, and it is worth saying so, because those instruments answer confidently. A health endpoint returning 200 says that a different HTTP request, on a different code path, got a response; it touches no session state, so it can report on none. A process that is still running says the operating system has not reaped it, which stays true when the task reading the transport has died and left the socket open behind it. A connection the kernel still lists as established says two kernels agree a connection exists, which is a fact about the operating system rather than about either program's willingness to read from it. Every one of those stays green while a session is dead, so the defence they are taken to provide — we would have been paged if the session had failed — is not a defence at all. A frame log is the one instrument on that list that observes the session, for the plain reason that frames are what a session is made of.

Row three has a shortlist, and most of it is framing#

When the trace puts the fault between a written response and an unread one, the candidate causes are few enough to enumerate, and on stdio they cluster around the same idea: the stream carries frames, not bytes, and anything that disturbs the frame boundaries breaks the reader rather than the writer. The framing layer — the code that decides where one message ends and the next begins in a stream of bytes — is where all four of the following land.

The most common is stdout contamination. A stdio server owns its standard output; every line on it must be a complete JSON-RPC message, and a single print("loading config…") — yours, or one inside a dependency, or a deprecation warning from the runtime — inserts a line the client's parser cannot decode. Some clients skip the bad line and continue; some log an error and continue; some tear down the connection. The failure appears at startup or at the first call that triggers the offending code path, and the server's own log looks perfect because from its point of view everything was written successfully. Diagnostics on a stdio server belong on stderr, without exception.

Buffering is the second. Standard output is line-buffered when attached to a terminal and block-buffered when attached to a pipe, so a server that behaves correctly when you run it by hand can hold a 900-byte response in an 8 KB buffer indefinitely once a client launches it as a subprocess. The trace signature is distinctive: the server logs the response written, the client sees nothing, and then several responses arrive at once when the buffer eventually fills or the process exits.

The third is embedded newlines. A message that contains a raw newline inside it is two frames as far as a line-splitting reader is concerned, and both halves are invalid JSON. This is why the specification forbids them and why serialisers must escape them, and it is why a tool that returns multi-line text works fine until someone's serialiser is replaced with one that pretty-prints. Maximum line length is the fourth, and it is the one in the trace above. None of the four produces an error on the writing side, which is exactly why the log has to come from both.

Timestamps are for durations on one side, not for latency across two#

Both logs above carry times, and it is tempting to subtract 09:41:03.118 from 09:41:03.121 and call the transport latency three milliseconds. On one machine with one clock that is roughly true. Across two machines it is arithmetic on two unrelated clocks: NTP-disciplined hosts in the same datacentre typically agree to within a few milliseconds, hosts across regions to within tens, and a laptop that has been asleep or a container whose clock was never disciplined can be off by seconds — which is enough to produce a trace where the response appears to precede the request. Treat cross-host differences as unreliable and use timestamps for what they are good at, which is intervals measured by one clock: how long the handler took, how long the client waited, how long the gap was between the last frame and the moment the run went quiet.

Those intervals answer questions the id alone cannot. A server that logs handler enter and no handler exit for four minutes has a handler that is blocked, and the next question is on what — a lock, a database call with no timeout of its own, an outbound HTTP request to a service that is itself hanging. A server that logs enter and exit 80 milliseconds apart, then writes the response frame nine seconds later, has a serialisation or flush problem rather than a slow handler. A client that logs the request and then logs nothing for six minutes before emitting notifications/cancelled, the message by which a client tells a server it has stopped waiting for a request, has a deadline that did eventually fire, which tells you the deadline exists and how long it is.

The gap between the last frame and the silence is also how you tell a stall from a slow success. Both look identical to a person watching a spinner, and they are not the same defect: a tool that takes 95 seconds because it is scanning an unindexed table is a performance problem with a straightforward fix, and a tool that has stopped forever is a liveness problem. Nothing in the rendered transcript distinguishes them, and thirty seconds of protocol log does.

The script earlier in this chapter reads time.monotonic() rather than a wall-clock time, and that line is doing the work this section describes. A monotonic clock counts forward from an origin the operating system picks at boot and is guaranteed never to jump backwards, which is exactly the property an interval measurement needs: a wall clock stepped by NTP in the middle of a measurement can turn two honest readings into a negative duration. The same property that makes it safe within one host makes it useless across two, since the origin is arbitrary and no two hosts share one. The two clocks fail in opposite directions — a wall clock is comparable between hosts and unreliable within one, a monotonic clock is reliable within one host and incomparable between two — and nothing in an ordinary deployment hands you a single reading that is both. That is why the diagnosis above rests on an asymmetry in what was logged rather than on a difference between two timestamps.

Tracing is not free, and it is not always the right instrument#

Full frame logging on a busy server is a real cost. A production server handling 40 tool calls a second with an average response of 12 KB writes roughly half a megabyte per second of log if you record payloads, which is 40 GB a day, and the write itself is synchronous in the naive implementation. The version that survives contact with production logs the metadata unconditionally — direction, method, id, byte length, timestamp — and the payload only under a sampling rule or a debug flag scoped to one session. That is usually enough, because the diagnosis above turned entirely on metadata; the bodies were never read.

Both of those figures are one multiplication each, and running them by hand is what turns a policy into something you can defend. Forty calls a second at twelve kilobytes a call is four hundred and eighty kilobytes a second, which is where "roughly half a megabyte" comes from, and multiplying that by the number of seconds in a day gives the daily total. The inbound direction barely moves it: the trace earlier in this chapter pairs a request of a few hundred bytes with a response of forty-odd kilobytes, so logging both directions costs very nearly what logging responses alone costs, and there is no saving to be had by dropping one. The order of the rounding is worth keeping straight as well. Multiply the unrounded per-second figure by the seconds in a day and round once at the end; take the rounded half-megabyte and multiply that instead and the answer drifts upward, which is how an estimate quietly acquires a digit it never earned.

Metadata also reaches further than "which side stopped", and this chapter's own numbers show how far. The response frame's metadata carries a byte count and the handler line carries a row count, and dividing 41,827 by 418 gives just over a hundred bytes per record. That division is the right one because the ceiling and the byte count are both measured on the whole frame, envelope included, so each record carries its share of the envelope with it. Dividing the client's 16,384-byte line ceiling by that per-record size gives a record count a little above 160, which is where the threshold in the scenario comes from; neither figure was measured, and both fell out of two integers a metadata-only log records for free. A threshold obtained that way predicts rather than describes, which is what makes it worth having: it says in advance which customers will trip the defect, so "intermittent" becomes testable by taking one customer above the line and one below it. The hedge in "about" is load-bearing too, since the per-record size is an average over one result set and a customer whose invoices carry longer subject lines crosses the ceiling sooner.

There is also a whole class of failure that a trace is close to useless against, and reading traces looking for it will actively mislead. When the fault is that a message was never supposed to be sent — because the two sides negotiated a capability away at connection time — the trace is complete, conforming and entirely uninteresting, and someone scanning it for an anomaly will find none and conclude the report was invalid. Chapter 5 is about that failure and its two neighbours.

A frame log is worth its cost because it turns a question about four components into a question about one, and it does so with two fields that were already in the protocol. The id says which request a frame belongs to; the direction and the byte count say whether it moved. Everything else in the diagnosis above followed from noticing that a response existed on one side of the wire and not on the other.

The more immediate limit is that a trace answers "which side stopped" and stops there. It does not say what was supposed to stop waiting, or who was entitled to wait longer, or what should have happened to a request whose caller had already given up. The notifications/cancelled at the end of the trace above arrived four and a half seconds after the request; nothing here explains where that number came from, what would have extended it, or what the server was supposed to do when it landed. Those are questions about deadlines and connection state rather than about frames.