v2.1 plan: task 01 cancel-record with its given served_test.go; index for 02/03

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
2026-09-25 11:12:58 -07:00
parent 481ea12f4c
commit a49a86c0e4
3 changed files with 181 additions and 0 deletions
@@ -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.
@@ -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)
@@ -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)
+		}
+	}
+}