Record cancellation from what the reverse proxy observed, not the request context

Implemented-By: OpenCode session (model recorded in docs/implementer-log.md)
This commit is contained in:
2026-09-25 11:32:18 -07:00
parent 317293cfb3
commit f3dfdbfa50
3 changed files with 91 additions and 1 deletions
+7 -1
View File
@@ -54,7 +54,7 @@ func (p *Handler) forward(w http.ResponseWriter, r *http.Request, route, host, l
total := time.Since(started)
req := forwardRow(route, fp, model, host, started, waited, rev, rec.status, total.Milliseconds())
if r.Context().Err() != nil {
if rev.cancelled {
req.Status = 499
req.Err = "client cancelled"
}
@@ -126,6 +126,9 @@ type forwardState struct {
ttfb time.Time
streamed bool
tee *tee
// cancelled is set when the reverse proxy's ErrorHandler observed the client leaving before a
// response byte was written; it is the one signal that turns a delivered row into a 499.
cancelled bool
}
// statusRecorder records the status written and forwards Flush so the reverse proxy can stream.
@@ -215,6 +218,9 @@ func newReverseProxy(h Health, host, leaseState, ctxHeader string, target *url.U
},
ErrorHandler: func(w http.ResponseWriter, req *http.Request, err error) {
if errors.Is(err, context.Canceled) {
// The client left before any byte was written; record it so the row is a 499,
// not the post-hoc context check that misread a pooled close as a cancel.
rev.cancelled = true
return
}
h.MarkDown(host, err.Error())
+83
View File
@@ -0,0 +1,83 @@
package proxy_test
import (
"net/http"
"strings"
"sync"
"testing"
"time"
"git.wntrmute.dev/kyle/crossbar/internal/store"
)
// A response the proxy delivered in full is recorded with the status the upstream returned, even
// when the client closes its connection the instant the body ends. Cancellation is what the
// reverse proxy observed while forwarding (a transport error before any byte, or the client
// leaving mid-body), never a look at the request context after the forward returned.
//
// Each request uses its own connection and closes it as soon as the response is read, which is
// what a pooled client does when its idle pool is full; the server then cancels the request's
// context while the handler may still be writing the accounting row.
func TestServedResponseIsNeverRecordedCancelled(t *testing.T) {
alpha := newUpstream(t, "alpha")
alpha.delay = 20 * time.Millisecond
r := newRig(t, `
listen = "127.0.0.1:1"
queue_max = 64
[hosts.alpha]
base_url = %q
models = { "shared" = { parallel = 8 } }
[routes.r]
hosts = ["alpha"]
default_model = "shared"
`, alpha)
const n = 32
var wg sync.WaitGroup
codes := make([]int, n)
for i := 0; i < n; i++ {
wg.Add(1)
go func(i int) {
defer wg.Done()
client := &http.Client{Transport: &http.Transport{DisableKeepAlives: true}}
req, _ := http.NewRequest(http.MethodPost, r.front.URL+"/r/v1/chat/completions", strings.NewReader(conversation(i, 1)))
req.Header.Set("Content-Type", "application/json")
resp, err := client.Do(req)
if err != nil {
t.Error(err)
return
}
drain(resp)
codes[i] = resp.StatusCode
}(i)
}
wg.Wait()
for i, c := range codes {
if c != 200 {
t.Fatalf("request %d: status %d, want 200", i, c)
}
}
// Rows are written after each response completes; allow the store a moment to catch up.
var rows []store.UsageRow
deadline := time.Now().Add(3 * time.Second)
for time.Now().Before(deadline) {
rows, _ = r.store.Usage(time.Time{}, store.ByRoute)
if len(rows) == 1 && rows[0].Requests == n {
break
}
time.Sleep(20 * time.Millisecond)
}
if len(rows) != 1 || rows[0].Requests != n {
t.Fatalf("usage = %+v, want one row with %d requests", rows, n)
}
if rows[0].Errors != 0 {
t.Errorf("usage = %+v, want 0 errors: every response was delivered with status 200", rows[0])
}
counts, _ := r.store.StatusCounts(time.Time{})
for _, c := range counts {
if c.Status != 200 {
t.Errorf("status counts %+v: a delivered 200 was recorded as %d", counts, c.Status)
}
}
}