Skip to content

feat(mcp-server): log the initialize handshake - #4299

Merged
gilgardosh merged 4 commits into
mainfrom
feat/mcp-log-initialize-handshake
Aug 27, 2026
Merged

feat(mcp-server): log the initialize handshake#4299
gilgardosh merged 4 commits into
mainfrom
feat/mcp-log-initialize-handshake

Conversation

@gilgardosh

Copy link
Copy Markdown
Collaborator

Why

The connector went blind between Aug 18 and Aug 26 — every tool returned its summary line and no
rows. #4295 fixes the cause (rows lived only in structuredContent, a field a client may ignore).

This PR addresses the second problem that incident exposed: the server had no idea the client
had changed.

Establishing that it was the client took a rollback test — checking out e31e8066, the commit
that demonstrably worked on Aug 18 including a successful tag write, and running it today reproduces
the failure exactly. Same commit, same server, opposite outcome. Confirming it then meant reading
Claude Desktop's own log directory:

Date Log file Event vocabulary Outcome
Aug 10 main.log Making remote MCP tool call: accounter_get_chargesRemote tool call succeeded rows arrived
Aug 26 claude.ai-web.log [MCP] tool_approval_gate {"toolName":"Accounter:accounter_search_charges",…} rows missing

None of that should have required someone's ~/Library/Logs. initialize (handler.ts) never read
request.params and never logged, so there was no record of the client's name, its version, the
protocol revision it asked for, or the capabilities it declared. The connector already logs every
tool call and every auth failure — the handshake was the one hop with no trace.

What

Every initialize emits one structured line tagged event: "mcp_initialize", joining tool_call
as the second selectable event:

Field Why
clientName, clientVersion the fields that date a client-side behaviour change
requestedProtocolVersion / servedProtocolVersion what was asked vs what we answered
protocolVersionMismatch the one field worth alerting on
clientCapabilities names only, sorted — values are unbounded and caller-supplied
userId, correlationId matches tool_call, so a session joins across both events

Three decisions worth reviewing

Logged from dispatchMcpRequest, not from the case 'initialize' that builds the response.
handleRpcRequest is the pure, env-free half and takes only the request — it has neither the caller
nor the correlation id to log. Delegating to it afterwards keeps the response built in exactly one
place, so the two cannot drift. The sync handleMcpBody path has no production call sites and stays
silent, which conveniently leaves its existing test of the pure response shape untouched (there's a
test asserting that silence).

describeInitializeParams is total. params is unknown off the wire and validated only as a
non-null object or array, so every field is narrowed there and anything unexpected degrades to
null/[]. A malformed handshake must still produce a line — a client sending something the server
cannot parse is precisely the event worth seeing, and an exception would lose it. Covered with
params as null, a string, an array, a number, and a clientInfo that is variously a string, an
array, null, or has non-string fields.

Caller-derived fields are spread beneath the canonical ones, matching the tool_call line.
Without it, clientInfo would be an authenticated way to attribute a call to a different userId
there's a test for that specifically. Client strings are clipped before reaching the log.

Deliberately excluded

  • A labeledTotals counter keyed by client version. /metrics is unauthenticated while calling
    a tool requires a token — already flagged in the runbook as worth closing — and client identity is
    a fingerprint of the deployment. It belongs in the log rather than on a public endpoint. Worth
    revisiting once /metrics is gated.
  • Protocol-version negotiation. The server keeps answering 2025-06-18 unconditionally; this
    only records what was asked. Changing what the server advertises is a live behavioural change to a
    connector that has just broken once, and should be decided against a logged mismatch rather than a
    guess — which is what protocolVersionMismatch now provides.

Verification

  • 785 tests pass (53 files), 14 of them new; typecheck, eslint and prettier clean
  • The initialize response is unchanged — asserted directly; this adds a log line, not a new
    response
  • Docs: README gains a "Handshake logging" section; runbook gains §3.1 with the field reference and
    jq recipes (the cross-reference from README was renumbered to match)

Note the first real run will answer something this investigation could not: which protocol revision
Claude Desktop 1.37937.1 actually negotiates.

🤖 Generated with Claude Code

The connector recently returned summary lines with no rows, because rows
lived only in `structuredContent` and the client's handling of that field
changed. Establishing that took a rollback test plus reading Claude
Desktop's own log directory, because this server records nothing about who
connects: `initialize` never read `request.params` and never logged.

Every `initialize` now emits one line tagged `event: "mcp_initialize"`,
joining `tool_call` as the second selectable event. It carries clientName /
clientVersion, requestedProtocolVersion vs servedProtocolVersion, a
protocolVersionMismatch boolean, clientCapabilities (names only), plus
userId and correlationId so a session joins across both events.

Logged from `dispatchMcpRequest` rather than the `case 'initialize'` that
builds the response: `handleRpcRequest` is the pure, env-free half and has
neither the caller nor the correlation id. Delegating to it afterwards keeps
the response in one place. `describeInitializeParams` is total — `params` is
`unknown` off the wire, so a malformed handshake still logs a line instead
of throwing, which is the case most worth seeing.

Caller-derived fields are spread beneath the canonical ones, so `clientInfo`
cannot attribute a call to another userId.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@gilgardosh
gilgardosh temporarily deployed to accounter-fullstack August 27, 2026 05:57 — with GitHub Actions Inactive
@gilgardosh
gilgardosh temporarily deployed to accounter-fullstack August 27, 2026 05:57 — with GitHub Actions Inactive
@github-actions

github-actions Bot commented Aug 27, 2026

Copy link
Copy Markdown
Contributor

🚀 Snapshot Release (alpha)

The latest changes of this PR are available as alpha on npm (based on the declared changesets):

Package Version Info
@accounter/client 0.1.0-alpha-20260827074134-8e15b7dbde9c5f6555c22f5a0b64e97df041cd7a npm ↗︎ unpkg ↗︎
@accounter/green-invoice-graphql 0.8.7-alpha-20260827074134-8e15b7dbde9c5f6555c22f5a0b64e97df041cd7a npm ↗︎ unpkg ↗︎
@accounter/hashavshevet-mesh 0.2.13-alpha-20260827074134-8e15b7dbde9c5f6555c22f5a0b64e97df041cd7a npm ↗︎ unpkg ↗︎
@accounter/israeli-vat-scraper 0.1.13-alpha-20260827074134-8e15b7dbde9c5f6555c22f5a0b64e97df041cd7a npm ↗︎ unpkg ↗︎
@accounter/modern-poalim-scraper 0.11.0-alpha-20260827074134-8e15b7dbde9c5f6555c22f5a0b64e97df041cd7a npm ↗︎ unpkg ↗︎
@accounter/payper-mesh 0.2.13-alpha-20260827074134-8e15b7dbde9c5f6555c22f5a0b64e97df041cd7a npm ↗︎ unpkg ↗︎
@accounter/scraper-app 0.0.3-alpha-20260827074134-8e15b7dbde9c5f6555c22f5a0b64e97df041cd7a npm ↗︎ unpkg ↗︎
@accounter/server 0.2.0-alpha-20260827074134-8e15b7dbde9c5f6555c22f5a0b64e97df041cd7a npm ↗︎ unpkg ↗︎
@accounter/shaam-uniform-format-generator 0.2.7-alpha-20260827074134-8e15b7dbde9c5f6555c22f5a0b64e97df041cd7a npm ↗︎ unpkg ↗︎
@accounter/shaam6111-generator 0.1.9-alpha-20260827074134-8e15b7dbde9c5f6555c22f5a0b64e97df041cd7a npm ↗︎ unpkg ↗︎

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟢 Approval recommended

The change is low-risk (additive logging + tests + docs) and does not alter protocol responses or tool execution behavior.

Pull request overview

Adds structured logging for the MCP initialize handshake so the server can attribute behavior changes to specific clients (name/version/capabilities/protocol) without relying on client-side logs—complementing existing per-tool-call logging.

Changes:

  • Emit a single structured event: "mcp_initialize" log line per initialize call (including client info, protocol versions, capabilities, userId, correlationId).
  • Add parsing/clipping helper (describeInitializeParams) plus unit tests and handshake logging tests.
  • Document the new log event in the package README + operations runbook, and publish via a changeset.
File summaries
File Description
packages/mcp-server/src/mcp/handler.ts Introduces mcp_initialize event logging on initialize and adds total parsing + clipping helpers for client-supplied fields.
packages/mcp-server/src/mcp/tests/handler.test.ts Adds unit tests for parameter parsing and verifies exactly-one handshake log line + invariants.
packages/mcp-server/README.md Documents handshake logging semantics and how it relates to tool-call usage logging.
packages/mcp-server/docs/operations-runbook.md Adds a dedicated section for handshake log fields and jq recipes for analysis/alerting.
.changeset/mcp-log-initialize-handshake.md Bumps @accounter/mcp-server with a patch changeset describing the new logging behavior.
Review details

Suppressed comments (1)

packages/mcp-server/src/mcp/tests/handler.test.ts:556

  • dispatchMcpRequest is exercised here with a primitive string params, but the real HTTP path rejects primitive params in asJsonRpcRequest. Using an array keeps the “unparseable handshake still logs” intent while matching a shape that can actually arrive over JSON-RPC.
    await initialize('not-an-object');
  • Files reviewed: 5/5 changed files
  • Comments generated: 3
  • Review effort level: Lite

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

Comment thread packages/mcp-server/src/mcp/handler.ts Outdated
Comment thread packages/mcp-server/src/mcp/handler.ts Outdated
Comment thread packages/mcp-server/src/mcp/__tests__/handler.test.ts Outdated
…ents

Review follow-ups on the initialize handshake logging.

- `clipClientLabel` appended the ellipsis *after* slicing to the cap, so a
  long client name emitted MAX_CLIENT_LABEL_LENGTH + 1 characters. The
  marker now counts towards the cap — a cap its own truncation marker can
  push past is not a cap. The test asserts against the exported constant
  rather than a literal, plus a boundary case for a name exactly at the cap.

- The constant's docblock said it "mirrors" MAX_MISS_LABEL_LENGTH, which is
  40 while this is 60. Reworded to say what it shares (motivation) and why
  the numbers differ: that one bounds a /metrics label, this bounds a log
  field.

- A test comment claimed every params shape it exercises is reachable from
  the wire, but asJsonRpcRequest rejects primitive and null params before
  dispatch. Reworded to give the real reason the helper is total: `params`
  is typed `unknown`, and the parser's validation is the kind of upstream
  promise that quietly stops holding.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@gilgardosh
gilgardosh temporarily deployed to accounter-fullstack August 27, 2026 07:38 — with GitHub Actions Inactive
@gilgardosh
gilgardosh temporarily deployed to accounter-fullstack August 27, 2026 07:38 — with GitHub Actions Inactive
The repo runs 63:9 behavior/behaviour and 58:4 recognized/recognised; match it.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@gilgardosh
gilgardosh temporarily deployed to accounter-fullstack August 27, 2026 07:39 — with GitHub Actions Inactive
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@gilgardosh
gilgardosh temporarily deployed to accounter-fullstack August 27, 2026 07:40 — with GitHub Actions Inactive
@gilgardosh
gilgardosh temporarily deployed to accounter-fullstack August 27, 2026 07:40 — with GitHub Actions Inactive
@gilgardosh
gilgardosh merged commit fda81a4 into main Aug 27, 2026
11 checks passed
@gilgardosh
gilgardosh deleted the feat/mcp-log-initialize-handshake branch August 27, 2026 07:44
gilgardosh added a commit that referenced this pull request Aug 27, 2026
* docs(mcp-server): postmortem for the blind-connector incident

Records the Aug 18–26 outage where every tool returned its summary line
without rows: what happened, why the connector broke, which properties of
our own design turned a third-party client change into a total outage, and
what changed in response (#4295 payload mirroring + contract test, #4299
handshake logging).

The structural section is the point. The rows depended on a field a client
may ignore; the tests asserted the object rather than the channel, so the
suite passed 760/760 straight through the outage; and the handshake was the
one hop with no log, so dating the change required the client's own local
logs.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

* docs(mcp-server): use the repo's American spellings in the postmortem

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

* docs(mcp-server): correct the tool count and record the merge

Seventeen tools, not nineteen — the larger number counted shapeListResult
call sites (16, since terminology.ts calls it twice and lookups.ts three
times) rather than registered tools.

Also updates the status row now that #4295 and #4299 have merged.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

* docs(mcp-server): bring the postmortem up to date

Written before the follow-up work landed. Updates it to record what
investigating the incident actually produced:

- Resolution now covers #4302 (money-shape drift the audit surfaced) and
  #4306 (documenting results in descriptions), alongside #4295 and #4299.
- The outputSchema decision was a judgement call ("the fix no longer depends
  on it") and is now a measurement: Desktop does not surface a declared
  schema to the model, established on one canary tool after ruling out a
  cached tools/list. So the model sees neither structuredContent nor
  outputSchema, and `content` is the only channel on two independent
  measurements rather than inference.
- Records that Desktop defers tool definitions, showing roughly the first
  sentence until the model loads one — which is why the scope-discovery
  instruction had to move into sentence one.
- Lesson 3 was incomplete. Handshake logging cannot detect a client that
  stops handshaking: a revision without `initialize` produces silence, not a
  changed version, so we would still learn at failure time.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

---------

Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants