diff --git a/internal/gateway/gateway.go b/internal/gateway/gateway.go index 05ec3887..abe55f34 100644 --- a/internal/gateway/gateway.go +++ b/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/" 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() diff --git a/internal/gateway/lane_usage_test.go b/internal/gateway/lane_usage_test.go new file mode 100644 index 00000000..3616c799 --- /dev/null +++ b/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) +}