From b13e84274007012ea4c7fe425092cf697cda5aae Mon Sep 17 00:00:00 2001 From: xarmian Date: Sun, 18 Oct 2026 11:12:41 -0400 Subject: [PATCH] fix(mcp): a refused tool call is audited as denied, not ok (BUG-3879) (#2222) * fix(mcp): a refused tool call is audited as denied, not ok (BUG-3879) A failed tool call answers the /mcp POST with 200 and an error result, so the audit middleware, which classified only the transport status, wrote result_status=ok for every refused write. MCPAuditLog now installs an outcome sink on the request context; a tool-handler middleware on every MCP server pad builds records a failed result's error code (and details.reason) into it. permission_denied, auth_required and rate_limited are denied; any other failure is an error; the code is the error_kind. Claude-Session: https://claude.ai/code/session_016Msqj8nRQUNbgdsXxhBBVR * test(mcp): unit rows for the tool-outcome sink, codes and middleware order (BUG-3879) Claude-Session: https://claude.ai/code/session_016Msqj8nRQUNbgdsXxhBBVR * docs: the MCP audit status is the call's outcome, not the transport's (BUG-3879) Claude-Session: https://claude.ai/code/session_016Msqj8nRQUNbgdsXxhBBVR * fix(mcp): a JSON-RPC error inside a 200 is audited too, via an OnError hook (BUG-3879 hunter r1 M1) mcp-go refuses an unknown tool, and answers a missing resource or prompt, before the tool-handler middleware runs, so those calls were still audited as ok. Claude-Session: https://claude.ai/code/session_016Msqj8nRQUNbgdsXxhBBVR * test(mcp): a failed tools/list audits as error; the prose names what OnError cannot see (BUG-3879 r2) Lead ruling R2 pins the unscoped hook; hunter r2 L1 narrows the claim: a message rejected before method dispatch never reaches OnError. Claude-Session: https://claude.ai/code/session_016Msqj8nRQUNbgdsXxhBBVR * test(mcp): a refused write's audit kind carries the reason BUG-3864 added (BUG-3879) After rebasing onto #2218 (BUG-3864), the 403s for a read-only token's write and a viewer's write carry details.reason, token_scope and role. recordToolOutcome writes error_kind as : whenever a reason is present, as designed, so the two transport rows now expect permission_denied:token_scope and permission_denied:role. On the old base those 403s carried no reason, which is what the rows had pinned. Claude-Session: https://claude.ai/code/session_016Msqj8nRQUNbgdsXxhBBVR * fix(mcp): an unverified email's refused call is audited as denied (BUG-3879 r4) Since BUG-3864, a write refused because the account's email is unverified answers with its own MCP code, email_not_verified, rather than permission_denied. classifyMCPToolOutcome only knew the older three refusal codes, so after the rebase onto #2218 that refusal was audited as error. It is denied now, as the classifier's own comment and this bug's contract already said. The plan and member limits stay errors (BUG-3894 owns that policy). The unit rows that paired permission_denied with an email_not_verified reason described a payload the server never sends; they now use token_scope, a reason it does send, plus a row for the real code. A new transport row drives an unverified owner's write on the Cloud fixture and requires a denied row. docs/api.md and the metric's Help text name the code. Claude-Session: https://claude.ai/code/session_016Msqj8nRQUNbgdsXxhBBVR --- .../bug3879_mcp_audit_tool_outcome_test.go | 179 ++++++++++++++++++ docs/api.md | 2 +- internal/mcp/audit_outcome.go | 111 +++++++++++ internal/mcp/audit_outcome_test.go | 116 ++++++++++++ internal/mcp/server.go | 14 +- internal/metrics/metrics.go | 2 +- internal/server/mcp_tool_outcome.go | 99 ++++++++++ internal/server/mcp_tool_outcome_test.go | 67 +++++++ internal/server/middleware_mcp_audit.go | 44 +++-- .../console/admin/mcp-audit/+page.svelte | 5 +- 10 files changed, 618 insertions(+), 21 deletions(-) create mode 100644 cmd/pad/bug3879_mcp_audit_tool_outcome_test.go create mode 100644 internal/mcp/audit_outcome.go create mode 100644 internal/mcp/audit_outcome_test.go create mode 100644 internal/server/mcp_tool_outcome.go create mode 100644 internal/server/mcp_tool_outcome_test.go diff --git a/cmd/pad/bug3879_mcp_audit_tool_outcome_test.go b/cmd/pad/bug3879_mcp_audit_tool_outcome_test.go new file mode 100644 index 000000000..356b9a47a --- /dev/null +++ b/cmd/pad/bug3879_mcp_audit_tool_outcome_test.go @@ -0,0 +1,179 @@ +package main + +// BUG-3879: a tool call refused inside a 200 /mcp response was audited as +// ok, because the audit middleware classified only the transport status. +// Driven through the server exactly as `pad server` wires it (wireMCP): the +// real bearer auth, audit middleware, Streamable HTTP transport, catalog, +// dispatcher and REST routes, so the rows below vouch for the binding and +// not only for the components (team CONVE-19). + +import ( + "net/http" + "strings" + "testing" + "time" + + "github.com/PerpetualSoftware/pad/internal/models" +) + +func TestBUG3879_ToolOutcomeReachesTheAuditRow(t *testing.T) { + f := newCapFixture(t, cfgHTTP, false, nil, "true") + readOnly, err := f.store.CreateAPIToken(f.member.ID, models.APITokenCreate{Name: "read-only", Scopes: `["read"]`}, 30, 0) + if err != nil { + t.Fatalf("CreateAPIToken read-only: %v", err) + } + viewer, err := f.store.CreateUser(models.UserCreate{Email: "viewer-3879@example.com", Name: "Viewer", Password: "correct-horse-battery-staple"}) + if err != nil { + t.Fatalf("CreateUser viewer: %v", err) + } + if err := f.store.AddWorkspaceMember(f.ws.ID, viewer.ID, "viewer"); err != nil { + t.Fatalf("AddWorkspaceMember viewer: %v", err) + } + viewerPAT, err := f.store.CreateAPIToken(viewer.ID, models.APITokenCreate{Name: "viewer"}, 30, 0) + if err != nil { + t.Fatalf("CreateAPIToken viewer: %v", err) + } + if err := f.store.SeedCollectionsFromTemplate(f.ws.ID, "startup"); err != nil { + t.Fatalf("SeedCollectionsFromTemplate: %v", err) + } + + create := `{"action":"create","workspace":"cap-ws","collection":"tasks","title":"BUG-3879 probe"}` + cases := []struct { + name string + user *models.User + bearer string + args string + wantStatus models.MCPAuditResultStatus + wantKind string + }{ + // A write the caller may make stays ok. + {"allowed write", f.member, f.memberPAT, create, models.MCPAuditResultOK, ""}, + // Refused before dispatch, by buildAuthedRequest's token-scope check. + // error_kind is code:reason, the reason BUG-3864 puts on the 403. + {"read-only key writes", f.member, readOnly.Token, create, models.MCPAuditResultDenied, "permission_denied:token_scope"}, + // Refused by the inner REST route's role check (an inner 403). + {"viewer writes", viewer, viewerPAT.Token, create, models.MCPAuditResultDenied, "permission_denied:role"}, + // A failure that is not a refusal is an error, with its code. + {"missing item", f.member, f.memberPAT, `{"action":"get","workspace":"cap-ws","ref":"TASK-99999"}`, models.MCPAuditResultError, "item_not_found"}, + // Refused by the catalog before any dispatch. + {"unknown action", f.member, f.memberPAT, `{"action":"show","workspace":"cap-ws","ref":"TASK-1"}`, models.MCPAuditResultError, "validation_failed"}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + bug3879Call(t, f, tc.user, tc.bearer, "pad_item", tc.args, tc.wantStatus, tc.wantKind) + }) + } + // mcp-go refuses an unknown tool before any tool middleware runs, with a + // JSON-RPC error inside a 200 (hunter r1 M1): the OnError hook's row. + t.Run("unknown tool", func(t *testing.T) { + bug3879Call(t, f, f.member, f.memberPAT, "pad_no_such_tool", `{}`, models.MCPAuditResultError, "tool_not_found") + }) +} + +// bug3879Call runs one tools/call and checks the one audit row it wrote. +// A tool failure answers with an error RESULT (isError); a call mcp-go +// refuses before any tool runs answers with a JSON-RPC error instead. +func bug3879Call(t *testing.T, f *capFixture, user *models.User, bearer, tool, args string, wantStatus models.MCPAuditResultStatus, wantKind string) { + t.Helper() + before := bug3879Rows(t, f, user.ID, tool) + body := `{"jsonrpc":"2.0","id":7,"method":"tools/call","params":{"name":"` + tool + `","arguments":` + args + `}}` + rr := bug3879Post(t, f, bearer, body) + if rr.Code != http.StatusOK { + t.Fatalf("tools/call answered %d, want the 200 this bug is about: %.300s", rr.Code, rr.Body.String()) + } + failed := strings.Contains(rr.Body.String(), `"isError":true`) || strings.Contains(rr.Body.String(), `"error":{"code":`) + if wantFailed := wantStatus != models.MCPAuditResultOK; failed != wantFailed { + t.Fatalf("precondition: call failed=%v, want %v: %.500s", failed, wantFailed, rr.Body.String()) + } + row := bug3879NextRow(t, f, user.ID, tool, before) + kind := "" + if row.ErrorKind != nil { + kind = *row.ErrorKind + } + if row.ResultStatus != wantStatus || kind != wantKind { + t.Fatalf("audit row = (%q, %q), want (%q, %q); response %.300s", + row.ResultStatus, kind, wantStatus, wantKind, rr.Body.String()) + } +} + +func bug3879Post(t *testing.T, f *capFixture, bearer, body string) *mcpRecorder { + t.Helper() + req, err := http.NewRequest(http.MethodPost, "/mcp", strings.NewReader(body)) + if err != nil { + t.Fatal(err) + } + req.Host = f.host + req.RemoteAddr = "192.0.2.10:4242" + req.Header.Set("Content-Type", "application/json") + req.Header.Set("Accept", "application/json, text/event-stream") + req.Header.Set("MCP-Protocol-Version", "2025-06-18") + req.Header.Set("Authorization", "Bearer "+bearer) + rr := newMCPRecorder() + f.srv.ServeHTTP(rr, req) + return rr +} + +// bug3879Rows is the user's audit rows for one tool. +func bug3879Rows(t *testing.T, f *capFixture, userID, tool string) []models.MCPAuditEntry { + t.Helper() + rows, err := f.store.ListMCPAuditByUser(userID, 100, 0) + if err != nil { + t.Fatalf("ListMCPAuditByUser: %v", err) + } + var out []models.MCPAuditEntry + for _, r := range rows { + if r.ToolName == tool { + out = append(out, r) + } + } + return out +} + +// bug3879NextRow waits for the one row the call wrote: the +// writer is asynchronous. The new row is found by id, not by position: +// two calls in one second tie on timestamp, and the tie-break is the +// random row id. +func bug3879NextRow(t *testing.T, f *capFixture, userID, tool string, before []models.MCPAuditEntry) models.MCPAuditEntry { + t.Helper() + seen := map[string]bool{} + for _, r := range before { + seen[r.ID] = true + } + deadline := time.Now().Add(5 * time.Second) + for { + rows := bug3879Rows(t, f, userID, tool) + if len(rows) == len(before)+1 { + for _, r := range rows { + if !seen[r.ID] { + return r + } + } + t.Fatal("one more row, but every id was already seen") + } + if len(rows) > len(before)+1 { + t.Fatalf("%d new %s rows, want exactly 1", len(rows)-len(before), tool) + } + if time.Now().After(deadline) { + t.Fatalf("no %s audit row within 5s", tool) + } + time.Sleep(20 * time.Millisecond) + } +} + +// BUG-3879 r4: since BUG-3864 an unverified email's refused write is its own +// code, email_not_verified, and it is a refusal like the other gates, so the +// audit row says denied. The Cloud fixture is the one BUG-3864's own test +// uses; the remote transport refuses in its gate before the request is built. +func TestBUG3879_UnverifiedEmailWriteAuditsAsDenied(t *testing.T) { + f := newCapFixture(t, cfgHTTP, true, nil, "true") + if err := f.store.SeedCollectionsFromTemplate(f.ws.ID, "startup"); err != nil { + t.Fatalf("SeedCollectionsFromTemplate: %v", err) + } + unverified := bug3864User(t, f, "bug3879-unverified@example.com", true) + if err := f.store.AddWorkspaceMember(f.ws.ID, unverified.ID, "owner"); err != nil { + t.Fatalf("AddWorkspaceMember: %v", err) + } + tok := bug3864Token(t, f, unverified, `["*"]`) + create := `{"action":"create","workspace":"cap-ws","collection":"tasks","title":"BUG-3879 unverified probe"}` + bug3879Call(t, f, unverified, tok, "pad_item", create, models.MCPAuditResultDenied, "email_not_verified") +} diff --git a/docs/api.md b/docs/api.md index a17622992..805a9cb96 100644 --- a/docs/api.md +++ b/docs/api.md @@ -129,7 +129,7 @@ One browser tab's content writes to an item are ordered by the server, also **pe - `PATCH /api/v1/admin/users/{userID}` — change a user's `role` (`admin`/`member`), `plan`, `plan_expires_at` or `plan_overrides` (admin-only). Demoting the instance's last ACTIVE human admin answers `409 last_active_admin` (BUG-3811; it used to answer `400 bad_request` "Cannot demote the last admin"); a disabled admin does not count. Changing your own role is `400 bad_request`. A role change for a user deleted while the request runs answers `404 not_found` (BUG-3826); the plan fields do not make that promise - `POST /api/v1/admin/users/{userID}/disable` — disable an account and revoke its sessions, API tokens and connected apps in one transaction (admin-only, BUG-3349). Disabling the last ACTIVE human admin answers `409 last_active_admin` (BUG-3811); disabling yourself is `400 bad_request`; a user deleted while the request runs answers `404 not_found` (BUG-3826) - `POST /api/v1/admin/test-email` — send test email (admin-only) -- `GET /api/v1/admin/mcp-audit?limit=&offset=` — every user's MCP calls, newest first (admin-only; limit default 50, capped at 200), plus `dropped` (audit rows lost to a full writer queue). Each item carries the raw `user_id` and `connection_id` (the OAuth grant's request id, or the PAT id), and since TASK-2255 (C110) the display names `user_name` (the name, else the email) and `connection_name` (the OAuth client's name, else the label the user gave the connection; for a PAT, its name). Both are omitted when the id no longer resolves (a deleted user, a revoked grant), and the page then shows the id. Resolved in one IN-list query per kind per page, not per row +- `GET /api/v1/admin/mcp-audit?limit=&offset=` — every user's MCP calls, newest first (admin-only; limit default 50, capped at 200). A row's `result_status` is the CALL's outcome: `ok` only when the call succeeded; `denied` when it was refused (401/403/429 at the transport, or a tool result with `permission_denied`, `auth_required`, `email_not_verified` or `rate_limited`); `error` for any other failure, including a JSON-RPC error a known method answers inside a 200 (`tool_not_found`, `resource_not_found`, `prompt_not_found`, else `jsonrpc_error`; a failed `initialize` or `tools/list` counts). A message mcp-go rejects before dispatching it to a method (an unknown method, a bad `jsonrpc` version) never reaches the hook and is still recorded as `ok`. A tool failure's `error_kind` is its MCP error code, or `:` when the error names its gate in `details.reason`; before BUG-3879 a tool call refused inside a 200 response was recorded as `ok`. Also returns `dropped` (audit rows lost to a full writer queue). Each item carries the raw `user_id` and `connection_id` (the OAuth grant's request id, or the PAT id), and since TASK-2255 (C110) the display names `user_name` (the name, else the email) and `connection_name` (the OAuth client's name, else the label the user gave the connection; for a PAT, its name). Both are omitted when the id no longer resolves (a deleted user, a revoked grant), and the page then shows the id. Resolved in one IN-list query per kind per page, not per row - `POST /api/v1/invitations/{code}/accept` — accept workspace invitation - `POST /api/v1/invitations/{code}/decline`, `POST /api/v1/me/invitations/{id}/decline` — decline a pending invitation (BUG-2136): it is deleted, as an owner's cancel does, and `member_invite_declined` is audited. By code, the caller must be signed in as the invited address; by id, the same admission as accept by id. 204 - `GET /api/v1/workspaces/{ws}/agent/bootstrap` — one-round-trip agent context (workspace + user + collections + always-on conventions + roles + playbook metadata + dashboard + `needs_onboarding` flag). Same payload as the MCP `pad://workspace/{ws}/bootstrap` resource and the `pad_set_workspace` embed. diff --git a/internal/mcp/audit_outcome.go b/internal/mcp/audit_outcome.go new file mode 100644 index 000000000..cfe9ddc60 --- /dev/null +++ b/internal/mcp/audit_outcome.go @@ -0,0 +1,111 @@ +package mcp + +import ( + "context" + "encoding/json" + "errors" + + "github.com/mark3labs/mcp-go/mcp" + "github.com/mark3labs/mcp-go/server" + + padserver "github.com/PerpetualSoftware/pad/internal/server" +) + +// recordToolOutcome is the tool-handler middleware that tells the /mcp +// audit log how a tool call ended (BUG-3879). A failed call answers the +// POST with 200, so the audit middleware cannot read the failure from the +// response status; this records the result's structured error code into +// the sink that middleware put on ctx. It sits at the server, not at the +// dispatch sites, because refusals are produced in many places (the +// pre-dispatch scope and verified-email gates in buildAuthedRequest, an +// inner route's 403, the ChatGPT scope challenge) and every one of them +// leaves through a tool result. Over stdio there is no sink and this does +// nothing. +func recordToolOutcome(next server.ToolHandlerFunc) server.ToolHandlerFunc { + return func(ctx context.Context, req mcp.CallToolRequest) (*mcp.CallToolResult, error) { + res, err := next(ctx, req) + switch { + case err != nil: + padserver.RecordMCPToolOutcome(ctx, string(ErrServerError), "") + case res != nil && res.IsError: + code, reason := toolErrorCode(res) + padserver.RecordMCPToolOutcome(ctx, code, reason) + } + return res, err + } +} + +// recordJSONRPCError is the OnError hook that records a JSON-RPC error +// response (BUG-3879 hunter r1 M1). mcp-go refuses an unknown tool, and +// answers a missing resource or prompt, before the tool-handler middleware +// is applied, with a JSON-RPC error inside a 200. A tool handler's own Go +// error reaches this hook too, after recordToolOutcome has recorded it; +// the sink keeps the first, so the row is unchanged. None of these is a +// refusal, so every code here audits as error. It fires for every method, +// not only tools/call: a failed initialize or tools/list did not succeed +// either (lead ruling R2 on BUG-3879). It does NOT see a message mcp-go +// rejects before dispatching it to a method (an unknown method, a bad +// jsonrpc version, a failed request-init): those still audit as ok, and no +// tool runs on them (hunter r2 L1). +func recordJSONRPCError(ctx context.Context, _ any, _ mcp.MCPMethod, _ any, err error) { + code := "jsonrpc_error" + switch { + case errors.Is(err, server.ErrToolNotFound): + code = "tool_not_found" + case errors.Is(err, server.ErrResourceNotFound): + code = "resource_not_found" + case errors.Is(err, server.ErrPromptNotFound): + code = "prompt_not_found" + } + padserver.RecordMCPToolOutcome(ctx, code, "") +} + +// toolErrorCode reads the code and details.reason of a failed result's +// error envelope: the structured content when it has one, else the text +// rendering, which NewErrorResult makes the same JSON. A result with no +// readable envelope (errorResultf's plain text) returns "", which the +// audit records as a tool_error. +func toolErrorCode(res *mcp.CallToolResult) (code, reason string) { + if res.StructuredContent != nil { + if b, err := json.Marshal(res.StructuredContent); err == nil { + if code, reason, ok := envelopeCode(b); ok { + return code, reason + } + } + } + for _, c := range res.Content { + var text string + switch t := c.(type) { + case mcp.TextContent: + text = t.Text + case *mcp.TextContent: + text = t.Text + } + if code, reason, ok := envelopeCode([]byte(text)); ok { + return code, reason + } + } + return "", "" +} + +// envelopeCode decodes {"error":{"code":...,"details":{"reason":...}}}. +// details is code-specific (open_children carries a list), so it is decoded +// apart: a details that is not an object loses the reason, never the code. +func envelopeCode(b []byte) (code, reason string, ok bool) { + var env struct { + Error struct { + Code string `json:"code"` + Details json.RawMessage `json:"details"` + } `json:"error"` + } + if json.Unmarshal(b, &env) != nil || env.Error.Code == "" { + return "", "", false + } + var d struct { + Reason string `json:"reason"` + } + if len(env.Error.Details) > 0 && json.Unmarshal(env.Error.Details, &d) == nil { + reason = d.Reason + } + return env.Error.Code, reason, true +} diff --git a/internal/mcp/audit_outcome_test.go b/internal/mcp/audit_outcome_test.go new file mode 100644 index 000000000..b1de32db5 --- /dev/null +++ b/internal/mcp/audit_outcome_test.go @@ -0,0 +1,116 @@ +package mcp + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "testing" + + "github.com/mark3labs/mcp-go/mcp" + + "github.com/PerpetualSoftware/pad/internal/models" + padserver "github.com/PerpetualSoftware/pad/internal/server" +) + +// BUG-3879: internal/server classifies a tool failure by code string, since +// it cannot import this package. These are the codes it must read as a +// refusal; a renamed constant would otherwise turn refusals into errors. +func TestToolOutcome_RefusalCodesAreDenied(t *testing.T) { + for _, code := range []ErrorCode{ErrPermissionDenied, ErrAuthRequired, ErrRateLimited} { + ctx, sink := padserver.WithMCPToolOutcomeSink(context.Background()) + padserver.RecordMCPToolOutcome(ctx, string(code), "") + if status, kind, _ := sink.Outcome(); status != models.MCPAuditResultDenied || kind != string(code) { + t.Errorf("%s audited as (%q, %q), want denied", code, status, kind) + } + } +} + +func TestToolErrorCode(t *testing.T) { + withReason := NewErrorResult(ErrorPayload{Code: ErrPermissionDenied, Message: "no", Details: json.RawMessage(`{"reason":"token_scope"}`)}) + listDetails := NewErrorResult(ErrorPayload{Code: ErrOpenChildren, Message: "open", Details: json.RawMessage(`[{"ref":"TASK-1"}]`)}) + textOnly := NewErrorResult(ErrorPayload{Code: ErrConflict, Message: "c"}) + textOnly.StructuredContent = nil + cases := []struct { + name string + res *mcp.CallToolResult + wantCode, wantWhy string + }{ + {"structured, with reason", withReason, "permission_denied", "token_scope"}, + {"details that is not an object keeps the code", listDetails, "open_children", ""}, + {"text rendering only", textOnly, "conflict", ""}, + {"plain text error", errorResultf("boom"), "", ""}, + } + for _, tc := range cases { + code, why := toolErrorCode(tc.res) + if code != tc.wantCode || why != tc.wantWhy { + t.Errorf("%s: (%q, %q), want (%q, %q)", tc.name, code, why, tc.wantCode, tc.wantWhy) + } + } +} + +// The middleware must be on every server NewServer builds, and outside +// WithRecovery, so a handler that panics or returns a Go error is still +// audited as a failure. Driven through the server's own message handling, +// as both transports do. +func TestToolOutcome_NewServerRecordsEveryEnding(t *testing.T) { + srv := NewServer(Options{Version: "test"}) + srv.MCP().AddTool(mcp.NewTool("refuse"), func(context.Context, mcp.CallToolRequest) (*mcp.CallToolResult, error) { + return NewErrorResult(ErrorPayload{Code: ErrPermissionDenied, Message: "no"}), nil + }) + srv.MCP().AddTool(mcp.NewTool("succeed"), func(context.Context, mcp.CallToolRequest) (*mcp.CallToolResult, error) { + return textResult("fine"), nil + }) + srv.MCP().AddTool(mcp.NewTool("go_error"), func(context.Context, mcp.CallToolRequest) (*mcp.CallToolResult, error) { + return nil, errors.New("handler failed") + }) + srv.MCP().AddTool(mcp.NewTool("panics"), func(context.Context, mcp.CallToolRequest) (*mcp.CallToolResult, error) { + panic("handler panicked") + }) + cases := []struct { + tool string + wantFailed bool + wantStatus models.MCPAuditResultStatus + wantKind string + }{ + {"refuse", true, models.MCPAuditResultDenied, "permission_denied"}, + {"succeed", false, "", ""}, + {"go_error", true, models.MCPAuditResultError, "server_error"}, + {"panics", true, models.MCPAuditResultError, "server_error"}, + // Refused by mcp-go before any middleware runs (hunter r1 M1). + {"no_such_tool", true, models.MCPAuditResultError, "tool_not_found"}, + } + for _, tc := range cases { + ctx, sink := padserver.WithMCPToolOutcomeSink(context.Background()) + srv.MCP().HandleMessage(ctx, json.RawMessage(`{"jsonrpc":"2.0","id":1,"method":"tools/call","params":{"name":"`+tc.tool+`","arguments":{}}}`)) + status, kind, failed := sink.Outcome() + if failed != tc.wantFailed || status != tc.wantStatus || kind != tc.wantKind { + t.Errorf("%s: (%q, %q, failed=%v), want (%q, %q, failed=%v)", tc.tool, status, kind, failed, tc.wantStatus, tc.wantKind, tc.wantFailed) + } + } +} + +// Lead ruling R2 on BUG-3879: the OnError hook is not scoped to tools/call, +// so a failed tools/list writes error, not ok. A cursor that is not one +// mcp-go issued fails the listing with INVALID_PARAMS. +func TestToolOutcome_AFailedToolsListIsAnError(t *testing.T) { + srv := NewServer(Options{Version: "test"}) + srv.MCP().AddTool(mcp.NewTool("succeed"), func(context.Context, mcp.CallToolRequest) (*mcp.CallToolResult, error) { + return textResult("fine"), nil + }) + ctx, sink := padserver.WithMCPToolOutcomeSink(context.Background()) + resp := srv.MCP().HandleMessage(ctx, json.RawMessage(`{"jsonrpc":"2.0","id":1,"method":"tools/list","params":{"cursor":"not-a-cursor-mcp-go-issued"}}`)) + raw, _ := json.Marshal(resp) + if !json.Valid(raw) || !bytes.Contains(raw, []byte(`"error"`)) { + t.Fatalf("precondition: tools/list did not fail: %s", raw) + } + if status, kind, failed := sink.Outcome(); !failed || status != models.MCPAuditResultError || kind != "jsonrpc_error" { + t.Fatalf("failed tools/list audited as (%q, %q, failed=%v), want (error, jsonrpc_error)", status, kind, failed) + } + // And a tools/list that succeeds stays ok. + ctx, sink = padserver.WithMCPToolOutcomeSink(context.Background()) + srv.MCP().HandleMessage(ctx, json.RawMessage(`{"jsonrpc":"2.0","id":2,"method":"tools/list"}`)) + if _, _, failed := sink.Outcome(); failed { + t.Fatal("a successful tools/list recorded a failure") + } +} diff --git a/internal/mcp/server.go b/internal/mcp/server.go index a731d4d0a..7685ce241 100644 --- a/internal/mcp/server.go +++ b/internal/mcp/server.go @@ -73,6 +73,11 @@ func NewServer(opts Options) *Server { // CAN serve tools. The list stays empty until TASK-945 wires // in the cmdhelp-derived registry. server.WithToolCapabilities(true), + // Tell the /mcp audit log how each tool call ended (BUG-3879). + // mcp-go makes the FIRST registered middleware the outermost, so + // this sits before WithRecovery: it sees a panic as the error the + // recovery turns it into. A no-op over stdio. + server.WithToolHandlerMiddleware(recordToolOutcome), // Recover from panics in tool handlers — important once the // shell-out dispatcher (TASK-945) starts running pad // subprocesses with arbitrary client-supplied args. @@ -90,10 +95,17 @@ func NewServer(opts Options) *Server { // advertises the same string. server.WithInstructions(instructions), } + // WithHooks replaces rather than adds, so every hook goes on one value. + hooks := &server.Hooks{} if opts.Clients != nil { // BUG-2772: record each session's declared client at initialize. - options = append(options, server.WithHooks(opts.Clients.hooks())) + hooks = opts.Clients.hooks() } + // BUG-3879: a JSON-RPC error answered before any tool handler runs + // (an unknown tool, a missing resource or prompt) reaches the audit + // log here, since the tool-handler middleware never sees it. + hooks.AddOnError(recordJSONRPCError) + options = append(options, server.WithHooks(hooks)) mcp := server.NewMCPServer(ServerName, version, options...) return &Server{mcp: mcp, debug: opts.Debug} } diff --git a/internal/metrics/metrics.go b/internal/metrics/metrics.go index 4e7be5e4b..1a6b3ad21 100644 --- a/internal/metrics/metrics.go +++ b/internal/metrics/metrics.go @@ -598,7 +598,7 @@ func New() *Metrics { mcpToolCallsTotal := prometheus.NewCounterVec(prometheus.CounterOpts{ Name: "pad_mcp_tool_calls_total", - Help: "Total number of MCP tool-call requests by user, tool, and outcome status.", + Help: "Total number of MCP tool-call requests by user, tool, and outcome status (ok: the call succeeded; denied: refused by auth, scope, role, an unverified email or rate limit; error: any other failure).", }, []string{"user_id", "tool", "status"}) // Buckets target the latency spread we expect for MCP tool calls: diff --git a/internal/server/mcp_tool_outcome.go b/internal/server/mcp_tool_outcome.go new file mode 100644 index 000000000..f1392625f --- /dev/null +++ b/internal/server/mcp_tool_outcome.go @@ -0,0 +1,99 @@ +package server + +import ( + "context" + "regexp" + "sync" + + "github.com/PerpetualSoftware/pad/internal/models" +) + +// A tool call that fails answers the /mcp POST with 200 and a tool-level +// error result, so the status MCPAuditLog reads from the response writer +// says nothing about it: a refused write was audited as ok (BUG-3879). +// The audit middleware therefore installs an outcome sink on the request +// context, and internal/mcp's tool-handler middleware, which sees every +// tool result on every MCP server pad builds, records a failed call's +// error code into it. The sink lives here rather than in internal/mcp +// because internal/mcp imports this package. + +type mcpToolOutcomeKey struct{} + +// MCPToolOutcomeSink holds the failure of the tool call a request carried. +// Guarded because the tool handler and the middleware that reads the sink +// are not ordered by anything the sink can see on every transport path. +type MCPToolOutcomeSink struct { + mu sync.Mutex + set bool + status models.MCPAuditResultStatus + kind string +} + +// WithMCPToolOutcomeSink returns ctx carrying a fresh sink, and the sink. +// MCPAuditLog is its production caller; it is exported for internal/mcp's +// tests, which drive the tool-handler middleware without the HTTP stack. +func WithMCPToolOutcomeSink(ctx context.Context) (context.Context, *MCPToolOutcomeSink) { + sink := &MCPToolOutcomeSink{} + return context.WithValue(ctx, mcpToolOutcomeKey{}, sink), sink +} + +// Outcome reports the recorded failure, if any. +func (s *MCPToolOutcomeSink) Outcome() (models.MCPAuditResultStatus, string, bool) { + s.mu.Lock() + defer s.mu.Unlock() + return s.status, s.kind, s.set +} + +// RecordMCPToolOutcome records that the tool call on ctx failed with the +// structured error code (one of internal/mcp's ErrorCode values) and, when +// the error payload carries one, its details.reason. A refusal is recorded +// as denied, any other failure as error. A no-op when no audit sink is on +// ctx (stdio, or a server built without MCPAuditLog). +// +// One /mcp POST carries one tools/call, so a sink sees one outcome; if it +// ever sees more, a refusal is kept over a plain error, because the refusal +// is what the audit log exists to show. +func RecordMCPToolOutcome(ctx context.Context, code, reason string) { + sink, _ := ctx.Value(mcpToolOutcomeKey{}).(*MCPToolOutcomeSink) + if sink == nil { + return + } + status, kind := classifyMCPToolOutcome(code, reason) + sink.mu.Lock() + defer sink.mu.Unlock() + if sink.set && (sink.status == models.MCPAuditResultDenied || status != models.MCPAuditResultDenied) { + return + } + sink.set, sink.status, sink.kind = true, status, kind +} + +// mcpErrorKindToken bounds what a tool's error code or reason may put in +// the audit row's error_kind: a short snake_case token. Anything else is +// replaced, so a payload can never write free text into the audit log. +var mcpErrorKindToken = regexp.MustCompile(`^[a-z][a-z0-9_]{0,63}$`) + +// classifyMCPToolOutcome maps a failed tool call's structured error code +// onto (audit_status, error_kind). The refusal codes are the ones the +// dispatcher gives a 401, 403 or 429 (or the pre-dispatch scope and +// verified-email gates that stand in for them): auth_required, +// permission_denied, email_not_verified and rate_limited are denied, as +// classifyMCPResult makes an outer 401/403/429. email_not_verified is its +// own code since BUG-3864, not a permission_denied reason. Every other code +// is an error; the plan and member limits stay errors (BUG-3894 owns that +// policy). error_kind is +// the code, plus ":" when the payload names the gate, so the cause +// survives rather than flattening to "forbidden". +func classifyMCPToolOutcome(code, reason string) (models.MCPAuditResultStatus, string) { + if !mcpErrorKindToken.MatchString(code) { + code = "tool_error" + } + kind := code + if reason != "" && mcpErrorKindToken.MatchString(reason) { + kind += ":" + reason + } + switch code { + case "auth_required", "permission_denied", "email_not_verified", "rate_limited": + return models.MCPAuditResultDenied, kind + } + return models.MCPAuditResultError, kind +} diff --git a/internal/server/mcp_tool_outcome_test.go b/internal/server/mcp_tool_outcome_test.go new file mode 100644 index 000000000..677a369b6 --- /dev/null +++ b/internal/server/mcp_tool_outcome_test.go @@ -0,0 +1,67 @@ +package server + +import ( + "context" + "testing" + + "github.com/PerpetualSoftware/pad/internal/models" +) + +// BUG-3879: how a failed tool call's structured error code becomes the +// audit row's (result_status, error_kind). +func TestClassifyMCPToolOutcome(t *testing.T) { + cases := []struct { + code, reason string + wantStatus models.MCPAuditResultStatus + wantKind string + }{ + {"permission_denied", "", models.MCPAuditResultDenied, "permission_denied"}, + {"permission_denied", "token_scope", models.MCPAuditResultDenied, "permission_denied:token_scope"}, + // email_not_verified is its own code (BUG-3864), and a refusal. + {"email_not_verified", "", models.MCPAuditResultDenied, "email_not_verified"}, + {"auth_required", "", models.MCPAuditResultDenied, "auth_required"}, + {"rate_limited", "", models.MCPAuditResultDenied, "rate_limited"}, + {"validation_failed", "", models.MCPAuditResultError, "validation_failed"}, + {"item_not_found", "", models.MCPAuditResultError, "item_not_found"}, + {"server_error", "", models.MCPAuditResultError, "server_error"}, + // No readable envelope. + {"", "", models.MCPAuditResultError, "tool_error"}, + // Neither field may write free text into the audit log. + {"Permission Denied!", "", models.MCPAuditResultError, "tool_error"}, + {"permission_denied", "a reason with spaces", models.MCPAuditResultDenied, "permission_denied"}, + } + for _, tc := range cases { + status, kind := classifyMCPToolOutcome(tc.code, tc.reason) + if status != tc.wantStatus || kind != tc.wantKind { + t.Errorf("classifyMCPToolOutcome(%q, %q) = (%q, %q), want (%q, %q)", + tc.code, tc.reason, status, kind, tc.wantStatus, tc.wantKind) + } + } +} + +func TestRecordMCPToolOutcome_RefusalOutranksError(t *testing.T) { + for _, order := range [][2]string{{"validation_failed", "permission_denied"}, {"permission_denied", "validation_failed"}} { + ctx, sink := WithMCPToolOutcomeSink(context.Background()) + RecordMCPToolOutcome(ctx, order[0], "") + RecordMCPToolOutcome(ctx, order[1], "") + status, kind, ok := sink.Outcome() + if !ok || status != models.MCPAuditResultDenied || kind != "permission_denied" { + t.Errorf("after %v: (%q, %q, %v), want the refusal", order, status, kind, ok) + } + } + // Two plain errors: the first stands. + ctx, sink := WithMCPToolOutcomeSink(context.Background()) + RecordMCPToolOutcome(ctx, "item_not_found", "") + RecordMCPToolOutcome(ctx, "validation_failed", "") + if _, kind, _ := sink.Outcome(); kind != "item_not_found" { + t.Errorf("two errors kept %q, want the first", kind) + } +} + +func TestRecordMCPToolOutcome_NoSinkIsANoOp(t *testing.T) { + RecordMCPToolOutcome(context.Background(), "permission_denied", "") // must not panic + _, sink := WithMCPToolOutcomeSink(context.Background()) + if _, _, ok := sink.Outcome(); ok { + t.Fatal("a fresh sink reports an outcome") + } +} diff --git a/internal/server/middleware_mcp_audit.go b/internal/server/middleware_mcp_audit.go index e86b78a13..87c5e6c16 100644 --- a/internal/server/middleware_mcp_audit.go +++ b/internal/server/middleware_mcp_audit.go @@ -26,14 +26,16 @@ import ( // the audit row carries the resolved user + token identity stashed on // context. Records one row per HTTP request hitting /mcp: // -// - Successful tool calls (200 OK with a JSON-RPC result envelope). -// - Tool calls that the inner handler rejected (200 OK with an error -// envelope — JSON-RPC errors are still HTTP 200 per spec). +// - Successful tool calls (200 OK with a JSON-RPC result envelope): ok. +// - Tool calls that failed or were refused (200 OK with an error +// result): denied or error, with the tool's error code as +// error_kind. The transport cannot show these, so the tool result +// reports them through RecordMCPToolOutcome (BUG-3879). // - Authorization gate misses (401 / 403). // - Server errors (5xx). // // Writes are async via a buffered channel + worker goroutine. The -// hot path captures the HTTP-level outcome, builds an MCPAuditEntry, +// hot path captures the outcome, builds an MCPAuditEntry, // and tries a non-blocking channel send; if the buffer is full // (DB outage / writer too slow), the entry is dropped and the // mcp_audit_dropped_total metric increments. The request never @@ -262,6 +264,11 @@ func (s *Server) MCPAuditLog(next http.Handler) http.Handler { // provides this — reuse rather than redo. ww := chimiddleware.NewWrapResponseWriter(w, r.ProtoMajor) + // BUG-3879: a failed tool call answers 200, so its outcome + // arrives through this sink, not through ww.Status(). + outcomeCtx, outcome := WithMCPToolOutcomeSink(r.Context()) + r = r.WithContext(outcomeCtx) + next.ServeHTTP(withFlushError(ww), r) // BUG-3827: chi drops flush errors latencyMs := int(time.Since(start) / time.Millisecond) @@ -291,6 +298,14 @@ func (s *Server) MCPAuditLog(next http.Handler) http.Handler { toolName, argsHash, toolNameSource := parseMCPRequestBodyWithSource(snifferBytes) status, errorKind := classifyMCPResult(ww.Status()) + // The transport status wins when it already refused or failed; + // only a request the transport let through can carry a tool + // failure (BUG-3879). + if status == models.MCPAuditResultOK { + if toolStatus, toolKind, failed := outcome.Outcome(); failed { + status, errorKind = toolStatus, toolKind + } + } entry := models.MCPAuditEntryInput{ Timestamp: start, @@ -583,17 +598,13 @@ func hashCanonicalJSON(raw json.RawMessage) string { // classifyMCPResult maps an HTTP status to (audit_status, error_kind). // -// JSON-RPC quirk: tool errors come back as 200 OK with an `error` -// field in the response body. We CAN'T see that here without -// snooping the response body too — and the spec for TASK-960 says -// "every MCP request results in exactly one audit-log row," not -// "every successful tool call." So we classify on transport-level -// status, with the understanding that result_status="ok" means -// "the gate let it through" rather than "the tool succeeded." That's -// the right granularity for forensics; per-tool success would need -// the dispatcher to emit its own audit signal post-execution, which -// is out of scope here (and probably belongs as a separate JSON-RPC -// success/failure stream). +// It classifies the TRANSPORT status only. A tool error comes back as +// 200 OK with an error result in the body, so on its own this function +// reads every failed tool call as ok. MCPAuditLog therefore overrides an +// ok with the tool call's own outcome when internal/mcp recorded one +// (RecordMCPToolOutcome, BUG-3879): result_status="ok" means the tool +// call succeeded, not merely that the gate let the request through. +// TASK-960's rule still holds: every MCP request gets exactly one row. func classifyMCPResult(httpStatus int) (models.MCPAuditResultStatus, string) { switch { case httpStatus == 0 || httpStatus == http.StatusOK: @@ -696,7 +707,8 @@ var _ func(http.Handler) http.Handler = (*Server)(nil).MCPAuditLog // (currently only "rate_limited" — extend if more denial paths // emit through here). Keeping the vocabulary aligned makes the // admin UI's status badges render consistently regardless of which -// emitter wrote the row. +// emitter wrote the row. Rows from MCPAuditLog can also carry a tool's +// error code, alone or as ":" (classifyMCPToolOutcome). // // latencyStart is the moment the request entered MCPBearerAuth so // the audit row carries real latency for denied requests too — diff --git a/web/src/routes/console/admin/mcp-audit/+page.svelte b/web/src/routes/console/admin/mcp-audit/+page.svelte index 3d4477829..028b56870 100644 --- a/web/src/routes/console/admin/mcp-audit/+page.svelte +++ b/web/src/routes/console/admin/mcp-audit/+page.svelte @@ -68,8 +68,9 @@ }); } - // Chip color for an MCP result status. These are transport results - // (ok / denied / error), not item statuses, so they map locally + // Chip color for an MCP result status. These are call outcomes + // (ok / denied / error; a refused tool call is denied even inside a + // 200, BUG-3879), not item statuses, so they map locally // rather than through fieldColors.statusColor (TASK-2292). function statusColor(status: string): string { if (status === 'ok') return 'var(--accent-green)';