<!--IssueSummary start--> <details> <summary> Everyone can contribute. [Help move this issue forward](https://handbook.gitlab.com/handbook/marketing/developer-relations/engineering/community-contributors-workflows/#contributor-links) while earning points, leveling up and collecting rewards. </summary> - [Work on this issue](https://contributors.gitlab.com/manage-issue?action=work&projectId=278964&issueIid=638385) </details> <!--IssueSummary end--> ### Summary A `tools/call` to a route-backed MCP tool writes two `api_json` lines for one POST to `/api/v4/mcp`. Both lines carry the HTTP method of the REST route the tool ran (GET, PUT or POST) and the MCP route `/api/:version/mcp`. Only one of them carries the JSON-RPC params. Route-backed tools are the ones defined with `route_setting :mcp`. The listed ones are `list_branches`, `list_pipelines` and `fork_repository`. The aggregated `search`, `save_merge_request`, `save_project` and `manage_pipeline` tools reach the same code, because they dispatch to route-backed sub-tools ([`aggregated_service.rb:55`](https://gitlab.com/gitlab-org/gitlab/-/blob/61a2beb6587f7154dd8b114337a0bcdbf330a82e/app/services/mcp/tools/base/aggregated_service.rb#L55)). The result: logs show GET and PUT requests to `/api/v4/mcp` that never happened, and every route-backed tool call is counted twice, along with its Gitaly and Redis calls. The second line also resets the request logger's DB timer, so the MCP line's `db_duration_s` leaves out the DB time used before the tool ran. This shows up in production logs. Prometheus request metrics are not affected, because `RequestsRackMiddleware` reads the method before the request runs ([`requests_rack_middleware.rb:72`](https://gitlab.com/gitlab-org/gitlab/-/blob/61a2beb6587f7154dd8b114337a0bcdbf330a82e/lib/gitlab/metrics/requests_rack_middleware.rb#L72)). ### Steps to reproduce 1. In GDK, create a token with the `mcp` scope. 1. POST this body to `/api/v4/mcp`: ```json {"jsonrpc":"2.0","id":1,"method":"tools/call","params":{"name":"list_branches","arguments":{"id":"<project path>"}}} ``` 1. Look at `log/api_json.log` for that request's `correlation_id`. ### Example Project None needed. Any project with a repository. ### What is the current *bug* behavior? Two lines with the same `correlation_id`, both with `"method":"GET"` and `"route":"/api/:version/mcp"`. One has the JSON-RPC params (`jsonrpc`, `id`, `method`, `params`). The other has none. ### What is the expected *correct* behavior? One line with `"method":"POST"`, the MCP route and the JSON-RPC params, and a `db_duration_s` that covers the whole request. The tool's `mcp.log` line records the HTTP status the REST route returned. ### Relevant logs and/or screenshots <details><summary>Why it happens</summary> - `ApiTool#execute` sets `request.env[Rack::REQUEST_METHOD]` to the REST route's method and calls `route.app.call(request.env)` ([`api_tool.rb:96-103`](https://gitlab.com/gitlab-org/gitlab/-/blob/61a2beb6587f7154dd8b114337a0bcdbf330a82e/app/services/mcp/tools/base/api_tool.rb#L96-103)). The `ensure` restores `api.format` and `rack.input`, but not `REQUEST_METHOD` ([`#L104-107`](https://gitlab.com/gitlab-org/gitlab/-/blob/61a2beb6587f7154dd8b114337a0bcdbf330a82e/app/services/mcp/tools/base/api_tool.rb#L104-107)). The request logger reads the method after the request finishes, so the MCP POST is logged with the REST route's method. - `route.app.call` runs the endpoint through the middleware that `API::API` inserts, including `GrapeLogging::Middleware::RequestLogger` ([`api.rb:35-36`](https://gitlab.com/gitlab-org/gitlab/-/blob/61a2beb6587f7154dd8b114337a0bcdbf330a82e/lib/api/api.rb#L35-36)), so the REST call writes its own line. That line also says `/api/:version/mcp`, because `RouteLogger` reads the route from `GRAPE_ROUTING_ARGS[:route_info]` ([`route_logger.rb:10-11`](https://gitlab.com/gitlab-org/gitlab/-/blob/61a2beb6587f7154dd8b114337a0bcdbf330a82e/lib/gitlab/grape_logging/loggers/route_logger.rb#L10-11)), and `ApiTool` merges the tool arguments into the MCP request's routing args instead of replacing them ([`api_tool.rb:95`](https://gitlab.com/gitlab-org/gitlab/-/blob/61a2beb6587f7154dd8b114337a0bcdbf330a82e/app/services/mcp/tools/base/api_tool.rb#L95)). - Each request logger resets the DB timer when it starts (`reset_db_runtime` in grape_logging's `RequestLogger#before`). The nested logger starts after the MCP request has already run its authentication, tool lookup and governance queries, so that DB time drops out of the MCP line. </details> <details><summary>History</summary> How `ApiTool#execute` got here: - !201838 added route-backed tools. It set `REQUEST_METHOD` to the route's method and ran the route with `route.exec(request.env)`, which in Grape 2 is `@app.call(env)`. Both the wrong method and the second line date from this MR. - !235263 (`get_job_log`) added the `ensure` that restores `api.format`, so a plain text route doesn't change the MCP response format. `REQUEST_METHOD` wasn't restored. - !243272 moved the class to `app/services/mcp/tools/base/`. No behaviour change. - !253200 (Grape 3) replaced `route.exec` with `route.app.call`. Same behaviour. - !256657 started reading the route's response headers, for rate limit retry details. - !259413 swaps `rack.input` for an empty body during the call, so the JSON-RPC `id` stops leaking into the route's params, and restores it in the same `ensure`. - !264670 added the tool's own DB counters to the `mcp.log` line. That's the line that keeps the tool's DB cost once the second `api_json` line is gone. How we found it: production `api_json` logs show GET and PUT requests to `/api/v4/mcp`, which only answers 405 to GET. Their `caller_id` is `POST /api/:version/mcp`, which led to `ApiTool#execute`. </details> ### Output of checks Reproduced with a request spec that captures `API::API::LOGGER` on `master` at `61a2beb6587f`. One `list_branches` call logged: ```plaintext method=GET status=200 path=/api/v4/mcp route=/api/:version/mcp params=["access_token"] method=GET status=200 path=/api/v4/mcp route=/api/:version/mcp params=["access_token", "jsonrpc", "id", "method", "params"] ``` Both lines carried `gitaly_calls=11`. In the same run, the nested logger's reset dropped 96 ms of DB time from the MCP line (test environment numbers). A spike that restored `REQUEST_METHOD` and skipped the request logger for the nested call wrote one line instead: `method=POST`, `gitaly_calls=11`, and the full DB time. The tool result didn't change, including `isError: true` with "404 Project Not Found" for a missing project. ### Proposal 1. `ApiTool#execute` changes the request's method from POST to the REST route's method (for example GET) so the route runs, and never changes it back, so the MCP request is logged as GET. Save the method before the change and put it back after the route runs, in the same `ensure` that already puts back `api.format` and `rack.input`. 1. Keep the nested REST call out of the request log. Set a flag in the request env around `route.app.call`, and have the request logger pass the call through without logging while the flag is set. This removes the second line, the double counting, and the DB timer reset. grape_logging 3.0.1 has no option to skip a request, so this needs a small subclass of its `RequestLogger` that overrides `call!` and calls `super`. That's the usual way to extend a Grape middleware. It depends on `call!` staying the gem's entry point, like the existing note on grape_logging internals in [`api.rb:15-19`](https://gitlab.com/gitlab-org/gitlab/-/blob/61a2beb6587f7154dd8b114337a0bcdbf330a82e/lib/api/api.rb#L15-19). A request spec that expects one `api_json` line per route-backed tool call catches a gem change that breaks it. Errors stay visible: an exception in the REST route reaches `CallTool`, which logs it on the `mcp.log` line and re-raises, so the MCP request's line still shows the failure. <details><summary>Example</summary> ```ruby # lib/gitlab/grape_logging/request_logger.rb module Gitlab module GrapeLogging class RequestLogger < ::GrapeLogging::Middleware::RequestLogger SKIP_ENV_KEY = 'gitlab.grape_logging.skip' def call!(env) return app.call(env) if env[SKIP_ENV_KEY] super end end end end ``` `lib/api/api.rb` inserts `Gitlab::GrapeLogging::RequestLogger` in place of `GrapeLogging::Middleware::RequestLogger`, with the same options. In `ApiTool#execute`: ```ruby begin request.env[Rack::RACK_INPUT] = StringIO.new request.env[Gitlab::GrapeLogging::RequestLogger::SKIP_ENV_KEY] = true status, headers, body = route.app.call(request.env) ensure request.env.delete(Gitlab::GrapeLogging::RequestLogger::SKIP_ENV_KEY) request.env['api.format'] = original_format request.env[Rack::RACK_INPUT] = original_input request.env[Rack::REQUEST_METHOD] = original_method end ``` The MCP request's logger starts before the flag is set and writes its line after the flag is cleared. The REST route's logger starts while the flag is set, so it runs the route without logging and without resetting the DB timer. </details> <details><summary>Why not an existing option, and the CPU cost</summary> Neither Grape 3.2.1 nor grape_logging 3.0.1 has a way to skip logging for one request. The options that come closest don't work: | Option | Why it doesn't work | |---|---| | An `include:` logger | It only adds fields to the line. `before` always resets the DB timer, and `after` always calls the reporter ([`request_logger.rb:27-41`](https://github.com/aserafin/grape_logging/blob/v3.0.1/lib/grape_logging/middleware/request_logger.rb#L27-L41)). | | `instrumentation_key:` with a subscriber that drops the nested event | Changes how every API request is logged, and the DB timer is still reset. | | A formatter that returns an empty string | The line is still built, and the DB timer is still reset. | | `route_setting` | It's set per route, not per call. A REST request and an MCP tool call use the same route. | | Running the endpoint without its middleware | Grape builds the middleware for each endpoint. Skipping it means calling the protected `Endpoint#run`, which also skips `Grape::Middleware::Error` and `Formatter`. `ApiTool` needs the status and formatted body those two produce. | CPU cost per call, measured in GDK with the `include:` list from `api.rb` and a logger that writes to `/dev/null`. Three rounds of 5,000 calls: | | CPU per call | |---|---| | `GrapeLogging::Middleware::RequestLogger` today | 277-318 µs | | Subclass, flag not set | 278-290 µs | | Subclass, flag set | 0.2-1.8 µs | | The `env` lookup on its own | 30 ns | Every API request pays for one hash lookup, which is smaller than the variation between rounds. Each route-backed tool call saves about 0.3 ms of CPU, because the second line is never built. </details> 1. Log the HTTP status the REST route returned on the tool's `mcp.log` line, as `Labkit::Fields::HTTP_STATUS_CODE` (`status`). `ApiTool#process_response` already has it. Today the line has only `tool_status`, which groups codes: 401 and 403 are both `unauthorized`, and other 4xx codes are `bad_request`. Don't use `http_status` or `status_code`, which LabKit lists as deprecated names for the same field. 1. Document the change in two places: - [Implement a tool from a REST API route](https://gitlab.com/gitlab-org/gitlab/-/blob/61a2beb6587f7154dd8b114337a0bcdbf330a82e/doc/development/duo_agent_platform/mcp/_index.md#L277): the route runs inside the MCP request and gets no `api_json.log` line of its own, and the tool's `mcp.log` line records its `status`, duration and DB counters. - The [`mcp.log` section](https://gitlab.com/gitlab-org/gitlab/-/blob/61a2beb6587f7154dd8b114337a0bcdbf330a82e/doc/administration/logs/_index.md#L1269) of the logs page: the new `status` field for route-backed tools. ### Open questions 1. ~~Drop the REST call's line, or keep it with the REST route? It is the only place the REST route's own status and duration are logged.~~ Drop it. The tool's `mcp.log` line already has the tool name, `tool_status`, `duration_s` and the tool's own DB counters, and the REST response still reaches the client as the tool result. The second line never identified the REST route either, since it logs `/api/:version/mcp`. The only thing it adds is the exact HTTP status, which proposal item 3 moves to the `mcp.log` line. ### Patch release information for backports Not requested.