From 3df251ed5d74549129b1dc462d2b3d748cae83c8 Mon Sep 17 00:00:00 2001 From: Vignesh Date: Fri, 9 Oct 2026 01:23:10 +0530 Subject: [PATCH 1/4] census: the call row carries the demanded set, so served != lane means what it says again (#969) Since the chooser demands the whole admitted set (provider.only with fallbacks off), the router may serve any member of it, so Record.Lane (the ranked head) stopped being the only machine the request would accept. The census read served != lane as the router going somewhere we did not choose, which after the set-demand is often the router choosing a different member of the set we did choose. Add Record.Lanes []string, filled from laneChoice.Only when the demand is still being sent, carrying the whole set when it has two or more members (a one-machine demand is left to Lane alone). The census counts asked != served only when served fell OUTSIDE the admitted set. callrows.Row embeds calllog.Record, so the census reads the new field the day it lands. --- cmd/codeaf-census/demandedlanes_test.go | 39 ++++++++++++++++ cmd/codeaf-census/report.go | 26 ++++++++++- internal/calllog/calllog.go | 16 +++++++ internal/provider/calllog.go | 32 +++++++++++++ internal/provider/demandedlanes_test.go | 62 +++++++++++++++++++++++++ 5 files changed, 174 insertions(+), 1 deletion(-) create mode 100644 cmd/codeaf-census/demandedlanes_test.go create mode 100644 internal/provider/demandedlanes_test.go diff --git a/cmd/codeaf-census/demandedlanes_test.go b/cmd/codeaf-census/demandedlanes_test.go new file mode 100644 index 0000000000..1ec707943a --- /dev/null +++ b/cmd/codeaf-census/demandedlanes_test.go @@ -0,0 +1,39 @@ +package main + +import ( + "bytes" + "strings" + "testing" +) + +// TestServedInsideTheDemandedSetIsNotAskedNotServed is #969's second acceptance: +// once a row carries the set the chooser demanded (`lanes`), served being a +// DIFFERENT member of that set is the router choosing inside the choice we made, +// not routing around it - so it is not counted as "asked for is not the machine +// that served". Only served landing OUTSIDE the set is. +func TestServedInsideTheDemandedSetIsNotAskedNotServed(t *testing.T) { + log := writeLines(t, + // Served tinder, demanded {cinnabar, tinder}: inside the set, agreement + // even though served != lane. + `{"ts":"2026-09-08T10:00:00.000Z","id":"1","model":"m/one","served":"tinder","lane":"cinnabar","lanes":["cinnabar","tinder"],"status":200,"ms":500}`, + // Served tinder, ranked cinnabar, no set: the pre-#937 shape, a real + // asked != served. + `{"ts":"2026-09-08T10:00:01.000Z","id":"2","model":"m/one","served":"tinder","lane":"cinnabar","status":200,"ms":500}`, + // Served ember, demanded {cinnabar, tinder}: outside the set, a real + // asked != served. + `{"ts":"2026-09-08T10:00:02.000Z","id":"3","model":"m/one","served":"ember","lane":"cinnabar","lanes":["cinnabar","tinder"],"status":200,"ms":500}`, + ) + rows, err := readLog(log) + if err != nil { + t.Fatal(err) + } + var out bytes.Buffer + report(&out, log, rows, defaults()) + got := out.String() + + // Three rows are attributed; the one served inside its set is agreement, the + // two served outside their admitted machines are not. + if !strings.Contains(got, "| the machine asked for is not the machine that served | 2 | 3 |") { + t.Errorf("served-inside-the-set was counted as asked != served:\n%s", got) + } +} diff --git a/cmd/codeaf-census/report.go b/cmd/codeaf-census/report.go index 5b11907ce1..db2cd4ec0d 100644 --- a/cmd/codeaf-census/report.go +++ b/cmd/codeaf-census/report.go @@ -521,7 +521,12 @@ func surprises(out io.Writer, rows, finishes []row) { } if r.Served != "" && r.Lane != "" { attributed++ - if !strings.EqualFold(r.Served, r.Lane) { + // A SET THE CHOOSER ADMITTED IS NOT A SINGLE RANKED NAME. When the + // row carries the demanded set, served being INSIDE it is the router + // picking a member of the choice we made, not routing around it - so + // only served landing OUTSIDE the set (or outside the lone name, on + // a row with no set) counts as asked != served (calllog's Lanes). + if !servedWasAdmitted(r) { disagreed++ } } @@ -649,6 +654,25 @@ func firstNonEmpty(values ...string) string { return "" } +// servedWasAdmitted reports whether the machine that served was one the request +// would have accepted. On a row that carries the demanded set ([calllog.Record]'s +// Lanes) that means served is a MEMBER of the set, because the chooser told the +// router it may serve any of them; on a row with no set it means served matches +// the single ranked name in Lane, which is the only machine such a row named. +// Both comparisons are case-insensitive, as the rest of this file reads machine +// names. +func servedWasAdmitted(r row) bool { + if len(r.Lanes) > 0 { + for _, lane := range r.Lanes { + if strings.EqualFold(r.Served, lane) { + return true + } + } + return false + } + return strings.EqualFold(r.Served, r.Lane) +} + // cell makes one string safe to sit in a markdown table: a pipe inside a cell // would end the column, and a signature full of router prose is exactly where // one turns up. diff --git a/internal/calllog/calllog.go b/internal/calllog/calllog.go index 8efe015e0a..ac213d98bb 100644 --- a/internal/calllog/calllog.go +++ b/internal/calllog/calllog.go @@ -252,6 +252,22 @@ type Record struct { // Empty for a call to an endpoint that is not a router, and for one sent // with no preference at all. Lane string `json:"lane,omitempty"` + // Lanes is the SET the request demanded, when it demanded more than one. + // Since the chooser was taught to admit the whole set it believed in + // (`provider.only` with `allow_fallbacks` off over every machine that + // survived the gate), the router is free to pick any member of it, so + // [Lane] above - the ranked head of that set - is no longer the only + // machine the request would accept. Served matching [Lane] exactly stopped + // being the question; served being INSIDE this set is, and a reader with + // only the head cannot tell "the router chose another machine we admitted" + // from "the router went somewhere we never named". + // + // Empty when the request demanded nothing (it ranked machines and the + // router was free to leave the set) or demanded exactly one - the single + // case [Lane] alone already answers - which is also the state of every row + // written before the set-demanding chooser existed. The members are the + // endpoint names in the order the choice ranked them, [Lane] first. + Lanes []string `json:"lanes,omitempty"` // Hedged marks the row of a call that was rescued by a second request to // another lane. Both halves of the pair leave their own rows; this is what // says they were a pair. diff --git a/internal/provider/calllog.go b/internal/provider/calllog.go index a63a654fcc..2c400353c1 100644 --- a/internal/provider/calllog.go +++ b/internal/provider/calllog.go @@ -449,6 +449,7 @@ func (c *Client) record(facts recordFacts) { // the row of the request it rescued says what happened to that one. if wait, watched := streamWatchFrom(facts.ctx).facts(); watched { record.Lane = recordedLane(body, wait.lane) + record.Lanes = demandedLanes(body) record.HazardCeilingMs = wait.deadline.Milliseconds() // WHAT WAS PLANNED AND WHAT HAPPENED ARE TWO FIELDS, AND THE ROW MAY // CARRY BOTH. The ceiling above is when the watch was going to start @@ -687,6 +688,37 @@ func soleDemandedLane(knobs callKnobs) string { return "" } +// demandedLanes is the SET this attempt's body demanded, and "" (an absent +// field) when it demanded nothing or demanded exactly one. It is the whole of +// `laneChoice.Only` - every machine the chooser admitted and told the router it +// may not leave - and it is read under the same discipline as [soleDemandedLane]: +// only when the demand is still being SENT ([callKnobs.carriesTheDemand]), never +// off knobs the widen has already relaxed, so the row cannot claim a set a +// retired pin's bare retry no longer carries. +// +// A single-machine demand is left to [Lane] alone, which already answers it; a +// hedge demands its one arm and is the same single case. This field exists for +// the one thing [Lane] cannot say - that served being a DIFFERENT member of the +// set was the router choosing inside the choice, not routing around it. +func demandedLanes(knobs callKnobs) []string { + if !knobs.carriesTheDemand() { + return nil + } + if knobs.laneChoice == nil || len(knobs.laneChoice.Only) < 2 { + return nil + } + lanes := make([]string, 0, len(knobs.laneChoice.Only)) + for _, name := range knobs.laneChoice.Only { + if name = strings.TrimSpace(name); name != "" { + lanes = append(lanes, name) + } + } + if len(lanes) < 2 { + return nil + } + return lanes +} + // recordedLane is the machine THIS ATTEMPT'S preference asked for: the head of // the order it sent, or the one machine it demanded. // diff --git a/internal/provider/demandedlanes_test.go b/internal/provider/demandedlanes_test.go new file mode 100644 index 0000000000..552218a01c --- /dev/null +++ b/internal/provider/demandedlanes_test.go @@ -0,0 +1,62 @@ +package provider + +import ( + "context" + "testing" + + "github.com/Agent-Field/codeaf/internal/calllog" + lanes "github.com/Agent-Field/codeaf/internal/lane" +) + +// TestADemandedSetLeavesEveryAdmittedMachineOnTheRow is #969's first acceptance: +// a call that demands a SET (every machine the chooser admitted, `provider.only` +// with fallbacks off) writes a row that carries the whole set in `lanes` and the +// ranked head in `lane`. Without the set, `served != lane` cannot tell "the +// router chose another machine we admitted" from "the router went somewhere we +// never named". +func TestADemandedSetLeavesEveryAdmittedMachineOnTheRow(t *testing.T) { + read := loggingTo(t) + client, _, _ := pacedPair(t) + + if _, err := client.CompleteWithMessages(context.Background(), userMessages("hello")); err != nil { + t.Fatal(err) + } + calllog.Close() + + finishes := ended(read()) + if len(finishes) != 1 { + t.Fatalf("one call should leave one finished row; got %d: %+v", len(finishes), finishes) + } + row := finishes[0] + if len(row.Lanes) != 2 || !hasName(row.Lanes, "cinnabar") || !hasName(row.Lanes, "tinder") { + t.Fatalf("lanes = %v, want both admitted machines on the row: %+v", row.Lanes, row) + } + if row.Lane != row.Lanes[0] { + t.Fatalf("lane = %q, want the ranked head of the demanded set %v", row.Lane, row.Lanes) + } + if row.Served == "" || !hasName(row.Lanes, row.Served) { + t.Fatalf("served = %q is not inside the admitted set %v", row.Served, row.Lanes) + } +} + +// TestASingleMachineDemandLeavesNoSetOnTheRow is the emptiness side: a demand of +// exactly one machine is the case `lane` alone already answers, so no `lanes` +// field is written - which is also the state of every row from before the +// set-demanding chooser existed. +func TestASingleMachineDemandLeavesNoSetOnTheRow(t *testing.T) { + if got := demandedLanes(callKnobs{laneChoice: &lanes.Choice{Only: []string{"cinnabar"}}}); got != nil { + t.Fatalf("a one-machine demand wrote lanes = %v, want nothing", got) + } + if got := demandedLanes(callKnobs{}); got != nil { + t.Fatalf("a call that demanded nothing wrote lanes = %v, want nothing", got) + } +} + +func hasName(names []string, want string) bool { + for _, name := range names { + if name == want { + return true + } + } + return false +} From d2e68a480ab2ea7e97716e50673f8e73142e9c6d Mon Sep 17 00:00:00 2001 From: Vignesh Date: Fri, 9 Oct 2026 01:24:15 +0530 Subject: [PATCH 2/4] docs: change entry for #1796 (demanded set on the call row) --- .../unreleased/1796-demanded-lanes-on-the-row.md | 14 ++++++++++++++ 1 file changed, 14 insertions(+) create mode 100644 docs/changes/unreleased/1796-demanded-lanes-on-the-row.md diff --git a/docs/changes/unreleased/1796-demanded-lanes-on-the-row.md b/docs/changes/unreleased/1796-demanded-lanes-on-the-row.md new file mode 100644 index 0000000000..a5e8796b83 --- /dev/null +++ b/docs/changes/unreleased/1796-demanded-lanes-on-the-row.md @@ -0,0 +1,14 @@ +--- +kind: fixed +title: the call row carries the demanded set, so served ≠ asked means what it says again +pr: 1796 +surface: [] +invalidates: + - "The call log's `Record.Lane` named ONE machine - the ranked head of the request's preference. Since the chooser was taught to demand the whole admitted set (`provider.only` with `allow_fallbacks: false`), the router may serve any member of that set, so a row where `served != lane` could no longer tell `the router chose a different member of the set we admitted` from `the router went somewhere we never named`, and the census family built on it (asked ≠ served) silently changed what it measured. The row now also carries `Record.Lanes`, the whole demanded set, filled from `laneChoice.Only` while the demand is still being sent and present only when the set has two or more members (a one-machine demand is left to `Lane` alone, which is also every pre-set-demand row). The census counts asked ≠ served only when served fell OUTSIDE the admitted set." +--- + +Raised out of #937's review as the owed follow-up: the measurement was ruled +honest and sufficient, and this is the field it named. Scoped to the log and the +census; widening `cmd/*-replay`'s `Policy.Demand` to return the set is the second +half, worth doing only now the log can say whether the served machine was inside +one. From 9544fd63579395fb132c3a00c2698aae3c335cb5 Mon Sep 17 00:00:00 2001 From: Vignesh Date: Wed, 14 Oct 2026 04:49:29 +0530 Subject: [PATCH 3/4] address review: record the demand that actually travelled, not the original choice ZeroPoint95's review on #1796 caught that demandedLanes read the original laneChoice.Only, so a rescue (sends only:[B]) and a narrowed retry (drops a refused machine) recorded the whole original set and misattributed Lane. Capture provider.only as wirePreferences composed it, at encode time, onto the trace; carry it onto the openAttempt so a finish row written after a later attempt re-encoded still describes its own. demandedLanes now reads that composed set, and recordedLane names the single machine a narrowed attempt really demanded rather than the ranked head it recovered from. Adds the two wire-versus-log regression tests the review asked for: a rescue arm records only its one machine, and a narrowed retry does not keep the set it no longer demands and attributes to the machine it does. --- .../1796-demanded-lanes-on-the-row.md | 2 +- internal/provider/calllog.go | 97 +++++++++++++--- internal/provider/demandedlanes_test.go | 107 ++++++++++++++++-- internal/provider/wire.go | 14 +++ 4 files changed, 195 insertions(+), 25 deletions(-) diff --git a/docs/changes/unreleased/1796-demanded-lanes-on-the-row.md b/docs/changes/unreleased/1796-demanded-lanes-on-the-row.md index a5e8796b83..6dc76d1579 100644 --- a/docs/changes/unreleased/1796-demanded-lanes-on-the-row.md +++ b/docs/changes/unreleased/1796-demanded-lanes-on-the-row.md @@ -4,7 +4,7 @@ title: the call row carries the demanded set, so served ≠ asked means what it pr: 1796 surface: [] invalidates: - - "The call log's `Record.Lane` named ONE machine - the ranked head of the request's preference. Since the chooser was taught to demand the whole admitted set (`provider.only` with `allow_fallbacks: false`), the router may serve any member of that set, so a row where `served != lane` could no longer tell `the router chose a different member of the set we admitted` from `the router went somewhere we never named`, and the census family built on it (asked ≠ served) silently changed what it measured. The row now also carries `Record.Lanes`, the whole demanded set, filled from `laneChoice.Only` while the demand is still being sent and present only when the set has two or more members (a one-machine demand is left to `Lane` alone, which is also every pre-set-demand row). The census counts asked ≠ served only when served fell OUTSIDE the admitted set." + - "The call log's `Record.Lane` named ONE machine - the ranked head of the request's preference. Since the chooser was taught to demand the whole admitted set (`provider.only` with `allow_fallbacks: false`), the router may serve any member of that set, so a row where `served != lane` could no longer tell `the router chose a different member of the set we admitted` from `the router went somewhere we never named`, and the census family built on it (asked ≠ served) silently changed what it measured. The row now also carries `Record.Lanes`, the set the attempt ACTUALLY went out demanding, captured from the composed `provider.only` at encode time rather than from the choice the call was decided on - so a rescue (which sends one arm) and a retry narrowed past a refused machine record the demand that travelled, not the original pair. The set is present only when it has two or more members; a one-machine demand is left to `Lane`, which now names the machine a narrowed attempt really demanded rather than the ranked head it recovered from. The census counts asked ≠ served only when served fell OUTSIDE the admitted set." --- Raised out of #937's review as the owed follow-up: the measurement was ruled diff --git a/internal/provider/calllog.go b/internal/provider/calllog.go index 2c400353c1..5f50306918 100644 --- a/internal/provider/calllog.go +++ b/internal/provider/calllog.go @@ -157,6 +157,18 @@ type callTrace struct { // (recordBodies). It is nil on every ordinary run, which is what keeps a // person's prompts out of a file they did not ask to have them in. body []byte + // demandedOnly is the SET the LAST encode of this call put on the wire - + // `provider.only` as [Client.wirePreferences] composed it, after the rescue + // arm, the refused-here drop and the retry-avoid narrowing have each had + // their say. It is the demand that actually travelled for the current + // attempt, not the choice the call was decided on: a rescue sends one + // machine, a narrowed retry drops the machine that refused, and a row built + // from the original choice would claim a set that attempt never carried. It + // is read when a row records its demanded set (calllog.go's [demandedLanes]) + // and, like the per-attempt knobs, is captured onto the [openAttempt] so a + // finish row written after the next attempt has re-encoded still describes + // its own. + demandedOnly []string } func newCallTrace() *callTrace { return &callTrace{} } @@ -175,6 +187,11 @@ type openAttempt struct { knobs callKnobs stream bool base string + // demandedOnly is the composed `provider.only` this attempt went out with, + // captured from the trace at the moment the start row opened the attempt so + // a finish row written after a later attempt re-encoded still describes the + // set THIS one carried (callTrace's [demandedOnly]). + demandedOnly []string } // The words [calllog.Record.Ended] uses. They are constants for the reason the @@ -210,13 +227,14 @@ func (t *callTrace) track(facts recordFacts, id string) { return } t.open = &openAttempt{ - id: id, - attempt: facts.attempt, - began: facts.began, - request: facts.request, - knobs: facts.knobs, - stream: facts.stream, - base: facts.baseFor(t.attemptBase), + id: id, + attempt: facts.attempt, + began: facts.began, + request: facts.request, + knobs: facts.knobs, + stream: facts.stream, + base: facts.baseFor(t.attemptBase), + demandedOnly: t.demandedOnly, } } @@ -448,8 +466,9 @@ func (c *Client) record(facts recordFacts) { // THIS attempt, so that the row of a rescue says what the rescue did and // the row of the request it rescued says what happened to that one. if wait, watched := streamWatchFrom(facts.ctx).facts(); watched { - record.Lane = recordedLane(body, wait.lane) - record.Lanes = demandedLanes(body) + demanded := bodyDemandedOnly(facts) + record.Lane = recordedLane(body, wait.lane, demanded) + record.Lanes = demandedLanes(demanded) record.HazardCeilingMs = wait.deadline.Milliseconds() // WHAT WAS PLANNED AND WHAT HAPPENED ARE TWO FIELDS, AND THE ROW MAY // CARRY BOTH. The ceiling above is when the watch was going to start @@ -662,6 +681,25 @@ func bodyKnobs(facts recordFacts) callKnobs { return facts.knobs } +// bodyDemandedOnly is the composed `provider.only` THIS ROW IS ABOUT, resolved +// the three ways [bodyKnobs] resolves its knobs. A start row is written before +// the attempt is tracked, so the trace's own last-encoded set is this attempt's +// (encode runs before the start row); an ordinary end row reads it off the open +// attempt that captured it; and the unconditional closing row reads the carried +// knobs' trace, whose open attempt is gone, so the trace's last-encoded set +// stands - which is still this attempt's, because the next attempt has not +// re-encoded. +func bodyDemandedOnly(facts recordFacts) []string { + trace := facts.knobs.trace + if trace == nil { + return nil + } + if facts.phase != calllog.PhaseStart && trace.open != nil { + return trace.open.demandedOnly + } + return trace.demandedOnly +} + // soleDemandedLane is the one machine THIS ATTEMPT'S BODY was pinned to, and "" // when it was free to be routed anywhere. A rescue demands the single arm it // walked to (hedge.go's [hedgePreference]) and a person's pin is one machine @@ -700,15 +738,26 @@ func soleDemandedLane(knobs callKnobs) string { // hedge demands its one arm and is the same single case. This field exists for // the one thing [Lane] cannot say - that served being a DIFFERENT member of the // set was the router choosing inside the choice, not routing around it. -func demandedLanes(knobs callKnobs) []string { - if !knobs.carriesTheDemand() { - return nil - } - if knobs.laneChoice == nil || len(knobs.laneChoice.Only) < 2 { +// demandedLanes is the SET this attempt actually went out demanding, and "" (an +// absent field) when it demanded nothing or demanded exactly one. `composed` is +// `provider.only` AS IT TRAVELLED for this attempt, captured at encode time +// (wire.go) and read off the open attempt or the trace by [bodyDemandedOnly] - +// NOT off `laneChoice.Only`, which is the choice the call was decided on. The +// two part company on exactly the rows that matter: a rescue narrows the demand +// to its one arm, a refusal drops the machine that refused, and a row built from +// the original choice would claim a set the attempt never carried and read a +// different member of it as agreement. +// +// A single-machine demand is left to [Lane] alone, which already answers it; a +// hedge sends its one arm and is the same single case. This field exists for +// the one thing [Lane] cannot say - that served being a DIFFERENT member of the +// set was the router choosing inside the choice, not routing around it. +func demandedLanes(composed []string) []string { + if len(composed) < 2 { return nil } - lanes := make([]string, 0, len(knobs.laneChoice.Only)) - for _, name := range knobs.laneChoice.Only { + lanes := make([]string, 0, len(composed)) + for _, name := range composed { if name = strings.TrimSpace(name); name != "" { lanes = append(lanes, name) } @@ -728,7 +777,21 @@ func demandedLanes(knobs callKnobs) []string { // `order` standing, so a lane the choice merely RANKED is still this body's ask // and a lane it DEMANDED is not — and a pinned request's bare retry was // reported under the name of the machine whose refusal it was recovering from. -func recordedLane(knobs callKnobs, asked string) string { +// +// AND A COMPOSED DEMAND OF ONE MACHINE IS THE AUTHORITY ON THE LANE. When this +// attempt went out with `provider.only` naming exactly one machine - a rescue's +// arm, or a retry narrowed to the one machine that has not refused - that +// machine is what was asked for, not the head of the order the call was decided +// on. Without this a retry that dropped `cinnabar` and demanded `tinder` was +// still logged `lane: cinnabar`, the machine whose refusal it was recovering +// from (#1796 review). The ranked head stands only when the demand did not +// narrow to one. +func recordedLane(knobs callKnobs, asked string, composed []string) string { + if len(composed) == 1 { + if lane := strings.TrimSpace(composed[0]); lane != "" { + return lane + } + } if asked == "" || knobs.carriesTheDemand() { return asked } diff --git a/internal/provider/demandedlanes_test.go b/internal/provider/demandedlanes_test.go index 552218a01c..618707d9ac 100644 --- a/internal/provider/demandedlanes_test.go +++ b/internal/provider/demandedlanes_test.go @@ -4,6 +4,7 @@ import ( "context" "testing" + "github.com/Agent-Field/agentfield/sdk/go/ai" "github.com/Agent-Field/codeaf/internal/calllog" lanes "github.com/Agent-Field/codeaf/internal/lane" ) @@ -39,17 +40,109 @@ func TestADemandedSetLeavesEveryAdmittedMachineOnTheRow(t *testing.T) { } } -// TestASingleMachineDemandLeavesNoSetOnTheRow is the emptiness side: a demand of -// exactly one machine is the case `lane` alone already answers, so no `lanes` -// field is written - which is also the state of every row from before the -// set-demanding chooser existed. -func TestASingleMachineDemandLeavesNoSetOnTheRow(t *testing.T) { - if got := demandedLanes(callKnobs{laneChoice: &lanes.Choice{Only: []string{"cinnabar"}}}); got != nil { +// TestANarrowedRetryRecordsTheMachineItReallyDemanded is the reviewer's second +// case (#1796 review): after `cinnabar` refuses, the retry sends `only: [tinder]` +// and `tinder` serves. The retry's row must NOT keep the original set in `lanes` +// (that would read a serve by `cinnabar` on some later call as inside-the-set +// agreement), and it must attribute to the machine it actually demanded, not the +// ranked head of the choice. The demand that travelled is read off the wire, not +// off the choice the call was decided on. +func TestANarrowedRetryRecordsTheMachineItReallyDemanded(t *testing.T) { + read := loggingTo(t) + client, server, _ := pacedPair(t, "cinnabar") + + if _, err := client.CompleteWithMessages(context.Background(), userMessages("hello")); err != nil { + t.Fatalf("the healthy machine should have answered: %v", err) + } + calllog.Close() + + if served := server.Served(); len(served) == 0 || served[len(served)-1] != "tinder" { + t.Fatalf("%v answered, want tinder", served) + } + finishes := ended(read()) + // The attempt that tinder served: it demanded tinder alone, so it carries no + // set, and both its lane and served are tinder. + var servedRow *calllog.Record + for i := range finishes { + if finishes[i].Served == "tinder" { + servedRow = &finishes[i] + } + } + if servedRow == nil { + t.Fatalf("no finished row was served by tinder: %+v", finishes) + } + if len(servedRow.Lanes) != 0 { + t.Fatalf("the narrowed retry kept a set it no longer demanded: lanes = %v", servedRow.Lanes) + } + if servedRow.Lane != "" && servedRow.Lane != "tinder" { + t.Fatalf("the narrowed retry attributed to %q, want the machine it demanded (tinder) or nothing", servedRow.Lane) + } + // No row from this call may claim the original two-machine set, since no + // attempt that could read a stray cinnabar serve as agreement went out + // demanding both after cinnabar refused. + for _, r := range finishes { + if r.Served == "tinder" && len(r.Lanes) == 2 { + t.Fatalf("a tinder-served row still claimed the demanded set %v", r.Lanes) + } + } +} + +// TestASingleMachineDemandIsNotWrittenAsASet is the emptiness side: a composed +// demand of one machine is the case `lane` alone already answers, so no `lanes` +// field is written, and a call that demanded nothing writes none either. +func TestASingleMachineDemandIsNotWrittenAsASet(t *testing.T) { + if got := demandedLanes([]string{"cinnabar"}); got != nil { t.Fatalf("a one-machine demand wrote lanes = %v, want nothing", got) } - if got := demandedLanes(callKnobs{}); got != nil { + if got := demandedLanes(nil); got != nil { t.Fatalf("a call that demanded nothing wrote lanes = %v, want nothing", got) } + if got := demandedLanes([]string{"cinnabar", "tinder"}); len(got) != 2 { + t.Fatalf("a two-machine demand wrote lanes = %v, want both", got) + } + // Blank members are trimmed, and a set that trims to one is not a set. + if got := demandedLanes([]string{"cinnabar", " "}); got != nil { + t.Fatalf("a demand that trims to one machine wrote lanes = %v, want nothing", got) + } +} + +// TestARescueArmRecordsOnlyTheMachineItWentOutTo is the reviewer's first case +// (#1796 review): a rescue sends `only: [the one arm]`, but its row was recording +// the whole original admitted set, so a serve by the other machine on that row +// read as inside-the-set agreement. The demanded set is captured from the +// composed wire preference at encode time, so a rescue arm's row carries its one +// machine (and therefore no set) and attributes to it, never the original pair. +func TestARescueArmRecordsOnlyTheMachineItWentOutTo(t *testing.T) { + client, _, model := pacedPair(t) + + // A rescue arm: the call was decided on the admitted set {cinnabar, tinder}, + // but THIS attempt is the hedge's own arm, which demands tinder alone. + knobs := callKnobs{ + intent: IntentInteractive, + laneChoice: &lanes.Choice{ + Only: []string{"cinnabar", "tinder"}, + Order: []string{"cinnabar", "tinder"}, + }, + hedgeLane: "tinder", + trace: newCallTrace(), + } + request := &ai.Request{Model: model, Messages: userMessages("hello")} + if _, err := client.encodeRequest(request, knobs); err != nil { + t.Fatal(err) + } + + // What the wire carried, captured at encode: the rescue's one machine. + if got := knobs.trace.demandedOnly; len(got) != 1 || got[0] != "tinder" { + t.Fatalf("the rescue arm captured demandedOnly = %v, want only the arm it went out to", got) + } + // So the row carries no set (one machine is Lane's job) and attributes to the + // machine the arm actually demanded, never the original pair's head. + if got := demandedLanes(knobs.trace.demandedOnly); got != nil { + t.Fatalf("the rescue arm wrote a set it did not demand: lanes = %v", got) + } + if got := recordedLane(knobs, "cinnabar", knobs.trace.demandedOnly); got != "tinder" { + t.Fatalf("the rescue arm attributed to %q, want the machine it demanded (tinder)", got) + } } func hasName(names []string, want string) bool { diff --git a/internal/provider/wire.go b/internal/provider/wire.go index fd670a53de..48193e94c0 100644 --- a/internal/provider/wire.go +++ b/internal/provider/wire.go @@ -408,6 +408,20 @@ func (c *Client) encodeRequest(request *ai.Request, knobs callKnobs) ([]byte, er // of it for a while, could not see the demand a rescue adds, and offered a // pinned request no first rung at all (issue #266). wire.Provider = c.wirePreferences(model, knobs) + // AND THE DEMANDED SET THAT TRAVELLED IS KEPT FOR THE ROW. `provider.only` + // as it was just composed is this attempt's real demand - narrowed by a + // rescue to one arm, by a refusal to the machines that have not refused - and + // not the set the call was decided on. The row records it from here so a + // rescue's row does not claim the whole original set (calllog.go's + // [demandedLanes]). It is cleared when no preference went out so a widened + // retry does not inherit the last attempt's demand. + if knobs.trace != nil { + if wire.Provider != nil && len(wire.Provider.Only) > 0 { + knobs.trace.demandedOnly = append([]string(nil), wire.Provider.Only...) + } else { + knobs.trace.demandedOnly = nil + } + } // AND WHETHER THE ASK WAS REALLY MADE IS RECORDED WHERE IT IS REALLY // WRITTEN. A base answers the #433 question with what comes back from a // request that carried a preference, and the widened retry that follows a From af5a9981fa4de229c614d5c727db39d56ace510c Mon Sep 17 00:00:00 2001 From: Vignesh Date: Thu, 15 Oct 2026 02:01:47 +0530 Subject: [PATCH 4/4] address review 2: preserve the demanded set through the hopped close, fix docs ZeroPoint95's second review caught that closeOpenAttempt clears trace.open before recording, so a finish row built on the fallback close read the latest encode's demand rather than the closed attempt's. Carry the attempt's snapshot through recordFacts.demandedOnly and read it off the ended row in bodyDemandedOnly, keyed on ended (set only on that row) so an attempt closed carrying no demand is not handed a later one. Also remove the stale duplicated demandedLanes doc that still described reading laneChoice.Only, and correct the Record.Lanes doc: Lane is a member of the set but not necessarily its first element, since a three-to-two retry can keep the original ranked head as Lane while Lanes names the surviving pair. Adds TestAHoppedAttemptKeepsItsOwnDemandedSetThroughTheClose, which fails without the carry and passes with it. --- internal/calllog/calllog.go | 31 ++++++++++-------- internal/provider/calllog.go | 31 +++++++++++------- internal/provider/demandedlanes_test.go | 43 +++++++++++++++++++++++-- 3 files changed, 77 insertions(+), 28 deletions(-) diff --git a/internal/calllog/calllog.go b/internal/calllog/calllog.go index ac213d98bb..3df5c8c540 100644 --- a/internal/calllog/calllog.go +++ b/internal/calllog/calllog.go @@ -252,21 +252,24 @@ type Record struct { // Empty for a call to an endpoint that is not a router, and for one sent // with no preference at all. Lane string `json:"lane,omitempty"` - // Lanes is the SET the request demanded, when it demanded more than one. - // Since the chooser was taught to admit the whole set it believed in - // (`provider.only` with `allow_fallbacks` off over every machine that - // survived the gate), the router is free to pick any member of it, so - // [Lane] above - the ranked head of that set - is no longer the only - // machine the request would accept. Served matching [Lane] exactly stopped - // being the question; served being INSIDE this set is, and a reader with - // only the head cannot tell "the router chose another machine we admitted" - // from "the router went somewhere we never named". + // Lanes is the SET this attempt actually went out demanding, when it + // demanded more than one. Since the chooser was taught to admit the whole + // set it believed in (`provider.only` with `allow_fallbacks` off over every + // machine that survived the gate), the router is free to pick any member of + // it, so [Lane] above is no longer the only machine the request would + // accept. Served matching [Lane] exactly stopped being the question; served + // being INSIDE this set is, and a reader with only [Lane] cannot tell "the + // router chose another machine we admitted" from "the router went somewhere + // we never named". // - // Empty when the request demanded nothing (it ranked machines and the - // router was free to leave the set) or demanded exactly one - the single - // case [Lane] alone already answers - which is also the state of every row - // written before the set-demanding chooser existed. The members are the - // endpoint names in the order the choice ranked them, [Lane] first. + // Empty when the attempt demanded nothing (it ranked machines and the router + // was free to leave the set) or demanded exactly one - the single case + // [Lane] alone already answers - which is also the state of every row written + // before the set-demanding chooser existed. The members are the endpoint + // names as the composed demand carried them. [Lane] is a member of this set + // but NOT necessarily its first: a retry narrowed from three machines to two + // can keep the original ranked head as [Lane] while [Lanes] names the pair + // that survived. Lanes []string `json:"lanes,omitempty"` // Hedged marks the row of a call that was rescued by a second request to // another lane. Both halves of the pair leave their own rows; this is what diff --git a/internal/provider/calllog.go b/internal/provider/calllog.go index 5f50306918..399694fa71 100644 --- a/internal/provider/calllog.go +++ b/internal/provider/calllog.go @@ -253,6 +253,7 @@ func (c *Client) closeOpenAttempt(ctx context.Context, trace *callTrace, ended s c.record(recordFacts{ ctx: ctx, request: open.request, knobs: open.knobs, stream: open.stream, attempt: open.attempt, began: open.began, ended: ended, id: open.id, base: open.base, + demandedOnly: open.demandedOnly, }) } @@ -345,6 +346,13 @@ type recordFacts struct { // overtaken, so reading the id off the trace would pair it with the wrong // start row — which is the very mis-pairing the closing row exists to end. id string + // demandedOnly is the composed `provider.only` of the attempt this row is + // about, carried ONLY on the unconditional closing row ([Client.closeOpenAttempt]). + // That path clears `trace.open` before it records, so the closed attempt's + // snapshot is no longer reachable off the trace and the latest encode's + // demand would stand in its place; carrying it here keeps the ending's set + // equal to the start's, exactly as `knobs` above is carried for the same row. + demandedOnly []string } // logNow is the wall clock the model-call log stamps its rows from, and it is @@ -690,6 +698,17 @@ func bodyKnobs(facts recordFacts) callKnobs { // stands - which is still this attempt's, because the next attempt has not // re-encoded. func bodyDemandedOnly(facts recordFacts) []string { + // A CARRIED CLOSING ROW HOLDS ITS OWN SNAPSHOT. The unconditional close + // ([Client.closeOpenAttempt]) takes the attempt off the trace before it + // records, so neither branch below could reach the closed attempt's demand - + // the trace's `open` is gone and its last-encoded set is a LATER attempt's. + // The snapshot it carried stands, the same way `knobs` carries for that row, + // and it is read off `ended` (set ONLY on that row) rather than off the set + // being non-nil, so an attempt that was closed carrying no demand is not + // handed a later attempt's one. + if facts.ended != "" { + return facts.demandedOnly + } trace := facts.knobs.trace if trace == nil { return nil @@ -726,18 +745,6 @@ func soleDemandedLane(knobs callKnobs) string { return "" } -// demandedLanes is the SET this attempt's body demanded, and "" (an absent -// field) when it demanded nothing or demanded exactly one. It is the whole of -// `laneChoice.Only` - every machine the chooser admitted and told the router it -// may not leave - and it is read under the same discipline as [soleDemandedLane]: -// only when the demand is still being SENT ([callKnobs.carriesTheDemand]), never -// off knobs the widen has already relaxed, so the row cannot claim a set a -// retired pin's bare retry no longer carries. -// -// A single-machine demand is left to [Lane] alone, which already answers it; a -// hedge demands its one arm and is the same single case. This field exists for -// the one thing [Lane] cannot say - that served being a DIFFERENT member of the -// set was the router choosing inside the choice, not routing around it. // demandedLanes is the SET this attempt actually went out demanding, and "" (an // absent field) when it demanded nothing or demanded exactly one. `composed` is // `provider.only` AS IT TRAVELLED for this attempt, captured at encode time diff --git a/internal/provider/demandedlanes_test.go b/internal/provider/demandedlanes_test.go index 618707d9ac..ee4067e8f4 100644 --- a/internal/provider/demandedlanes_test.go +++ b/internal/provider/demandedlanes_test.go @@ -32,8 +32,8 @@ func TestADemandedSetLeavesEveryAdmittedMachineOnTheRow(t *testing.T) { if len(row.Lanes) != 2 || !hasName(row.Lanes, "cinnabar") || !hasName(row.Lanes, "tinder") { t.Fatalf("lanes = %v, want both admitted machines on the row: %+v", row.Lanes, row) } - if row.Lane != row.Lanes[0] { - t.Fatalf("lane = %q, want the ranked head of the demanded set %v", row.Lane, row.Lanes) + if !hasName(row.Lanes, row.Lane) { + t.Fatalf("lane = %q is not a member of the demanded set %v", row.Lane, row.Lanes) } if row.Served == "" || !hasName(row.Lanes, row.Served) { t.Fatalf("served = %q is not inside the admitted set %v", row.Served, row.Lanes) @@ -145,6 +145,45 @@ func TestARescueArmRecordsOnlyTheMachineItWentOutTo(t *testing.T) { } } +// TestAHoppedAttemptKeepsItsOwnDemandedSetThroughTheClose covers the fallback +// closing mechanism (#1796 review, second pass): the unconditional close +// ([Client.closeOpenAttempt]) clears `trace.open` before it records, so a finish +// row built from it cannot reach the closed attempt's demand off the trace - the +// trace's last-encoded set is a LATER attempt's. The closing row must read the +// snapshot it was handed instead. This tests [bodyDemandedOnly] at that seam +// directly, because the lane fields are only written for a watched call and the +// close path's bug is in which set reaches them, not in the watch. +func TestAHoppedAttemptKeepsItsOwnDemandedSetThroughTheClose(t *testing.T) { + trace := newCallTrace() + // Attempt 1 went out demanding both; its snapshot is what the close carries. + openOne := &openAttempt{id: "one", demandedOnly: []string{"cinnabar", "tinder"}} + // Attempt 2 has since re-encoded to one machine, so the trace's own set is + // tinder alone - the stand-in that would stand in if the snapshot were lost. + trace.demandedOnly = []string{"tinder"} + trace.open = nil // closeOpenAttempt cleared it before recording. + + // The carried closing row, as closeOpenAttempt builds it: ended set, the + // closed attempt's own snapshot carried, the trace holding a later set. + closing := recordFacts{ + knobs: callKnobs{trace: trace}, + ended: endedHopped, + demandedOnly: openOne.demandedOnly, + } + if got := bodyDemandedOnly(closing); len(got) != 2 || !hasName(got, "cinnabar") || !hasName(got, "tinder") { + t.Fatalf("the hopped ending took a later attempt's demand: %v, want the set it carried", got) + } + if got := demandedLanes(bodyDemandedOnly(closing)); len(got) != 2 { + t.Fatalf("the hopped ending wrote the wrong set: lanes = %v", got) + } + + // And an attempt closed carrying NO demand is not handed the trace's later + // one: the snapshot, not the non-nil-ness of the field, is the signal. + singleClose := recordFacts{knobs: callKnobs{trace: trace}, ended: endedHopped, demandedOnly: nil} + if got := bodyDemandedOnly(singleClose); got != nil { + t.Fatalf("an attempt closed with no demand was handed %v", got) + } +} + func hasName(names []string, want string) bool { for _, name := range names { if name == want {