[lorenzozanee]

What does this PR do?

MCP request logs now separate handler and response serialization time and report cancellation or timeout. Malformed responses and failed input or output paths are surfaced as errors; this does not claim to resolve the reported 180-second Windows delay, which was not reproduced.

Focused validation: make -f Makefile.cbm test-focused TEST_SUITES="mcp log daemon_application httpd" (462 passed, 5 skipped). scripts/lint.sh --ci stopped because cppcheck is unavailable; Windows and upstream CI remain unverified.

Prepared with AI assistance for the submitting account owner.

Fixes #965

[DeusData]

Thank you, @lorenzozanee. Splitting handler time from serialization time is exactly the visibility #965 needs. We also appreciate you being upfront that the 180 s Windows delay itself wasn't reproduced, and that this wasn't run on Windows or CI.

Could you split this into two PRs?

• Timing and transport fields (handler_duration_ms, response_serialization_ms, cancelled, timed_out): an easy yes.

• Behaviour changes that clients depend on need a separate maintainer decision:

  • rejecting requests without "jsonrpc": this inverts the existing contract test jsonrpc_parse_missing_jsonrpc_field, which pinned the lenient default;
  • rejecting null or float ids;
  • dropping "result":null;
  • exiting the stdio server on a missing response or on poll/fcntl errors, including the removed blocking-poll fallback;
  • the new HTTP 500 path.

  A handler that returns NULL currently ends the whole session instead of producing an error reply, and that alone is a big change in how failures behave.

A few mechanical items for the timing PR:

1. Memory-core ratchet: src/ui/http_server.c goes from 31 to 32 raw allocator calls (the new free(error_response)), and its baseline is 31, so lint-memory-core will fail. Please use the mem_core wrappers.
2. Log coverage: the cbm_log_mcp_request assertions were removed from tests/test_log.c. Please keep them, or name the test that now covers the same contract.
3. macOS skip: mcp_server_run_reports_input_failure is skipped on macOS as "Unix-specific", but macOS is Unix. Could it run there, or could the skip say what actually fails?

Thanks again. The timing half will help a lot with diagnosing slow sessions.

[github-actions]

Thanks for opening this — it has been seen, and it is queued.

This note is automated, but it is not a brush-off: it exists so you know where your PR stands instead of having to guess from silence.

Current review status: working through a backlog. 0.9.1-rc.1 is out, so the release freeze that held reviews is over — but it left a large queue of open pull requests behind it, and we are reading through them oldest-first. The background is in discussion #1144.

What that means for this PR, concretely:

• It will not be closed for inactivity. No stale bot touches pull requests here.
• It may still sit a while before a human reads it. That is on us, not on you.
• Older PRs are read first, so a recent one is not being skipped — it is behind a queue.

Things that will genuinely speed it up whenever review does happen:

• Keep it rebased on main — the tree is moving quickly right now, and a conflicting branch cannot be reviewed as the diff you intended.
• Get CI green, or say which failures you believe are pre-existing.
• Keep the change to one claim. Bundled features and refactors get split before they get merged, which costs you a round trip.
• Every commit needs a sign-off (git commit -s) — CI enforces DCO.

If this fixes a bug, a reproduction we can run is worth more than a description of the symptom.

Thanks for contributing, and sorry in advance for the wait.

[DeusData]

Thanks again for the request-timing diagnostics. The earlier split request still stands: timing/transport fields can be reviewed separately from the JSON-RPC and session behavior changes. The latter require a maintainer decision; please let us know if that boundary needs clarification.

[DeusData]

Thanks again for the timing diagnostics. The requested split still separates timing/transport reporting from JSON-RPC and session behavior changes. The latter need our decision; sorry for the delay on that, and I’ll follow up soon.

[DeusData]

Thank you so much, @lorenzozanee, for this work and for your patience while it waited on us. Splitting handler time from serialization time, and flagging cancelled and timed-out requests, is exactly the visibility #965 asked for. Your tests that keep tool arguments and project names out of the log lines are a really nice touch.

Since the branch allows maintainer edits, we did the split from the earlier review ourselves so the timing half can land now. On top of your commit we:

1. Kept the timing fields as you wrote them (handler_duration_ms, response_serialization_ms, cancelled, timed_out and status=timeout), together with your log tests for them.
2. Took the behaviour changes back out of this PR: the stricter jsonrpc and id parsing, dropping "result":null, the new NULL returns from the response formatters, exiting the stdio loop on a missing response or an input/output failure, the removed blocking-poll fallback, the HTTP 500 path, ending the daemon session on a missing response, and the update-notice warning, along with their tests. As the review said, those need a separate maintainer decision. Your original commit 6f17caa still has all of it, so nothing is lost, and you are very welcome to open it as its own PR. This also settles the macOS skip question, since those two stdio tests left together with the changes they covered.
3. Dropped the list_projects sort guard, because main already has the same fix (25383bc).
4. Restored the cbm_log_mcp_request checks in tests/test_log.c with the new signature, and added checks for the new fields and for status=timeout.
5. Cleared the lint findings: clang-format on two of the new lines, plus two cppcheck shadowed-variable reports that lived in the reverted formatter code. The memory-core count for src/ui/http_server.c is back at its baseline of 31 for the same reason, since the extra free left with the HTTP 500 path.
6. Merged current main. There was one conflict: main now logs the server/discover connect probe as info instead of an error (server/discover returns -32601 Method not found, so every modern MCP SDK connect logs an error #2433), and we kept that rule with your new logging call.

Please pull before pushing again, since the branch now has our commits on top. Thanks again: the timing half will make slow sessions much easier to diagnose.

[DeusData]

Merged as 69b26df - thank you so much, @lorenzozanee! Every mcp.request log line now carries handler_duration_ms, response_serialization_ms, cancelled and timed_out, so a slow call shows right away whether the time went to the handler or to the reply. Your tests that keep tool arguments and project names out of those lines are a great touch. The protocol-behaviour half stays in your original commit 6f17caa for its own decision, as explained above. Thank you for your patience.