diff --git a/docs/plans/v2.1/01-cancel-record.md b/docs/plans/v2.1/01-cancel-record.md new file mode 100644 index 0000000..5b0cc6d --- /dev/null +++ b/docs/plans/v2.1/01-cancel-record.md @@ -0,0 +1,68 @@ +# v2.1 task 01: a delivered response is never recorded as cancelled + +**Branch:** `v2.1` (run `git switch -c v2.1 master` if it does not exist, else `git switch v2.1`; `git status --short` must be empty, otherwise stop) +**Commit subject:** `Record cancellation from what the reverse proxy observed, not the request context` + +## Goal + +The accounting row for a forwarded request takes its status from what the reverse proxy did. +A response that was delivered in full is recorded with the status the upstream returned, even +when the client closes its connection the instant the body ends. Status 499 ("client +cancelled") is recorded in exactly two cases: the reverse proxy's transport failed with a +context error before any response byte was written, or the client left mid-body (the +`http.ErrAbortHandler` panic the recover path already handles). + +## Context + +v1's `forward.go` writes the row after `rp.ServeHTTP` returns and, if `r.Context().Err()` is +non-nil at that moment, turns the row into a 499 error. The server cancels a request's context +when the client's connection closes, and a pooled client closes a connection as soon as it has +read a response whenever its idle pool is full. So a served 200 becomes a recorded 499 whenever +that close lands before the row is written. Measured on 2026-09-25: about a third of delivered +responses under the given test's load; `TestQueueFullIs503` flaked on it. The reverse proxy's +`ErrorHandler` already sees `context.Canceled` for the "client gone before the response" case +and currently returns without leaving a trace, which is why the post-hoc check was there. + +## Files + +- Copy: `internal/proxy/served_test.go` +- Modify: `internal/proxy/forward.go`, `docs/implementer-log.md` + +## Rules the tests check + +- `TestServedResponseIsNeverRecordedCancelled` (given): 32 concurrent requests on one host + (`parallel = 8`, `queue_max = 64`), each on its own connection that closes after the response + is read; every response is 200; the usage row has 32 requests and **0 errors**; the status + counts hold only status 200. +- `TestClientCancelMidStreamIsRecorded` and `TestClientCancelWhileQueuedIsRecorded` (v1, in the + tree) still pass: mid-stream and while-queued cancellations are still 499 rows with a + non-empty `err`. +- `TestQueueFullIs503` (v1, in the tree) still passes: 3 requests, 1 error. + +Rule for the implementation: the `ErrorHandler` records that it observed a cancellation (a +field on `forwardState` is the natural place) and the row is 499 when that field is set or the +recover path saw `http.ErrAbortHandler`. The check of `r.Context().Err()` after the forward is +removed. Nothing else in the row changes. `forward.go` stays under 400 lines. + +## Steps + +- [ ] **1.** Branch as above; copy the given test. +- [ ] **2. See it fail:** `go test -race -count=3 -run 'TestServedResponseIsNeverRecordedCancelled$' ./internal/proxy/` fails every run with `want 0 errors`. +- [ ] **3.** Change `forward.go` per the rule. `gofmt -w internal/proxy/`. +- [ ] **4.** `go test -race -count=3 ./internal/proxy/` → `ok` three times. **5.** `go test -race -count=1 ./...` → all `ok`. +- [ ] **6.** `make gate`. **7.** Row `v2.1/01-cancel-record`; commit. + +```sh +git add internal/proxy docs/implementer-log.md +git commit +``` + +## Done when + +- The given test passes three times in a row under `-race`; the two v1 cancel tests and + `TestQueueFullIs503` pass; gate ok; the given file byte-identical. + +## Stop and report if + +- The given test still fails after the post-hoc check is gone: quote the status counts. +- Making the given test pass requires editing any `_test.go` file. diff --git a/docs/plans/v2.1/README.md b/docs/plans/v2.1/README.md new file mode 100644 index 0000000..e50fe58 --- /dev/null +++ b/docs/plans/v2.1/README.md @@ -0,0 +1,30 @@ +# v2.1 implementation plan: fixes found while running v2 + +> **For the implementing model:** do not work from this file. The owner gives you one task file at +> a time. This file is the index for the owner and the reviewer. + +**Goal:** close the two defects and one gap found while v2 ran, without new features. + +- **01-cancel-record** — a delivered response is never recorded as a 499; cancellation is what + the reverse proxy observed. Found 2026-09-25 by the intermittent `Errors:2` in + `TestQueueFullIs503`; verified with a diagnostic build; the given + `internal/proxy/served_test.go` reproduces it on every run. +- **02-props-loaded-only** (to be written after v2 merges) — the poller asks `/props?model=X` + only for models `/v1/models` lists as loaded, because llama-server's router autoloads a model + named in that query (`models_autoload`). See the v2 README's note of 2026-09-25. +- **03-timing-margins** (to be written) — the remaining sleep-ordered assertions in v1 and v2 + given tests move to state-based waits, as `TestQueueFullIs503` and `TestParallelAndQueue` did. + +**How this plan was made:** acceptance tests first; no reference implementation. The given test +for task 01 was run against the v2 tree (fails six of six) and against a throwaway fix that +follows the task's rule (passes four full package runs with the v1 cancel tests); the throwaway +was discarded. + +## Global constraints + +- Everything in `AGENTS.md`. Branch `v2.1` from `master` after v2 merges. One task, one fresh + OpenCode session, one commit. Given files are copied and never edited. + +## Changes during the run + +(none yet) diff --git a/docs/plans/v2.1/_files/internal/proxy/served_test.go b/docs/plans/v2.1/_files/internal/proxy/served_test.go new file mode 100644 index 0000000..046bc1e --- /dev/null +++ b/docs/plans/v2.1/_files/internal/proxy/served_test.go @@ -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) + } + } +}