Log each MCP POST's JSON-RPC method and timings

[brianglass]

Why

After #241 deployed, Claude clients still stall on one POST /mcp per connection: 4 of the first 7 claude.ai requests on the new revision took exactly 21s, with the same 457-byte response as before. Switching from SSE to JSON should have changed the reply's size and didn't, so #241's unclosed-stream theory was wrong. None of ~30 hand-built probes reproduce it, and Cloud Run's request log doesn't show the JSON-RPC method or where the time goes.

What

• mcp_svc/request_log.py wraps the MCP app and prints one JSON line per POST. Cloud Run turns these into a searchable jsonPayload. Each line has:
  • The message: JSON-RPC method, id, tool name, and the names of the params and _meta keys. Argument values are never logged, so search text doesn't end up in the logs.
  • Headers: Accept, Content-Type, Content-Length, Transfer-Encoding, MCP-Protocol-Version and User-Agent, plus whether Mcp-Session-Id, Last-Event-ID, Origin and Authorization are present (presence only, no values).
  • Trace id: the Cloud Run trace id, so each line can be joined to its request-log entry.
  • Timings: when the body finished arriving, when the response started and finished, and when the client disconnected.
  • Slow requests: a "stage": "slow" snapshot after 5s, because a request Cloud Run abandons at its timeout may never log "done".
• orthocal/asgi.py: wraps the MCP app and corrects the json_response comment, which claimed Answer MCP POSTs with plain JSON instead of an SSE stream #241 fixed the stalls. json_response=True itself stays; it's harmless.

The log volume is about 3k lines a day at current traffic. Once the cause is found, the wrapper can come out or move to sampling.

After deploy

gcloud logging read 'jsonPayload.mcp_request_log=true AND jsonPayload.stage="slow"' --limit=50 --format=json

For each stall this will show:

• No body_complete_ms: the client never finished sending the body.
• body_complete_ms but no response_start_ms: the handler never answered.
• response_complete_ms present: the reply was finished but the connection stayed open.

Test plan

• New unit tests: method, tool and _meta keys are logged and argument values aren't; trace id is captured; the slow snapshot fires; batch and unparseable bodies are handled; exceptions are logged and re-raised; non-POST and lifespan requests pass through untouched
• Local uvicorn server prints one line per POST with the expected fields
• Full suite passes (224 tests, 1 skipped)

🤖 Generated with Claude Code