gateway: a 429 from a key's queue is in the usage ledger, as any other turn-away (#956)

The last candidate turned away by a key's or account's queue answers 429 with
Retry-After, and shows in the Routing trace and the recent-calls ring — but no
lane refusal reached the usage ledger, so Usage, the CSV export and the failure
filter never said it happened.

The final write is guarded by `call.To != ""`, and call.To is only set inside
s.attempt, which a lane refusal never reaches (the attempt is gated on
`err == nil`). Every other turn-away that happens before any provider was asked
goes through turnedAway(), which records it with Rejected: true: an unknown
model, a usage cap, an account barred, a sealed subagent task.

turnedAway's ledger half is now `logged`, and the lane branch calls that alone:
serve still reaches its end and writes the one recent-calls entry it always
wrote, so the refusal is one entry in Recent calls and one row in the ledger.
Calling turnedAway here recorded it twice.

Unchanged: the 429, its Retry-After, which members are skipped, and that nobody
rests for it (#892).

TestQueueRefusalIsInTheUsageLedger fails without the change — the ledger holds
no rejected 429 after a full queue — and passes with it, asserting exactly one
recent-calls entry and exactly one rejected 429 row;
TestUnknownModelRefusalIsInTheUsageLedger is the contrast that shows an unknown
model's refusal was recorded all along. go vet ./... and the builds for darwin,
GOOS=linux and GOOS=windows pass, and the lane tests pass under -race -count=20.

internal/gateway/gateway.go

@@ -1120,17 +1120,25 @@ func (s *Server) serve(w http.ResponseWriter, r *http.Request, from provider.Pro
 			}
 		}
 	}
+	// the usage row of a request turned away before any provider was asked:
+	// the ledger says it failed and why. The recent-calls entry is the
+	// usual one at the end of serve, so a caller that only wants the row
+	// (a lane refusal, which returns to serve's end) does not call
+	// turnedAway and record twice.
+	logged := func() {
+		rec := usage.Record{Time: start, Agent: call.Agent, Via: call.Via, Provider: call.Provider, Model: call.Model, Requested: call.Model,
+			Millis: call.Millis, Status: call.Status, Rejected: true, Session: sessionOf(r.Header), NativeSession: nativeSessionOf(r.Header), Kind: call.Kind, Endpoint: endpointOf(r, from, ""), Archive: call.archiveName()}
+		failedWith(&rec, call.Status, call.Error, "")
+		withBodies(&rec, &call)
+		appendUsage(r, rec)
+	}
 	// a request turned away before any provider was asked is in the log
 	// as the failure it was, with the reason
 	turnedAway := func() {
 		finishCapture()
 		call.Millis = time.Since(start).Milliseconds()
 		s.record(call)
-		rec := usage.Record{Time: start, Agent: call.Agent, Via: call.Via, Provider: call.Provider, Model: call.Model, Requested: call.Model,
-			Millis: call.Millis, Status: call.Status, Rejected: true, Session: sessionOf(r.Header), NativeSession: nativeSessionOf(r.Header), Kind: call.Kind, Endpoint: endpointOf(r, from, ""), Archive: call.archiveName()}
-		failedWith(&rec, call.Status, call.Error, "")
-		withBodies(&rec, &call)
-		appendUsage(r, rec)
+		logged()
 	}
 	// a model's id without a provider in it that names a routing group is
 	// the group's, as "group/<id>" is, rather than one provider's that
@@ -1732,6 +1740,11 @@ func (s *Server) serve(w http.ResponseWriter, r *http.Request, from provider.Pro
 				w.Header().Set("Retry-After", "1")
 			}
 			failTo(w, kept, from, call.Status, call.Error)
+			// nobody was asked, and the agent is told: the ledger gets
+			// the row, as any other turn-away leaves one, and the usual
+			// entry in Recent calls is the one serve writes at its end
+			call.Millis = time.Since(start).Milliseconds()
+			logged()
 			break
 		}
 		hw.settle()

internal/gateway/lane_usage_test.go

@@ -0,0 +1,107 @@
+package gateway
+
+import (
+	"context"
+	"testing"
+	"time"
+
+	"github.com/yetone/magpie/internal/provider"
+	"github.com/yetone/magpie/internal/usage"
+)
+
+// A request turned away by a key's or account's queue answers 429 (that part
+// works), and shows in the Routing trace and the recent-calls ring, but never
+// reaches the usage ledger: the final write is guarded by `call.To != ""`
+// (gateway.go:2155) and call.To is only set inside s.attempt, which a lane
+// refusal never reaches (the attempt is gated on `err == nil`).
+//
+// Every other turn-away that happens before any provider was asked goes through
+// turnedAway(), which does write a Rejected record: an unknown model, a usage
+// cap, an account barred, a sealed subagent task. The same class of refusal
+// should read the same in Usage and in a CSV export.
+func TestQueueRefusalIsInTheUsageLedger(t *testing.T) {
+	fresh(t)
+	v, up := slowUp(t)
+	one := 1
+	if err := provider.Save(provider.Provider{ID: "slow", Name: "Slow", Key: "k", Models: []string{"m"}, Chat: up + "/v1", Anthropic: up,
+		MaxConcurrency: &one, QueueLimit: 1, QueueWait: 1}); err != nil {
+		t.Fatal(err)
+	}
+	g := newLaneRig(t)
+	lane := func() Lane { return g.s.Lanes()["slow#"+provider.KeyID("k")] }
+
+	// a takes the only slot, b waits behind it
+	g.send(context.Background(), "/v1/chat/completions", "slow/m", "a")
+	within(t, "a at the vendor", func() bool { return len(v.seen()) == 1 })
+	g.send(context.Background(), "/v1/chat/completions", "slow/m", "b")
+	within(t, "b queued", func() bool { return lane().Waiting == 1 })
+
+	// c is turned away at once by the full queue
+	g.send(context.Background(), "/v1/chat/completions", "slow/m", "c")
+	r := g.reply()
+	if r.tag != "c" || r.status != 429 {
+		t.Fatalf("c = %+v, want a 429", r)
+	}
+	// the answer is out, so the ledger write is due
+	time.Sleep(500 * time.Millisecond)
+
+	// one entry in Recent calls and one row in the ledger, both saying the
+	// request was turned away: it is one refusal, not two
+	if n := recent429s(g.s); n != 1 {
+		t.Errorf("%d recent-calls entries for the 429, want 1", n)
+	}
+	if n := ledger429s(); n != 1 {
+		t.Errorf("%d rejected 429 rows in the usage ledger, want 1", n)
+	}
+
+	close(v.gate("a"))
+	g.reply()
+}
+
+// recent429s is how many of the recent calls are the 429 the queue gave.
+func recent429s(s *Server) int {
+	n := 0
+	for _, c := range s.Recent() {
+		if c.Status == 429 {
+			n++
+		}
+	}
+	return n
+}
+
+// ledger429s is how many rejected 429 rows the ledger holds.
+func ledger429s() int {
+	n := 0
+	for _, rec := range usage.Load(time.Time{}) {
+		if rec.Status == 429 && rec.Rejected {
+			n++
+		}
+	}
+	return n
+}
+
+// The contrast that makes this a defect rather than a design choice: a refusal
+// turned away the same way, for a model magpie does not know, does reach the
+// ledger, because it goes through turnedAway().
+func TestUnknownModelRefusalIsInTheUsageLedger(t *testing.T) {
+	fresh(t)
+	_, up := slowUp(t)
+	if err := provider.Save(provider.Provider{ID: "slow", Name: "Slow", Key: "k", Models: []string{"m"}, Chat: up + "/v1"}); err != nil {
+		t.Fatal(err)
+	}
+	g := newLaneRig(t)
+
+	g.send(context.Background(), "/v1/chat/completions", "nope/nothing", "a")
+	r := g.reply()
+	if r.status == 200 {
+		t.Fatalf("a = %+v, want a refusal", r)
+	}
+	time.Sleep(500 * time.Millisecond)
+
+	for _, rec := range usage.Load(time.Time{}) {
+		if rec.Rejected {
+			return // an unknown model is logged as the failure it was
+		}
+	}
+	t.Fatalf("an unknown model's refusal is in no usage record either (status %d): the contrast this test needs is gone", r.status)
+}