From 13ff6189850d294577d4bb84d88942fb6009fa4d Mon Sep 17 00:00:00 2001 From: Dan Barr <6922515+danbarr@users.noreply.github.com> Date: Thu, 7 May 2026 14:41:25 -0400 Subject: [PATCH] Skip WARN for non-POST Streamable HTTP requests The telemetry middleware logged WARN for every request where the MCP parser produced no method, treating absence of a method as a misconfig. That assumption holds for POST (which carries the JSON-RPC body) but not for valid Streamable HTTP lifecycle traffic: GET opens an SSE stream, DELETE terminates a session. Operator-driven sessions and keepalives produced one WARN per pod every ~30s, drowning real signals. Gate the warning on r.Method == POST so misconfiguration on the JSON-RPC path still surfaces while expected non-JSON-RPC requests stay quiet. Recording of mcp.server.operation.duration is unchanged. Fixes #4451 Co-Authored-By: Claude Opus 4.7 (1M context) --- pkg/telemetry/middleware.go | 8 +- pkg/telemetry/middleware_test.go | 123 +++++++++++++++++++++++++++++++ 2 files changed, 128 insertions(+), 3 deletions(-) diff --git a/pkg/telemetry/middleware.go b/pkg/telemetry/middleware.go index b7411da42a..cc17e5f4db 100644 --- a/pkg/telemetry/middleware.go +++ b/pkg/telemetry/middleware.go @@ -697,11 +697,13 @@ func (m *HTTPMiddleware) recordMetrics(ctx context.Context, r *http.Request, rw m.requestDuration.Record(ctx, duration.Seconds(), attrs) // Record OTEL MCP spec mcp.server.operation.duration for actual MCP requests. - // mcpMethod should never be "unknown" for requests reaching the MCP middleware; - // if it is, the middleware chain is misconfigured (see #3687). + // Only POST requests carry a JSON-RPC body; GET (SSE stream open) and DELETE + // (session termination) are valid Streamable HTTP lifecycle requests with no + // MCP method to record. An unknown method on a POST indicates either a + // misconfigured middleware chain (see #3687) or a parse failure. if mcpMethod != "unknown" { m.recordOperationDuration(ctx, r, mcpMethod, mcpResourceID, rw.statusCode, duration) - } else { + } else if r.Method == http.MethodPost { //nolint:gosec // G706: HTTP method and URL path from request slog.Warn("mcp method could not be determined, middleware may be misconfigured", "http_method", r.Method, "path", r.URL.Path) diff --git a/pkg/telemetry/middleware_test.go b/pkg/telemetry/middleware_test.go index 1404d4f6b5..32797cc25e 100644 --- a/pkg/telemetry/middleware_test.go +++ b/pkg/telemetry/middleware_test.go @@ -4,8 +4,10 @@ package telemetry import ( + "bytes" "context" "encoding/json" + "log/slog" "net/http" "net/http/httptest" "os" @@ -2209,6 +2211,127 @@ func TestHTTPMiddleware_OperationDuration(t *testing.T) { } } +// TestHTTPMiddleware_UnknownMethodWarning pins down the truth table for the +// "method could not be determined" diagnostic introduced in #3687 and refined +// in #4451: +// +// HTTP method | parsed MCP method | warn? | record operation duration? +// ------------+-------------------+-------+--------------------------- +// POST | tools/call | no | yes +// POST | | yes | no +// GET | | no | no +// DELETE | | no | no +// +// GET (SSE stream open) and DELETE (session termination) are valid Streamable +// HTTP lifecycle requests with no JSON-RPC body, so warning on them produces +// noise rather than signal. POST without a parsed method retains the warning +// because it indicates a real misconfiguration on the JSON-RPC path. +// +// Subtests redirect slog.Default (process-global), so they must not run in +// parallel. +// +//nolint:paralleltest,tparallel // Subtests redirect slog.Default, which is process-global state +func TestHTTPMiddleware_UnknownMethodWarning(t *testing.T) { + tests := []struct { + name string + httpMethod string + mcpRequest *mcpparser.ParsedMCPRequest + expectWarn bool + expectMetric bool + }{ + { + name: "POST with parsed MCP method records duration and does not warn", + httpMethod: http.MethodPost, + mcpRequest: &mcpparser.ParsedMCPRequest{ + Method: "tools/call", + ID: "1", + IsRequest: true, + }, + expectWarn: false, + expectMetric: true, + }, + { + name: "POST without parsed MCP method warns and does not record duration", + httpMethod: http.MethodPost, + mcpRequest: nil, + expectWarn: true, + expectMetric: false, + }, + { + name: "GET to /mcp does not warn (SSE stream open)", + httpMethod: http.MethodGet, + mcpRequest: nil, + expectWarn: false, + expectMetric: false, + }, + { + name: "DELETE to /mcp does not warn (session termination)", + httpMethod: http.MethodDelete, + mcpRequest: nil, + expectWarn: false, + expectMetric: false, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + var buf bytes.Buffer + handler := slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelWarn}) + orig := slog.Default() + slog.SetDefault(slog.New(handler)) + t.Cleanup(func() { slog.SetDefault(orig) }) + + reader := sdkmetric.NewManualReader() + meterProvider := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + + middleware := NewHTTPMiddleware( + Config{ServiceName: "test-service", ServiceVersion: "1.0.0"}, + tracenoop.NewTracerProvider(), + meterProvider, + "test-server", + "streamable-http", + ) + + wrappedHandler := middleware(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + })) + + req := httptest.NewRequest(tt.httpMethod, "/mcp", nil) + if tt.mcpRequest != nil { + ctx := context.WithValue(req.Context(), mcpparser.MCPRequestContextKey, tt.mcpRequest) + req = req.WithContext(ctx) + } + rec := httptest.NewRecorder() + wrappedHandler.ServeHTTP(rec, req) + + logged := buf.String() + if tt.expectWarn { + require.Contains(t, logged, "mcp method could not be determined", + "expected WARN for %s with no parsed MCP method", tt.httpMethod) + // Operators rely on these attributes to identify the offending traffic. + assert.Contains(t, logged, `"http_method":"`+tt.httpMethod+`"`) + assert.Contains(t, logged, `"path":"/mcp"`) + } else { + assert.NotContains(t, logged, "mcp method could not be determined", + "unexpected WARN for %s /mcp", tt.httpMethod) + } + + var rm metricdata.ResourceMetrics + require.NoError(t, reader.Collect(context.Background(), &rm)) + var hasOperationDuration bool + for _, sm := range rm.ScopeMetrics { + for _, m := range sm.Metrics { + if m.Name == metricOperationDuration { + hasOperationDuration = true + } + } + } + assert.Equal(t, tt.expectMetric, hasOperationDuration, + "mcp.server.operation.duration presence should match expectation") + }) + } +} + func TestRecordSSEConnection_DualEmission(t *testing.T) { t.Parallel()