metrics: stop counting client-cancelled requests as server errors (#1255)
## Summary
- Remap recorded status to `499` (NGINX-style "client closed") when
`ctx.Context().Err()` is `context.Canceled` after the handler returns
- Skip the `http_errors_total` increment for `499`s so the availability
metric reflects server-visible errors only
## Why
Under scraper-driven load, clients with short timeouts paginate
`/v0.1/servers`, give up while PG is busy, and close the TCP connection.
The handler's DB iteration returns `context canceled`, the handler
converts that to `huma.Error500InternalServerError`, and tries to write
a response to the now-closed socket. NGINX records `499` (client closed)
and never delivers anything to the client — but the registry's
middleware records `status_code=500` and bumps
`mcp_registry_http_errors_total`.
That's what's been firing the `Availability dropped below 95%` alert
during the daily 17:00 UTC bursts. Recent prod numbers from one pod
(~19h uptime):
```
mcp_registry_http_errors_total{path="/v0.1/servers", status_code="500"} 7396
mcp_registry_http_errors_total{path="/v0.1/servers/{serverName}/versions", status_code="500"} 283
mcp_registry_http_errors_total{path="/v0/servers", status_code="500"} 352
```
…against zero 5xx in NGINX ingress logs over the same window. The alert
was correct *given the data it had*; the data was misclassifying client
cancellations as server errors.
## What this does
In `internal/api/router/router.go` (the metric middleware): after
`next(ctx)`, check `ctx.Context().Err()`. If it's `context.Canceled`,
override `statusCode` to `499` and skip the error counter. Requests
counter and duration histogram still record so the cancellation rate
stays visible.
`context.DeadlineExceeded` is intentionally **not** remapped — that
would indicate a server-side timeout if we ever add per-request
deadlines, and should still count as a server error.
## What this does *not* do
- Doesn't reduce the underlying load (ServiceNow + notion catalog
scrapers driving the daily peak — separate work, see the `updated_since`
outreach we're doing).
- Doesn't change handler behaviour — handlers still call
`huma.Error500…` on `context.Canceled`. We could short-circuit earlier
(return without writing) to save the work, but that's a bigger refactor
and the metric fix unblocks the alert immediately.
## Companion change (no code, just a Grafana annotation tweak)
The `Availability dropped below 95%` alert (UID `bexrc60etvhmoa`)
currently has the annotation:
> No. of 5xx are increased from acceptable limit i.e. 5% of total
throughput
The query is on `mcp_registry_http_errors_total`, not 5xx specifically.
After this change the count is meaningful again, but the wording is
still misleading. Suggest updating to:
> Internal error rate exceeded 5% of total throughput
(no PromQL change required.)
## Test plan
- [x] `go test ./internal/api/router/...` — new test passes
- [x] `golangci-lint run ./internal/...` — clean
- [ ] After merge, watch a daily 17:00 UTC burst —
`mcp_registry_http_errors_total{status_code="500",
path="/v0.1/servers"}` should stay flat while
`mcp_registry_http_requests_total{status_code="499",
path="/v0.1/servers"}` grows. Availability alert should not fire on
cancellation-only bursts.
🤖 Generated with [Claude Code](https://claude.com/claude-code)
Co-authored-by: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
parent
6d6a887174
commit
4e147072f0
2 changed files with 146 additions and 1 deletions
|
|
@ -2,7 +2,9 @@
|
|||
package router
|
||||
|
||||
import (
|
||||
"context"
|
||||
"encoding/json"
|
||||
"errors"
|
||||
"fmt"
|
||||
"net/http"
|
||||
"strings"
|
||||
|
|
@ -19,6 +21,12 @@ import (
|
|||
"github.com/modelcontextprotocol/registry/internal/telemetry"
|
||||
)
|
||||
|
||||
// statusClientClosed mirrors NGINX's non-standard 499 — used for requests
|
||||
// where the client disconnected before we finished. Distinguishing these from
|
||||
// real server errors keeps the availability metric meaningful under bursts of
|
||||
// scraper traffic that time out and reconnect.
|
||||
const statusClientClosed = 499
|
||||
|
||||
// Middleware configuration options
|
||||
type middlewareConfig struct {
|
||||
skipPaths map[string]bool
|
||||
|
|
@ -67,6 +75,22 @@ func MetricTelemetryMiddleware(metrics *telemetry.Metrics, options ...Middleware
|
|||
duration := time.Since(start).Seconds()
|
||||
statusCode := ctx.Status()
|
||||
|
||||
// If the client disconnected before the handler finished, the handler
|
||||
// likely converted the resulting context.Canceled into a huma 5xx and
|
||||
// tried to write a response to a closed socket. NGINX records that
|
||||
// case as a 499 (client closed). Without this remap we count it as a
|
||||
// server error: a single ServiceNow-style burst that times out a
|
||||
// few thousand list-servers requests inflates http_errors_total even
|
||||
// though no client ever saw a 5xx, and the availability alert fires
|
||||
// on what is effectively just slow responses.
|
||||
//
|
||||
// Only context.Canceled is remapped — context.DeadlineExceeded would
|
||||
// indicate a server-side timeout we set ourselves and should still
|
||||
// count as a server error if/when we add per-request deadlines.
|
||||
if reqErr := ctx.Context().Err(); reqErr != nil && errors.Is(reqErr, context.Canceled) {
|
||||
statusCode = statusClientClosed
|
||||
}
|
||||
|
||||
// Combine common and custom attributes
|
||||
attrs := []attribute.KeyValue{
|
||||
attribute.String("method", method),
|
||||
|
|
@ -77,7 +101,9 @@ func MetricTelemetryMiddleware(metrics *telemetry.Metrics, options ...Middleware
|
|||
// Record metrics
|
||||
metrics.Requests.Add(ctx.Context(), 1, metric.WithAttributes(attrs...))
|
||||
|
||||
if statusCode >= 400 {
|
||||
// Skip the error counter for client-closed requests so the availability
|
||||
// metric reflects server-visible errors only.
|
||||
if statusCode >= 400 && statusCode != statusClientClosed {
|
||||
metrics.ErrorCount.Add(ctx.Context(), 1, metric.WithAttributes(attrs...))
|
||||
}
|
||||
|
||||
|
|
|
|||
119
internal/api/router/router_test.go
Normal file
119
internal/api/router/router_test.go
Normal file
|
|
@ -0,0 +1,119 @@
|
|||
package router_test
|
||||
|
||||
import (
|
||||
"context"
|
||||
"errors"
|
||||
"net/http"
|
||||
"net/http/httptest"
|
||||
"strings"
|
||||
"testing"
|
||||
|
||||
"github.com/danielgtaylor/huma/v2"
|
||||
"github.com/danielgtaylor/huma/v2/adapters/humago"
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
|
||||
"github.com/modelcontextprotocol/registry/internal/api/router"
|
||||
"github.com/modelcontextprotocol/registry/internal/telemetry"
|
||||
)
|
||||
|
||||
// TestMetricMiddleware_ClientCancelledNotCountedAsError verifies that a request
|
||||
// the client gave up on (request-context Canceled) is recorded as 499 in
|
||||
// http_requests_total and is NOT incremented in http_errors_total — even when
|
||||
// the handler returned huma.Error500InternalServerError because its DB call
|
||||
// surfaced context.Canceled.
|
||||
//
|
||||
// Regression test for the case where a ServiceNow-style scraper burst
|
||||
// generated thousands of internal 500s for cancelled requests, tripping the
|
||||
// "Availability dropped below 95%" alert despite zero 5xx reaching clients.
|
||||
func TestMetricMiddleware_ClientCancelledNotCountedAsError(t *testing.T) {
|
||||
shutdown, metrics, err := telemetry.InitMetrics("test")
|
||||
require.NoError(t, err)
|
||||
defer func() { _ = shutdown(context.Background()) }()
|
||||
|
||||
mux := http.NewServeMux()
|
||||
api := humago.New(mux, huma.DefaultConfig("Test API", "1.0.0"))
|
||||
api.UseMiddleware(router.MetricTelemetryMiddleware(metrics))
|
||||
|
||||
// Handler that simulates: DB returns context.Canceled because the client
|
||||
// disconnected, handler converts to huma 500.
|
||||
huma.Register(api, huma.Operation{
|
||||
OperationID: "cancelled-list",
|
||||
Method: http.MethodGet,
|
||||
Path: "/v0/servers",
|
||||
}, func(_ context.Context, _ *struct{}) (*struct{}, error) {
|
||||
return nil, huma.Error500InternalServerError("Failed to get registry list",
|
||||
errors.New("error iterating rows: context canceled"))
|
||||
})
|
||||
|
||||
mux.Handle("/metrics", metrics.PrometheusHandler())
|
||||
|
||||
cancelledCtx, cancel := context.WithCancel(context.Background())
|
||||
cancel()
|
||||
|
||||
req := httptest.NewRequest(http.MethodGet, "/v0/servers", nil).WithContext(cancelledCtx)
|
||||
rec := httptest.NewRecorder()
|
||||
mux.ServeHTTP(rec, req)
|
||||
|
||||
scrapeReq := httptest.NewRequest(http.MethodGet, "/metrics", nil)
|
||||
scrapeRec := httptest.NewRecorder()
|
||||
mux.ServeHTTP(scrapeRec, scrapeReq)
|
||||
assert.Equal(t, http.StatusOK, scrapeRec.Code)
|
||||
|
||||
body := scrapeRec.Body.String()
|
||||
|
||||
// The request is recorded — but as 499, not 500.
|
||||
assert.True(t,
|
||||
containsMetric(body, `mcp_registry_http_requests_total`, `status_code="499"`, `path="/v0/servers"`),
|
||||
"expected requests_total to record status_code=499 for the cancelled request; got:\n%s",
|
||||
filterMetricLines(body, "mcp_registry_http_requests_total"),
|
||||
)
|
||||
assert.False(t,
|
||||
containsMetric(body, `mcp_registry_http_requests_total`, `status_code="500"`, `path="/v0/servers"`),
|
||||
"did not expect requests_total to record status_code=500 for a client-cancelled request; got:\n%s",
|
||||
filterMetricLines(body, "mcp_registry_http_requests_total"),
|
||||
)
|
||||
|
||||
// The error counter is NOT bumped for 499s — that is the point of this fix.
|
||||
assert.False(t,
|
||||
containsMetric(body, `mcp_registry_http_errors_total`, `status_code="499"`),
|
||||
"errors_total must not be incremented for client-cancelled requests; got:\n%s",
|
||||
filterMetricLines(body, "mcp_registry_http_errors_total"),
|
||||
)
|
||||
assert.False(t,
|
||||
containsMetric(body, `mcp_registry_http_errors_total`, `status_code="500"`, `path="/v0/servers"`),
|
||||
"errors_total must not record a 500 for a request the client already gave up on; got:\n%s",
|
||||
filterMetricLines(body, "mcp_registry_http_errors_total"),
|
||||
)
|
||||
}
|
||||
|
||||
// containsMetric returns true iff some line in body starts with `metric{...}`
|
||||
// and that label set contains every requested label fragment.
|
||||
func containsMetric(body, metric string, labels ...string) bool {
|
||||
for _, line := range strings.Split(body, "\n") {
|
||||
if !strings.HasPrefix(line, metric+"{") {
|
||||
continue
|
||||
}
|
||||
ok := true
|
||||
for _, l := range labels {
|
||||
if !strings.Contains(line, l) {
|
||||
ok = false
|
||||
break
|
||||
}
|
||||
}
|
||||
if ok {
|
||||
return true
|
||||
}
|
||||
}
|
||||
return false
|
||||
}
|
||||
|
||||
func filterMetricLines(body, metric string) string {
|
||||
var lines []string
|
||||
for _, line := range strings.Split(body, "\n") {
|
||||
if strings.HasPrefix(line, metric) {
|
||||
lines = append(lines, line)
|
||||
}
|
||||
}
|
||||
return strings.Join(lines, "\n")
|
||||
}
|
||||
Loading…
Reference in a new issue