feat(mcp): log JSON-RPC method and tool name on per-request slog line

docs/architecture.md

@@ -181,7 +181,11 @@ and commit completion. The service layer closes that gap on failure:
   `internal/storage/`, and `internal/runner/` retrieve the logger via
   `ctxlog.Logger(ctx)` so every log line emitted during a request carries the
   same correlation ID. Falls back to `slog.Default()` for background contexts
-  that bypass the middleware (e.g. stall scanner goroutine).
+  that bypass the middleware (e.g. stall scanner goroutine). Also stores a
+  `*MCPCall` in the context (via `ctxlog.WithMCPCall`) for `/mcp` requests;
+  `mcpRequestInfoMiddleware` in `internal/mcp/server.go` populates it with
+  the JSON-RPC `method` and tool `name`, which the `observe` middleware then
+  appends as `mcp_method` / `mcp_tool` fields on the per-request log line.
 - **Metrics** (`metrics`): declares all Prometheus metric vars and exposes a
   `Register(prometheus.Registerer)` function called once at startup in
   `main.go`. Metrics are served at `GET /metrics` on the **admin listener** only

docs/gotchas.md

@@ -116,6 +116,18 @@
   not carry the correlation ID. Background goroutines (stall scanner, git-pull
   ticker) do not go through the middleware; `ctxlog.Logger(ctx)` falls back to
   `slog.Default()` safely in those paths.
+- **MCP tool name in the request log line:** for `POST /mcp` requests the
+  `observe` middleware emits two extra fields alongside the standard `method`,
+  `path`, `status`, `duration_ms`, and `request_id` fields:
+  `mcp_method` (JSON-RPC method, e.g. `tools/call`) and `mcp_tool` (tool name,
+  e.g. `claim_card` or `report_usage`). Both fields are omitted for non-MCP
+  routes and for MCP methods other than `tools/call` (e.g. `initialize`) where
+  there is no tool name. The extraction is best-effort — a body-peeking
+  middleware (`mcpRequestInfoMiddleware` in `internal/mcp/server.go`) reads the
+  request body, parses the JSON-RPC envelope, restores the body, and writes the
+  results into a `*ctxlog.MCPCall` stashed in the context by `observe`. Errors
+  during extraction are swallowed; the log line is still emitted with whatever
+  fields were successfully extracted.
 - **`/metrics` and pprof live on the admin port:** Prometheus scraping
   (`GET /metrics`) and `/debug/pprof/*` are served only on the admin listener
   (`admin_port`), which defaults to `127.0.0.1` (`admin_bind_addr`). The main

internal/api/router.go

@@ -2,6 +2,7 @@
 package api
 
 import (
+	"context"
 	"encoding/json"
 	"errors"
 	"log/slog"
@@ -307,19 +308,40 @@ func observe(next http.Handler) http.Handler {
 			return
 		}
 
+		// For MCP requests, stash an MCPCall pointer in context so that the
+		// inner mcpRequestInfoMiddleware can populate method/tool after parsing
+		// the JSON-RPC body. We hold the pointer here so we can read it back
+		// after ServeHTTP returns to append mcp_method/mcp_tool to the log line.
+		var mcpCall *ctxlog.MCPCall
+
+		if r.URL.Path == "/mcp" {
+			var ctx context.Context
+
+			ctx, mcpCall = ctxlog.WithMCPCall(r.Context())
+			r = r.WithContext(ctx)
+		}
+
 		rw := &responseWriter{ResponseWriter: w, statusCode: http.StatusOK}
 		start := time.Now()
 
 		next.ServeHTTP(rw, r)
 
 		dur := time.Since(start)
 
-		ctxlog.Logger(r.Context()).Info("request",
+		attrs := []any{
 			"method", r.Method,
 			"path", r.URL.Path,
 			"status", rw.statusCode,
 			"duration_ms", dur.Milliseconds(),
-		)
+		}
+		if mcpCall != nil && mcpCall.Method != "" {
+			attrs = append(attrs, "mcp_method", mcpCall.Method)
+			if mcpCall.Tool != "" {
+				attrs = append(attrs, "mcp_tool", mcpCall.Tool)
+			}
+		}
+
+		ctxlog.Logger(r.Context()).Info("request", attrs...)
 
 		// SSE streams would pollute the REST latency histogram and the
 		// path label set — skip them entirely for metrics. MCP Streamable

internal/ctxlog/ctxlog.go

@@ -12,6 +12,34 @@ import (
 // contextKey is an unexported type for context keys in this package.
 type contextKey struct{}
 
+// mcpCallKey is the context key for storing *MCPCall.
+type mcpCallKey struct{}
+
+// MCPCall holds MCP-specific request metadata populated by mcpRequestInfoMiddleware.
+// Both fields start empty and are filled in after the JSON-RPC body is parsed.
+type MCPCall struct {
+	Method string // JSON-RPC method (e.g. "tools/call", "notifications/initialized")
+	Tool   string // tool name for tools/call requests; empty otherwise
+}
+
+// WithMCPCall stashes an empty *MCPCall in ctx and returns both the enriched
+// context and the pointer. The caller (observe middleware) holds the pointer so
+// downstream middleware (mcpRequestInfoMiddleware) can mutate it, and the
+// pointer is readable after ServeHTTP returns.
+func WithMCPCall(ctx context.Context) (context.Context, *MCPCall) {
+	call := &MCPCall{}
+
+	return context.WithValue(ctx, mcpCallKey{}, call), call
+}
+
+// MCPCallFromContext retrieves the *MCPCall stored by WithMCPCall, or nil if
+// no value is present (e.g. non-MCP requests or tests that skip middleware).
+func MCPCallFromContext(ctx context.Context) *MCPCall {
+	call, _ := ctx.Value(mcpCallKey{}).(*MCPCall)
+
+	return call
+}
+
 // WithRequestID returns a new context that carries a *slog.Logger
 // derived from slog.Default() with the "request_id" attribute set to id.
 // Retrieve the logger with Logger(ctx).

internal/ctxlog/ctxlog_test.go

@@ -54,6 +54,27 @@ func TestLogger_fallback(t *testing.T) {
 		"Logger on empty context should return slog.Default()")
 }
 
+func TestWithMCPCall_roundtrip(t *testing.T) {
+	ctx, call := ctxlog.WithMCPCall(context.Background())
+	require.NotNil(t, call)
+
+	// Mutate via the returned pointer.
+	call.Method = "tools/call"
+	call.Tool = "claim_card"
+
+	// Retrieving via context should return the same pointer, not a copy.
+	got := ctxlog.MCPCallFromContext(ctx)
+	require.NotNil(t, got)
+	assert.Same(t, call, got, "MCPCallFromContext should return the same pointer")
+	assert.Equal(t, "tools/call", got.Method)
+	assert.Equal(t, "claim_card", got.Tool)
+}
+
+func TestMCPCallFromContext_missing(t *testing.T) {
+	got := ctxlog.MCPCallFromContext(context.Background())
+	assert.Nil(t, got, "MCPCallFromContext on a bare context should return nil")
+}
+
 func TestWithRequestID_differentIDs(t *testing.T) {
 	restoreSlogDefault(t)
 

internal/mcp/logging_test.go

@@ -0,0 +1,169 @@
+package mcp
+
+import (
+	"bytes"
+	"io"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+
+	"github.com/mhersson/contextmatrix/internal/ctxlog"
+)
+
+// TestMCPRequestInfoMiddleware verifies that mcpRequestInfoMiddleware correctly
+// extracts JSON-RPC method and tool name from the request body and populates the
+// MCPCall stored in context, while always restoring the body for downstream handlers.
+func TestMCPRequestInfoMiddleware(t *testing.T) {
+	tests := []struct {
+		name          string
+		httpMethod    string
+		body          string
+		wantMethod    string
+		wantTool      string
+		bodyInContext bool // whether to inject MCPCall into the context
+	}{
+		{
+			name:          "tools/call body populates method and tool",
+			httpMethod:    http.MethodPost,
+			body:          `{"jsonrpc":"2.0","method":"tools/call","params":{"name":"claim_card"}}`,
+			wantMethod:    "tools/call",
+			wantTool:      "claim_card",
+			bodyInContext: true,
+		},
+		{
+			name:          "notifications/initialized body populates method only",
+			httpMethod:    http.MethodPost,
+			body:          `{"jsonrpc":"2.0","method":"notifications/initialized","params":{}}`,
+			wantMethod:    "notifications/initialized",
+			wantTool:      "",
+			bodyInContext: true,
+		},
+		{
+			name:          "malformed JSON leaves fields empty",
+			httpMethod:    http.MethodPost,
+			body:          `not-json`,
+			wantMethod:    "",
+			wantTool:      "",
+			bodyInContext: true,
+		},
+		{
+			name:          "GET method is a no-op (call pointer unmodified)",
+			httpMethod:    http.MethodGet,
+			body:          `{"jsonrpc":"2.0","method":"tools/call","params":{"name":"claim_card"}}`,
+			wantMethod:    "",
+			wantTool:      "",
+			bodyInContext: true,
+		},
+	}
+
+	for _, tc := range tests {
+		t.Run(tc.name, func(t *testing.T) {
+			originalBody := tc.body
+
+			// Build context: inject an MCPCall if the test scenario requires it.
+			ctx := t.Context()
+
+			var call *ctxlog.MCPCall
+			if tc.bodyInContext {
+				ctx, call = ctxlog.WithMCPCall(ctx)
+			}
+
+			// Downstream handler: reads r.Body and asserts it equals the original bytes.
+			downstream := http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) {
+				if r.Body != nil {
+					got, err := io.ReadAll(r.Body)
+					assert.NoError(t, err)
+					assert.Equal(t, originalBody, string(got),
+						"downstream should see the original body bytes")
+				}
+			})
+
+			handler := mcpRequestInfoMiddleware(downstream)
+
+			req := httptest.NewRequest(tc.httpMethod, "/mcp", strings.NewReader(tc.body))
+			req = req.WithContext(ctx)
+			rw := httptest.NewRecorder()
+
+			handler.ServeHTTP(rw, req)
+
+			if tc.bodyInContext {
+				require.NotNil(t, call)
+				assert.Equal(t, tc.wantMethod, call.Method, "Method mismatch")
+				assert.Equal(t, tc.wantTool, call.Tool, "Tool mismatch")
+			}
+		})
+	}
+}
+
+// TestMCPRequestInfoMiddleware_nilContext verifies that a nil MCPCall in context
+// (no /mcp route injection) is handled defensively — middleware delegates to next
+// without panicking.
+func TestMCPRequestInfoMiddleware_nilContext(t *testing.T) {
+	called := false
+	downstream := http.HandlerFunc(func(_ http.ResponseWriter, r *http.Request) {
+		called = true
+
+		body, err := io.ReadAll(r.Body)
+		assert.NoError(t, err)
+		assert.JSONEq(t, `{"method":"tools/call"}`, string(body))
+	})
+
+	handler := mcpRequestInfoMiddleware(downstream)
+
+	req := httptest.NewRequest(http.MethodPost, "/mcp",
+		bytes.NewBufferString(`{"method":"tools/call"}`))
+	// No MCPCall injected into context.
+
+	rw := httptest.NewRecorder()
+	handler.ServeHTTP(rw, req)
+
+	assert.True(t, called, "downstream should be called even when MCPCall is absent from context")
+}
+
+// TestMCPRequestInfoMiddleware_truncatesLongFields verifies that an
+// authenticated client cannot use a multi-megabyte JSON-RPC method or tool name
+// to amplify the per-request slog line. Both fields are capped at maxLogFieldLen.
+func TestMCPRequestInfoMiddleware_truncatesLongFields(t *testing.T) {
+	longMethod := strings.Repeat("M", maxLogFieldLen*4)
+	longTool := strings.Repeat("T", maxLogFieldLen*4)
+
+	// Build a body where method == "tools/call" so the tool branch fires, but
+	// also include an oversize method via a separate body that uses the long
+	// method literally.
+	bodyToolsCall := `{"jsonrpc":"2.0","method":"tools/call","params":{"name":"` + longTool + `"}}`
+	bodyLongMethod := `{"jsonrpc":"2.0","method":"` + longMethod + `","params":{}}`
+
+	t.Run("tools/call with long tool name", func(t *testing.T) {
+		ctx, call := ctxlog.WithMCPCall(t.Context())
+		downstream := http.HandlerFunc(func(_ http.ResponseWriter, _ *http.Request) {})
+		handler := mcpRequestInfoMiddleware(downstream)
+
+		req := httptest.NewRequest(http.MethodPost, "/mcp", strings.NewReader(bodyToolsCall))
+		req = req.WithContext(ctx)
+
+		handler.ServeHTTP(httptest.NewRecorder(), req)
+
+		assert.Equal(t, "tools/call", call.Method)
+		assert.LessOrEqual(t, len(call.Tool), maxLogFieldLen+len("…"),
+			"Tool should be truncated to at most maxLogFieldLen + ellipsis")
+	})
+
+	t.Run("long method name", func(t *testing.T) {
+		ctx, call := ctxlog.WithMCPCall(t.Context())
+		downstream := http.HandlerFunc(func(_ http.ResponseWriter, _ *http.Request) {})
+		handler := mcpRequestInfoMiddleware(downstream)
+
+		req := httptest.NewRequest(http.MethodPost, "/mcp", strings.NewReader(bodyLongMethod))
+		req = req.WithContext(ctx)
+
+		handler.ServeHTTP(httptest.NewRecorder(), req)
+
+		assert.LessOrEqual(t, len(call.Method), maxLogFieldLen+len("…"),
+			"Method should be truncated to at most maxLogFieldLen + ellipsis")
+		assert.Empty(t, call.Tool, "Tool should be empty for non-tools/call methods")
+	})
+}