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 <code>:<reason> 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
This commit is contained in:
xarmian
2026-10-18 11:12:41 -04:00
committed by GitHub
parent 52d13c070d
commit b13e842740
10 changed files with 618 additions and 21 deletions
@@ -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")
}
+1 -1
View File
@@ -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 `<code>:<reason>` 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.
+111
View File
@@ -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
}
+116
View File
@@ -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")
}
}
+13 -1
View File
@@ -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}
}
+1 -1
View File
@@ -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:
+99
View File
@@ -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 ":<reason>" 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
}
+67
View File
@@ -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")
}
}
+28 -16
View File
@@ -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 "<code>:<reason>" (classifyMCPToolOutcome).
//
// latencyStart is the moment the request entered MCPBearerAuth so
// the audit row carries real latency for denied requests too —
@@ -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)';