/v0/servers logs benign client cancellations as "list servers failed" and triggers "superfluous response.WriteHeader" warnings

[tadasant]

🤖 This issue was generated by Claude Code.

Thanks to @pree-dew (Pree) for reporting these log lines at the last Registry Working Group meeting. 🙏

Summary

When a client disconnects mid-request on GET /v0/servers, the list handler does not detect the cancellation. It (a) logs the resulting context.Canceled at default level as list servers failed: ..., and (b) returns huma.Error500InternalServerError, which makes huma attempt to write a status to an already-committed/closed response — producing a superfluous response.WriteHeader call warning. Both are benign-but-noisy: no real client is affected, because the client has already gone away.

Observed log lines (production)

2026/05/28 20:28:26 list servers failed: error iterating rows: context canceled
... superfluous response.WriteHeader call from github.com/danielgtaylor/huma/v2/adapters/humago.(*goContext).SetStatus (humago.go:110)

Root cause

internal/api/handlers/v0/servers.go (~line 135) logs and 500s on every error from the service, with no special-casing for client cancellation:

servers, nextCursor, err := registry.ListServers(ctx, filter, input.Cursor, input.Limit)
if err != nil {
    log.Printf("list servers failed: %v", err)
    return nil, huma.Error500InternalServerError("Failed to get registry list")
}

The error string originates from internal/database/postgres.go (~line 262), fmt.Errorf("error iterating rows: %w", err), where rows.Err() returns context.Canceled when the client disconnects during row streaming. Returning a huma 5xx here then drives humago's SetStatus (adapters/humago/humago.go:110, which calls w.WriteHeader unguarded) to write a status onto a response whose header is already committed → the superfluous response.WriteHeader call warning.

So the two log lines are two symptoms of one root cause: the list handler does not short-circuit on client cancellation.

Affected files

• internal/api/handlers/v0/servers.go (≈ line 135) — unconditional error log + 500
• internal/database/postgres.go (≈ line 262) — error origin (the same error iterating rows pattern also appears at ≈ lines 479 and 722 and shares the exposure)
• internal/service/registry_service.go (≈ line 55) — pass-through

Relationship to existing work

• metrics: stop counting client-cancelled requests as server errors #1255 (merged) fixed only the metrics side — it remaps cancelled 500→499 in internal/api/router/router.go and skips http_errors_total. Its description explicitly notes handlers "still call huma.Error500… on context.Canceled" and "tried to write a response to a closed socket", i.e. the handler-side logging and double-write were deliberately left out of scope.
• API latency: /v0/servers reads consistently take 20–25s #1252 (open) tracks the underlying /v0/servers latency that causes clients to time out and cancel in the first place. This issue is about the noisy logging/response behavior and is independent of the latency fix.

A regression test already associates this exact error string with cancellation: internal/api/router/router_test.go's TestMetricMiddleware_ClientCancelledNotCountedAsError simulates it with errors.New("error iterating rows: context canceled").

Suggested fix direction

Detect cancellation in the list handler before logging an error or returning a 5xx, e.g.:

if err != nil {
    if errors.Is(err, context.Canceled) || ctx.Err() != nil {
        // client went away — nothing to return; skip the noisy error log and 5xx
        return nil, huma.Error499ClientClosedRequest(...) // or return the context error without error-level logging
    }
    log.Printf("list servers failed: %v", err)
    return nil, huma.Error500InternalServerError("Failed to get registry list")
}

Returning early (without invoking the error-response writer) also prevents the second WriteHeader. Consider applying the same guard to the other handlers that call streaming db.* methods, and/or downgrading cancellation to a debug-level log. A small regression test mirroring the existing TestMetricMiddleware_ClientCancelledNotCountedAsError could assert that no error-level log / no 5xx is produced on cancellation.

Reproduction

make dev-compose, then curl --max-time 0.05 http://localhost:8080/v0/servers (or start the request and abort it). Both log lines appear on the server.

Severity

Low — log noise only; no client-visible incorrect behavior. Worth fixing to keep stderr/alerting signal clean and to avoid masking genuine double-write bugs.

[pree-dew]

Did some debugging around this issue. Here are the findings:

Note the timing of errors, its happening every day around midnight (will be useful to connect later)

• Both issue of timeout and superfluous are happening at same time.

Proof:

================================================================

• At the same time there is a surge in traffic on /servers endpoint and the pattern is same, its happening everyday at midnight

Proof:

================================================================

• At the same time there is CPU spike and again the pattern is same, its happening everyday at midnight

Proof:

All resources are showing spike at the same time

=============================================================

As per above insights these are the possible scenario for context timeouts/latency/huma errors:

• We might be spending good amount of time to free up postgres connection which resulting into postgres queue filling up.
• Either we are short on resources in terms of CPU and number of connections for the load that we are receiving.
• We are spending good amount of time while processing query results resulting into high CPU usage.
• Postgres queries are also slow along with high CPU processing time.

we should also check if our rate limiting in kicking or not on such high throughput

These timeouts are resulting into huma errors also, in this way

As per huma flow
      │
      ├─ ctx.SetStatus(200) → WriteHeader(200) ← first call, headers committed
      │
      ├─ api.Marshal(ctx.BodyWriter(), ...) ← tries to write the JSON body
      │               └─ **FAILS — client already disconnected**
      │
      └─ detects context.Canceled
                       ctx.SetStatus(499) → WriteHeader(499) ← SECOND call → WARNING

As per all above scenarios, solution will change. I will do load testing to confirm which one of above scenario or possible multiple scenarios are true. Once we find that then we can decide at which layer we should think about solution.

[rdimitrov]

Sorry for the noise, #1335 only covered part of it and falsely marked this as completed

[pree-dew]

Did load testing for the production load with around 19k server entries. These are the insights:

• Number of go routines are around 8K to 12K during peak load.
• Heap idle memory is very small.
• CPU is also high since GC is continuously triggering.
• Requests are getting timeout as it is either waiting for postgres queue or taking time to process since CPU is already high.

Problem is we are not able to handle the RPS at this volume, because as the RPS cross 300 CPU consumption, heap and go routines increase sharply defining that as a limit our service can handle as of now. If the RPS is smaller than this our api is quite fast which highlights the fact that DB queries are not an issue here.

In order to fix this we can consider these options:

1. Have a CDN in place which will cache most of the requests.
2. Try to increase the RPS by decreasing the CPU processing happening after fetching high number of servers.
3. Increase resources by figuring out the throughput we can handle as per current allocation and enabling auto scaling on top of it.

I would suggest to go with CDN layer caching as solution as it will generally bring down overall latency and will not bring that much load on the backend service. We have 3 options for this

• Cloud CDN
• Cloudflare
• Fastly

@rdimitrov @tadasant These are the insights from my load testing, your feedback will be very helpful here before I start with solution.

[tadasant]

@pree-dew I had Claude POC a change: modelcontextprotocol/dns#26

Not intended to be driven to completion on that branch (I closed), just wanted to check we didn't have blockers to executing this (besides eventually merging a PR there). Seems we should be all clear for you tackle as you have time 👍

[pree-dew]

Super, @tadasant Thank you 🙏

[piyushbag]

Following up on the handler-side scope rdimitrov called out after #1335: I am opening a PR to apply the same client-cancellation handling (499, no error-level log, no second WriteHeader) to GET .../servers/{serverName}/versions/{version} and GET .../servers/{serverName}/versions. Scoped to those two handlers plus unit tests; not the CDN/RPS work pree-dew is tracking separately.

[pree-dew]

@rdimitrov
Design document for enabling cloudflare https://app.notion.com/p/Cloudflare-Edge-Caching-for-the-MCP-Registry-3bb36f79f7498010800bc5d8a5db62b0?source=copy_link