Skip to content

[Server] Log JSON-RPC payloads at debug level only - #525

Open
aton-of-data wants to merge 1 commit into
modelcontextprotocol:mainfrom
aton-of-data:protocol-log-payloads-at-debug
Open

aton-of-data wants to merge 1 commit into
modelcontextprotocol:mainfrom
aton-of-data:protocol-log-payloads-at-debug

Conversation

@aton-of-data

Copy link
Copy Markdown

Fixes #524

Problem. At 3175614, src/Server/Protocol.php puts whole JSON-RPC payloads into the log context at info level:

  • :181 info('Received message to process.', ['message' => $input]), the raw wire input
  • :260 info('Handling request.', ['request' => $request])
  • :364 info('Handling response from client.', ['response' => $response]), which carries sampling and elicitation replies
  • :384 info('Handling notification.', ['notification' => $notification])

docs/run/server-builder.md:241 and :271 set up a Monolog StreamHandler at Logger::INFO. With that setup every tool argument, and every elicitation or sampling reply, is written to disk twice per message.

The rest of the SDK already keeps payloads at debug: CallToolHandler.php:69 logs tool arguments at debug and :155 tool failures, the client logs its raw input at debug (src/Client/Protocol.php:576), and StatelessProtocol logs no payloads at all. Protocol was the one place that did not follow that split.

Change. The four info records now carry identifiers only: method and request_id for requests, message_id for client responses, method for notifications. Received message to process. stays at info with no context, and a new debug record, Received message payload., carries the raw input under the same message key. That raw input holds every request, response and notification in a batch, so debug output still has the full payload.

Reproduction. The documented configuration (Monolog StreamHandler('php://stdout', Logger::INFO)), Server::builder()->setLogger($logger)->addTool(fn (string $username, string $password) => 'ok', 'login'), over InMemoryTransport, sending initialize, notifications/initialized, then tools/call with {"username":"alice","password":"hunter2"}.

Before, excerpt:

mcp-server.INFO: Received message to process. {"message":"{\"jsonrpc\":\"2.0\",\"id\":2,\"method\":\"tools/call\",\"params\":{\"name\":\"login\",\"arguments\":{\"username\":\"alice\",\"password\":\"hunter2\"}}}"} []
mcp-server.INFO: Handling request. {"request":{"Mcp\\Schema\\Request\\CallToolRequest":{"jsonrpc":"2.0","id":2,"method":"tools/call","params":{"name":"login","arguments":{"username":"alice","password":"hunter2"}}}}} []

After:

mcp-server.INFO: Received message to process. [] []
mcp-server.INFO: Handling request. {"method":"tools/call","request_id":2} []
mcp-server.INFO: Queueing server response {"response_id":2} []

hunter2 appears twice in the INFO log before and not at all after. With the handler at DEBUG it still appears, in Received message payload. and in CallToolHandler's Executing tool.

Test. ProtocolTest::testMessagePayloadsAreOnlyLoggedAtDebugLevel runs three cases (a tools/call request, a client response to an elicitation, a notifications/cancelled notification) and asserts for each that no record at info or above contains the payload, that the method or id is still logged at info, and that the payload is present at debug. It fails 3 of 3 on 3175614 and passes 3 of 3 with the change. No existing test was changed.

Verified on PHP 8.3.6, PHPUnit 10.5.65:

Check Before After
phpunit --testsuite=unit 1582 tests, OK, 4 skipped 1585 tests, OK, same 4 skipped
phpstan no errors no errors
php-cs-fixer fix --dry-run --diff (no cache) 0 of 575 files 0 of 575 files
integration suite, one file at a time 12 of 13 OK same 12 OK
examples suite 5 tests OK

Not verified. DualEraElicitationTest hangs in my environment on the base commit as well, so it was skipped. In the inspector suite the 44 HTTP tests error on base and patched alike (fetch failed ... invalid onRequestStart method from the npx inspector); the stdio inspector tests pass. The conformance tests need Docker and were not run.

Left alone, same family, failure paths only. src/Capability/Discovery/SchemaValidator.php:89-92 logs the tool arguments at error, but only when the validator itself throws; Protocol.php:562-566 logs a client reply at error when it cannot be reconstructed from the session. These are diagnostics at warning or error, not per-message info logging, so I kept them out of this change. The first is worth a follow-up if you agree.

AI disclosure: Claude (Anthropic) was used to diagnose this, write the change and the test, and run the verification. Every result quoted here was executed.

Protocol logged the raw input and the full request, client response and
notification objects as context at info level, so a server logging at INFO
wrote every tool argument and every elicitation/sampling reply to its log.

Info records now carry only the method and id; the raw message is logged
once at debug level.

Fixes modelcontextprotocol#524

This branch has not been deployed

No deployments
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.

Server logs full JSON-RPC payloads, tool arguments included, at info level

1 participant