census: the call row carries the demanded set, so served != lane means what it says again (#969)

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)
+	}
+}

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.

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 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
+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.

internal/calllog/calllog.go

@@ -252,6 +252,25 @@ 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 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 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
 	// says they were a pair.

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,
 	}
 }
 
@@ -235,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,
 	})
 }
 
@@ -327,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
@@ -448,7 +474,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)
+		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
@@ -661,6 +689,36 @@ 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 {
+	// 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
+	}
+	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
@@ -687,6 +745,36 @@ func soleDemandedLane(knobs callKnobs) string {
 	return ""
 }
 
+// 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(composed))
+	for _, name := range composed {
+		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.
 //
@@ -696,7 +784,21 @@ func soleDemandedLane(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
 	}