amadan
room.js: codex round 2 - a verdict, and a stamp, per generation
S3-8 is S3-1's other half. The watchdog compared generations correctly and then called markTrouble, which returned early on record.renewed — so a connection that had renewed once was never told its *current* credential had expired, and the round-1 test passed a spy for the marking function and so proved nothing about the path that swallowed it. markTrouble now takes the list the verdict is about and compares the connection's own listAt with it; the boolean is out of the decision entirely, and the test runs the real marking functions and reads the sentence tileNote would render. S3-9 is S3-2's other half. A restart installs list B; another tile's Retry fetches C; renewOutdated skips the running restart, rightly; and B's proof then stamped the connection with C — a credential it had never been given, whose schedule then governed it. Each attempt now captures the list it installs and stamps only that generation, and a newer list arriving mid-attempt is a debt followUp pays once the attempt settles. The debt is bounded by the newest list that run had to work with, so a connection that simply cannot renew does not restart itself for ever. S3-10: the trap recorded setConfiguration before calling it, so a throw counted as an installation, and the counts were global, so one connection's second update could stand in for another left on the empty list. Recorded after the real call returns, keyed by connection, and the assertions fold the log to each live connection's last configuration. S3-11: the recording handler collapsed duplicate attribute keys into a map and gave every derived handler its own store, so a logger reached through WithAttrs wrote where nobody read. One shared store, bound attributes replayed onto each record, an ordered slice with a typed value — and a test of the test. S3-12: posted counted candidates before the stale-target return and before the queue. It is delivered now, counted where the hub answers 200. The three-restarts test passes an old deadline the current code ignores, so restoring the removed optional-deadline branch fails it on attempt one. The Retry test gains a connection whose own restart is already running, and asserts it restarted again rather than merely acquiring the new stamp — without which S3-9's bug satisfied it. One change nobody asked for: renewals[peer].attempts accumulates across runs instead of starting again at 1. The follow-up renewal begins within a millisecond of the first verdict and reset it, which made icestuck's "spent the whole budget" assertion race — and a counter that starts again is one no gate can wait on. 66 node tests, each new one seen failing first. make browser twice: 26 of 27 with `call` lost to the known ICE stall — gathered 0, delivered 0, received 2, added 2, iceGatheringState still "gathering" on one side — then 27/27 in 418.89s.
Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01CzvnuKhLzudvq7jZ7SvVt2
5 files changed,
+409
−90
docs/superpowers/reviews/2026-09-10-slice-3-record.md+36 −1internal/meet/app_relay_test.go+104 −19internal/meet/static/room.js+95 −32test/browser/call.mjs+61 −24test/browser/negotiation.test.mjs+113 −14
diff --git a/docs/superpowers/reviews/2026-09-10-slice-3-record.md b/docs/superpowers/reviews/2026-09-10-slice-3-record.md| index 1db606e..b05d724 100644 |
| --- a/docs/superpowers/reviews/2026-09-10-slice-3-record.md |
| +++ b/docs/superpowers/reviews/2026-09-10-slice-3-record.md |
| @@ -210,11 +210,15 @@ full diff. |
| three losing runs — `ice`, `icerenewal` and `staletarget`, on separate |
| gate runs — and all three say the same thing: |
| - | side | gathered | posted | received | added | pending | gatheringState | |
| + | side | gathered | delivered | received | added | pending | gatheringState | |
| | --- | --- | --- | --- | --- | --- | --- | |
| | A | 4 | 4 | 0 | 0 | 0 | complete | |
| | B | 0 | 0 | 4 | 4 | 0 | **gathering** | |
| + (`delivered` was `posted` when these were captured; Codex round 2 |
| + moved the count to where the hub accepts a candidate rather than |
| + where one is handed to a queue, and the readings are unchanged.) |
| + |
| One browser gathers **no ICE candidate at all** and never leaves |
| `gathering`. The other gathers, posts every one it gathers, and the |
| first adds every one it receives. There is nothing for the client to |
| @@ -295,3 +299,34 @@ W3-1..W3-6 are the same defects. One commit answered all of them. |
| | W3-12 | A sub-six-second development TTL leaves a margin under a second, which the delay floor would turn into a 1 Hz fetch loop | Fixed, not carried: `schedulable()` declines below a one-second margin and `state().ice.schedulable` says so | `a margin under a second is not a schedule` | |
| Commit: `6b316cc..c3e2318`. |
| + |
| +## Codex round 2 |
| + |
| +`codex exec` read the branch again at `d62e93b`. S3-3, S3-4 and S3-7 |
| +closed; the other four were half-closed, each for a reason that had |
| +survived under the fix rather than because the fix was wrong. Five new |
| +findings, one commit. |
| + |
| +| Finding | What it was | Disposition | Test | |
| +| --- | --- | --- | --- | |
| +| S3-8 (P2) | S3-1's other half: the watchdog compared generations correctly and then called `markTrouble`, which returned early on `record.renewed`. A connection that renewed once was never told its *current* credential had expired — and the round-1 test passed a spy for the marking function, so it proved nothing about the path that swallowed it | Fixed. `markTrouble(id, kind, upTo)` compares `entry.listAt` with the list the verdict is about; the boolean is gone from the decision entirely. The watchdog test now runs the real marking functions and reads the sentence `tileNote` would render | `a renewal in an earlier cycle does not exempt a connection from a later one`, `a connection already proven onto a newer list is left alone by the deadline` | |
| +| S3-9 (P2) | S3-2's other half: a restart installs list B, another tile's Retry fetches C, `renewOutdated` skips the running restart — and B's proof then stamped the connection with C, a credential it had never been given, whose schedule then governed it | Fixed. Each attempt captures the list it installs and stamps only that generation on proof; when a newer list arrived during the attempt, `followUp` renews onto it once the attempt settles. The follow-up is bounded by the list that run had to work with, so a connection that simply cannot renew does not restart itself for ever | `a proof stamps the list it installed, not one that arrived while it was proving`, `a Retry reaches a connection whose own restart was already running` | |
| +| S3-10 (P3) | The trap recorded `setConfiguration` before calling it, so a throw counted as an installation, and the counts were global, so one connection's second update could stand in for another left on the empty list | Fixed. Recorded after the real call returns, keyed by the connection's index; the assertions fold the log to each *live* connection's last configuration | `ice`, `icerenewal` | |
| +| S3-11 (P3) | The recording handler put attributes in a map (collapsing duplicate keys) and gave every derived handler its own store, so a logger reached through `WithAttrs` wrote where nobody read and its bound attributes were invisible | Fixed. One shared store, bound attributes and groups replayed onto each record, and the assertion reads an ordered slice with a typed value | `TestBuildLogsOneINFOLineWithTheRegionCountAndNotTheKey`, plus `TestTheRecordingHandlerSeesWhatALoggerCarries` — a test of the test | |
| +| S3-12 (P3) | `posted` counted candidates before the stale-target return and before the queue, so it counted ones that never reached the wire | Fixed. Renamed `delivered` and counted where the hub answers 200 | the flake captures above, unchanged in shape | |
| + |
| +Two test claims were tightened rather than added: the three-restarts |
| +test passes an old deadline that the current code ignores, so restoring |
| +the removed optional-deadline branch fails it; and the Retry test gains |
| +a connection whose own restart is already running, with the extra |
| +assertion that it *restarted again* rather than merely acquiring the |
| +new stamp — without which the S3-9 bug satisfied it. |
| + |
| +One behaviour changed that no finding asked for, and it is worth |
| +naming: `renewals[peer].attempts` accumulates across runs now instead of |
| +starting again at 1 with each one. A follow-up renewal reset it to 1 |
| +within milliseconds of the first verdict, which made `icestuck`'s |
| +"it spent the whole budget" assertion race, and a count that starts |
| +again says nothing a gate can wait on. |
| + |
| +Commit: `d62e93b..bffbbfb`. |
diff --git a/internal/meet/app_relay_test.go b/internal/meet/app_relay_test.go| index b851233..b948aa4 100644 |
| --- a/internal/meet/app_relay_test.go |
| +++ b/internal/meet/app_relay_test.go |
| @@ -56,7 +56,7 @@ func TestSetRelayFlipsRelayConfigured(t *testing.T) { |
| // survived. |
| func TestBuildLogsOneINFOLineWithTheRegionCountAndNotTheKey(t *testing.T) { |
| var buf bytes.Buffer |
| - rec := &recordingHandler{inner: slog.NewTextHandler(&buf, nil)} |
| + rec := newRecordingHandler(slog.NewTextHandler(&buf, nil)) |
| logger := slog.New(rec) |
| cfg := minimalConfig(t) |
| cfg.Logger = logger |
| @@ -89,13 +89,20 @@ func TestBuildLogsOneINFOLineWithTheRegionCountAndNotTheKey(t *testing.T) { |
| if got.Level != slog.LevelInfo { |
| t.Fatalf("the relay line is %s, not INFO", got.Level) |
| } |
| - attrs := map[string]string{} |
| - got.Attrs(func(a slog.Attr) bool { |
| - attrs[a.Key] = a.Value.String() |
| - return true |
| - }) |
| - if len(attrs) != 1 || attrs["regions"] != "1" { |
| - t.Fatalf("want exactly one attribute, regions=1; got %v", attrs) |
| + // A slice, not a map: a map collapses two attributes that share a |
| + // key, so `regions=1, regions=<the whole contract>` would have read |
| + // as one attribute and passed (Codex S3-11). And the value is |
| + // checked as an int64, not as its rendering, so a string "1" is not |
| + // mistaken for the count. |
| + attrs := recordAttrs(got) |
| + if len(attrs) != 1 { |
| + t.Fatalf("want exactly one attribute on the relay line, got %d: %v", len(attrs), attrs) |
| + } |
| + if attrs[0].Key != "regions" { |
| + t.Fatalf("the one attribute is %q, not regions", attrs[0].Key) |
| + } |
| + if attrs[0].Value.Kind() != slog.KindInt64 || attrs[0].Value.Int64() != 1 { |
| + t.Fatalf("regions is %v (%s), want the int64 1", attrs[0].Value, attrs[0].Value.Kind()) |
| } |
| if log := buf.String(); strings.Contains(log, "uMhwW4P") { |
| t.Fatal("the relay key reached the log") |
| @@ -106,10 +113,28 @@ func TestBuildLogsOneINFOLineWithTheRegionCountAndNotTheKey(t *testing.T) { |
| // there were, at what level, and with which attributes — the three |
| // questions a rendered line cannot answer. It forwards to a real |
| // handler as well, so a failure can still print what was written. |
| +// |
| +// The store is shared with every handler derived from this one, and the |
| +// attributes and groups bound along the way are kept and replayed onto |
| +// each record. Without both, a logger reached through WithAttrs wrote |
| +// into a store nobody read, and the attributes it was carrying were |
| +// invisible to the assertions — so a line that logged the decoded |
| +// contract through a bound attribute would have passed a test whose |
| +// name says it cannot (Codex S3-11). |
| type recordingHandler struct { |
| - inner slog.Handler |
| - mu sync.Mutex |
| - kept []slog.Record |
| + inner slog.Handler |
| + store *recordStore |
| + bound []slog.Attr |
| + groups []string |
| +} |
| + |
| +type recordStore struct { |
| + mu sync.Mutex |
| + kept []slog.Record |
| +} |
| + |
| +func newRecordingHandler(inner slog.Handler) *recordingHandler { |
| + return &recordingHandler{inner: inner, store: &recordStore{}} |
| } |
| func (h *recordingHandler) Enabled(ctx context.Context, l slog.Level) bool { |
| @@ -117,24 +142,84 @@ func (h *recordingHandler) Enabled(ctx context.Context, l slog.Level) bool { |
| } |
| func (h *recordingHandler) Handle(ctx context.Context, r slog.Record) error { |
| - h.mu.Lock() |
| - h.kept = append(h.kept, r.Clone()) |
| - h.mu.Unlock() |
| + kept := r.Clone() |
| + if len(h.bound) > 0 { |
| + // Bound attributes belong to the record as much as the ones the |
| + // call site passed: they are what a reader of the line sees. |
| + front := slog.NewRecord(r.Time, r.Level, r.Message, r.PC) |
| + front.AddAttrs(h.bound...) |
| + r.Attrs(func(a slog.Attr) bool { |
| + front.AddAttrs(a) |
| + return true |
| + }) |
| + kept = front |
| + } |
| + if len(h.groups) > 0 { |
| + // A grouped record is not the shape this test is about, and |
| + // pretending otherwise would hide it: keep it whole and let the |
| + // count assertion speak. |
| + kept.AddAttrs(slog.String("__groups", strings.Join(h.groups, "."))) |
| + } |
| + h.store.mu.Lock() |
| + h.store.kept = append(h.store.kept, kept) |
| + h.store.mu.Unlock() |
| return h.inner.Handle(ctx, r) |
| } |
| func (h *recordingHandler) WithAttrs(as []slog.Attr) slog.Handler { |
| - return &recordingHandler{inner: h.inner.WithAttrs(as)} |
| + return &recordingHandler{ |
| + inner: h.inner.WithAttrs(as), |
| + store: h.store, |
| + bound: append(append([]slog.Attr(nil), h.bound...), as...), |
| + groups: h.groups, |
| + } |
| } |
| func (h *recordingHandler) WithGroup(name string) slog.Handler { |
| - return &recordingHandler{inner: h.inner.WithGroup(name)} |
| + return &recordingHandler{ |
| + inner: h.inner.WithGroup(name), |
| + store: h.store, |
| + bound: h.bound, |
| + groups: append(append([]string(nil), h.groups...), name), |
| + } |
| } |
| func (h *recordingHandler) records() []slog.Record { |
| - h.mu.Lock() |
| - defer h.mu.Unlock() |
| - return append([]slog.Record(nil), h.kept...) |
| + h.store.mu.Lock() |
| + defer h.store.mu.Unlock() |
| + return append([]slog.Record(nil), h.store.kept...) |
| +} |
| + |
| +// recordAttrs is a record's attributes in order, duplicates and all. |
| +func recordAttrs(r slog.Record) []slog.Attr { |
| + var out []slog.Attr |
| + r.Attrs(func(a slog.Attr) bool { |
| + out = append(out, a) |
| + return true |
| + }) |
| + return out |
| +} |
| + |
| +// TestTheRecordingHandlerSeesWhatALoggerCarries is a test of the test: |
| +// the assertions above are only worth their names if the handler under |
| +// them keeps duplicate keys apart and carries bound attributes through. |
| +func TestTheRecordingHandlerSeesWhatALoggerCarries(t *testing.T) { |
| + rec := newRecordingHandler(slog.NewTextHandler(io.Discard, nil)) |
| + base := slog.New(rec) |
| + base.Info("plain", "regions", 1, "regions", 2) |
| + slog.New(rec).With("bound", "yes").Info("derived", "regions", 1) |
| + |
| + got := rec.records() |
| + if len(got) != 2 { |
| + t.Fatalf("want both records in one store, got %d", len(got)) |
| + } |
| + if attrs := recordAttrs(got[0]); len(attrs) != 2 { |
| + t.Fatalf("duplicate keys were collapsed: %v", attrs) |
| + } |
| + attrs := recordAttrs(got[1]) |
| + if len(attrs) != 2 || attrs[0].Key != "bound" { |
| + t.Fatalf("a bound attribute did not reach the record: %v", attrs) |
| + } |
| } |
| // TestSetRelayIsTypeConsistentWithBuildsInitialStore: build() stores a |
diff --git a/internal/meet/static/room.js b/internal/meet/static/room.js| index 81cf123..02633a6 100644 |
| --- a/internal/meet/static/room.js |
| +++ b/internal/meet/static/room.js |
| @@ -939,12 +939,13 @@ |
| // The four numbers that say where ICE stopped, and the one place |
| // they exist: a connection whose negotiation completed and whose |
| // transport never left `new` (the residual gate flake) is either |
| - // gathering nothing, posting nothing, receiving nothing, or |
| - // adding nothing, and only these tell those four apart. Counts, |
| - // never candidates: an address is not something this file |
| - // publishes. |
| + // gathering nothing, delivering nothing, receiving nothing, or |
| + // adding nothing, and only these tell those four apart. |
| + // `delivered` is counted where the hub accepts a candidate, not |
| + // where one is handed to the queue. Counts, never candidates: an |
| + // address is not something this file publishes. |
| gathered: 0, |
| - posted: 0, |
| + delivered: 0, |
| received: 0, |
| added: 0, |
| }; |
| @@ -1628,7 +1629,7 @@ |
| // and interrupting it would show the sentence to someone whose |
| // call is about to come back. |
| if (record && record.running) continue; |
| - markRelayExpired(id); |
| + markRelayExpired(id, expiring); |
| } |
| } |
| @@ -1639,18 +1640,30 @@ |
| // ICE restarts with a good new credential in hand, none of them |
| // proven — where the credential is fine and the path is not. Saying |
| // "expired" there would be a sentence about the wrong thing. |
| - function markRelayExpired(id) { |
| - markTrouble(id, 'expired'); |
| + function markRelayExpired(id, expiring) { |
| + markTrouble(id, 'expired', expiring); |
| } |
| - function markRenewalStuck(id) { |
| - markTrouble(id, 'stuck'); |
| + function markRenewalStuck(id, attempted) { |
| + markTrouble(id, 'stuck', attempted); |
| } |
| - function markTrouble(id, kind) { |
| - const record = renewalRecord(id); |
| - if (record.renewed) return; |
| - record.trouble = kind; |
| + // markTrouble is where a verdict becomes a sentence, and `upTo` is |
| + // the list the verdict is about: the credential that expired, or the |
| + // one a restart could not install. A connection proven onto something |
| + // newer has nothing to answer for and is left alone; anything else is |
| + // told. |
| + // |
| + // It used to read `record.renewed` instead — "did this connection |
| + // ever renew, once, at any time" — which was true for the rest of the |
| + // call after a single success and swallowed every later verdict |
| + // silently, watchdog included (Codex S3-8). The boolean is gone from |
| + // the decision entirely; `listAt` is the only thing that answers |
| + // which credential a connection is actually on. |
| + function markTrouble(id, kind, upTo) { |
| + const entry = pcs.get(id); |
| + if (!entry || (upTo && entry.listAt > upTo)) return; |
| + renewalRecord(id).trouble = kind; |
| renderTiles(); |
| } |
| @@ -1685,18 +1698,38 @@ |
| if (record.running) return false; |
| record.running = true; |
| record.renewed = false; |
| + // The stamp of the last list this run actually installed, for the |
| + // verdict at the bottom: it is the list the restarts failed on, and |
| + // not necessarily the newest one the call holds. |
| + let lastInstalled = ice.fetchedAt; |
| try { |
| for (let attempt = 1; attempt <= RENEW_ATTEMPTS; attempt++) { |
| if (state.stopped || pcs.get(id) !== entry) return false; |
| - record.attempts = attempt; |
| + // Restarts spent on this connection, and never reset: a |
| + // connection that is handed one list after another and cannot |
| + // land on any of them has spent all of them, and a count that |
| + // started again with each run read as 1 the instant a |
| + // follow-up began — which is a number that says nothing and |
| + // that a gate cannot wait on. |
| + record.attempts += 1; |
| // The generation this connection is on now, and the count of |
| // exchanges it has completed: the two things the proof is |
| // measured against. |
| const oldUfrag = await selectedUfrag(entry.pc); |
| const from = entry.desc; |
| + // The list this attempt installs, and the stamp that names it. |
| + // Read here and used on proof, because `ice.fetchedAt` is the |
| + // *newest* list the call has fetched and another tile's Retry |
| + // can replace it while this attempt is still running: stamping |
| + // the global one claimed the connection was on a credential it |
| + // had never been given, and handed it that credential's |
| + // schedule (Codex S3-9). |
| + const installed = ice.servers; |
| + const installedAt = ice.fetchedAt; |
| + lastInstalled = installedAt; |
| try { |
| - entry.pc.setConfiguration({ iceServers: ice.servers }); |
| - entry.floor = !ice.servers.length; |
| + entry.pc.setConfiguration({ iceServers: installed }); |
| + entry.floor = !installed.length; |
| } catch { |
| // An older browser without setConfiguration: the restart still |
| // re-gathers, on the servers this connection was built with. |
| @@ -1715,7 +1748,7 @@ |
| requestReset(id); |
| await sleep(RENEW_WINDOW); |
| if (state.stopped || pcs.get(id) !== entry) return false; |
| - markRenewalStuck(id); |
| + markRenewalStuck(id, installedAt); |
| return false; |
| } |
| const proven = await proveRenewed(id, entry, oldUfrag, from, Date.now() + RENEW_WINDOW); |
| @@ -1724,17 +1757,42 @@ |
| record.renewed = true; |
| record.ufrag = proven; |
| record.at = Date.now(); |
| - entry.listAt = ice.fetchedAt; |
| + entry.listAt = installedAt; |
| record.trouble = ''; |
| renderTiles(); |
| return true; |
| } |
| } |
| - markRenewalStuck(id); |
| + markRenewalStuck(id, lastInstalled); |
| return false; |
| } finally { |
| record.running = false; |
| - } |
| + // And if a newer list arrived while this attempt was running, |
| + // this connection owes a renewal onto it: `renewOutdated` skipped |
| + // it because a restart was in flight, and nothing else is coming |
| + // for it until the next scheduled renewal (Codex S3-9). |
| + followUp(id, lastInstalled); |
| + } |
| + } |
| + |
| + // followUp is that debt, paid once the attempt that incurred it has |
| + // let go of the record. `attempted` is the newest list that run had |
| + // to work with: only a list newer than *that* is a debt, which is |
| + // what keeps a connection that simply cannot be renewed from |
| + // restarting itself for ever. A timeout of zero rather than a direct |
| + // call, because `renewOne` refuses to start while `running` is set |
| + // and this runs from the `finally` that clears it. |
| + function followUp(id, attempted) { |
| + if (state.stopped || ice.fetchedAt <= attempted) return; |
| + const entry = pcs.get(id); |
| + if (!entry || entry.listAt >= ice.fetchedAt) return; |
| + setTimeout(() => { |
| + const now = pcs.get(id); |
| + if (state.stopped || !now || now.listAt >= ice.fetchedAt) return; |
| + renewOne(id).catch((err) => { |
| + console.error('meet: renew', err); |
| + }); |
| + }, 0); |
| } |
| // retryRenewal is the control §5.3 step 3 puts on a tile in trouble: |
| @@ -1912,10 +1970,6 @@ |
| function send(to, type, payload) { |
| if (!state.peer) return; |
| - if (type === 'candidate') { |
| - const entry = pcs.get(to); |
| - if (entry) entry.posted += 1; |
| - } |
| // A target the hub has already said it does not have. Queueing for |
| // it would buy one more 404 and one more recovery round each time, |
| // and ICE alone produces a dozen candidates a renegotiation; the |
| @@ -1966,6 +2020,14 @@ |
| return; |
| } |
| if (res.status === 200) { |
| + // Accepted by the hub, which is the only count worth having: |
| + // one taken at `send` counted candidates that a stale target |
| + // dropped on the spot and ones still sitting in a queue |
| + // nobody was pumping (Codex S3-12). |
| + if (head.body.type === 'candidate') { |
| + const entry = pcs.get(to); |
| + if (entry) entry.delivered += 1; |
| + } |
| q.shift(); |
| wait = BACKOFF_MIN; |
| continue; |
| @@ -2772,7 +2834,7 @@ |
| for (const [id, entry] of pcs) { |
| out[id] = { |
| gathered: entry.gathered, |
| - posted: entry.posted, |
| + delivered: entry.delivered, |
| received: entry.received, |
| added: entry.added, |
| pending: entry.pending.length, |
| @@ -2832,10 +2894,10 @@ |
| frames: new Map(frames), |
| signaling, |
| connection, |
| - // Where ICE got to, per connection: gathered, posted, |
| - // received, added, and what is still buffered waiting for a |
| - // remote description. Four counts and a length — never an |
| - // address. |
| + // Where ICE got to, per connection: gathered, delivered |
| + // (accepted by the hub), received, added, and what is still |
| + // buffered waiting for a remote description. Four counts and a |
| + // length — never an address. |
| candidates: candidateState(), |
| // §5.2 and §5.3, for the gate. The three clocks are |
| // milliseconds since the epoch, converted once in fetchIce, so |
| @@ -2856,8 +2918,9 @@ |
| // on: nothing is timed, and that is deliberate (W3-12). |
| schedulable: schedulable(), |
| }, |
| - // Per connection: how many restarts §5.3 step 2 has spent, and |
| - // whether one of them was proven. `ufrag` is the ICE username |
| + // Per connection: how many restarts §5.3 step 2 has spent |
| + // since this connection was built — across runs, never reset — |
| + // and whether one of them was proven. `ufrag` is the ICE username |
| // fragment the proof found — a generation name, not a |
| // credential. |
| renewals: renewalState(), |
diff --git a/test/browser/call.mjs b/test/browser/call.mjs| index 6a405e1..7ec2faa 100644 |
| --- a/test/browser/call.mjs |
| +++ b/test/browser/call.mjs |
| @@ -325,8 +325,9 @@ async function diagnose(page, label) { |
| renewals: s.renewals, |
| // Where ICE got to, per peer. The pcState above says |
| // negotiation finished; these say whether anything was |
| - // ever gathered, sent, received or added afterwards, which |
| - // is the next question and the one nothing else answers. |
| + // ever gathered, delivered to the hub, received or added |
| + // afterwards, which is the next question and the one |
| + // nothing else answers. |
| candidates: s.candidates, |
| } |
| : null, |
| @@ -565,10 +566,15 @@ const pcTap = () => { |
| } |
| return (h >>> 0).toString(16); |
| }; |
| - const note = (at, config) => { |
| + // `pc` is the connection's index in __pcs, so a configuration can be |
| + // attributed to the connection that took it: without that, repeated |
| + // updates to one connection could stand in for another left on the |
| + // empty list (Codex S3-10). |
| + const note = (at, pc, config) => { |
| const servers = (config && config.iceServers) || []; |
| window.__iceConfigs.push({ |
| at, |
| + pc, |
| servers: servers.length, |
| credentialed: servers.filter((v) => v.credential).length, |
| digest: digest(servers), |
| @@ -577,13 +583,18 @@ const pcTap = () => { |
| window.RTCPeerConnection = new Proxy(Real, { |
| construct(target, args) { |
| const pc = Reflect.construct(target, args); |
| + const index = window.__pcs.length; |
| window.__pcs.push(pc); |
| - note('construct', args[0]); |
| + note('construct', index, args[0]); |
| const real = pc.setConfiguration && pc.setConfiguration.bind(pc); |
| if (real) { |
| pc.setConfiguration = (config) => { |
| - note('setConfiguration', config); |
| - return real(config); |
| + // After the real call returns, never before: a |
| + // setConfiguration that throws installs nothing, and |
| + // recording it first counted an attempt as an installation. |
| + const out = real(config); |
| + note('setConfiguration', index, config); |
| + return out; |
| }; |
| } |
| return pc; |
| @@ -591,6 +602,18 @@ const pcTap = () => { |
| }); |
| }; |
| +// installedPerConnection folds the trap's log into "what each live |
| +// connection is actually configured with": the last configuration it |
| +// took, keyed by the connection's own index. |
| +function installedPerConnection(configs, live) { |
| + const out = new Map(); |
| + for (const c of configs) { |
| + if (live && !live.includes(c.pc)) continue; |
| + out.set(c.pc, c); |
| + } |
| + return Array.from(out.entries()).map(([pc, c]) => ({ pc, ...c })); |
| +} |
| + |
| // iceConfigs is what the trap recorded: one entry per configuration the |
| // page installed, in order, with a digest standing in for the |
| // credentials it carried. |
| @@ -598,6 +621,15 @@ function iceConfigs(page) { |
| return page.evaluate(() => window.__iceConfigs || []); |
| } |
| +// livePcs is the indices of the connections the page still holds open, |
| +// so a configuration belonging to one that has since been closed and |
| +// rebuilt is not read as the current state of anything. |
| +function livePcs(page) { |
| + return page.evaluate(() => (window.__pcs || []) |
| + .map((pc, i) => (pc.connectionState === 'closed' ? -1 : i)) |
| + .filter((i) => i >= 0)); |
| +} |
| + |
| // selectedUfrags is §5.3 step 2's reading taken independently of the |
| // client's: the transport names the selected pair, the pair names its |
| // local candidate, and the candidate carries the ICE generation's |
| @@ -885,21 +917,16 @@ const run = { |
| // if every RTCPeerConnection were constructed with an empty list; |
| // this is what the constructor received (Codex S3-5). |
| const configs = await iceConfigs(page); |
| - const built = configs.filter((c) => c.at === 'construct'); |
| - const floor = built.filter((c) => c.servers === 0); |
| - const installed = configs.filter((c) => c.at === 'setConfiguration' && c.servers === 2); |
| - check(built.length > 0 && configs.some((c) => c.servers === 2 && c.credentialed === 1), |
| - label + ' put the two-entry list, one credentialed, into a real connection (' + |
| - JSON.stringify(configs) + ')'); |
| - // Built with it, or given it before it could need it. Both are |
| - // §5.2: the first roster waits for the fetch, but a `peer` that |
| - // lands inside that fetch builds on the floor's empty list and |
| - // adopts the real one at its next quiet moment. What must never |
| - // happen is a connection left on the empty list — which is what |
| - // the client's own cached count could not tell anyone. |
| - check(floor.length <= installed.length, |
| - label + ' left no connection on the empty list (' + floor.length + ' built on the floor, ' + |
| - installed.length + ' given the list afterwards)'); |
| + const live = await livePcs(page); |
| + const now = installedPerConnection(configs, live); |
| + // Per connection, and the *last* configuration each one took: a |
| + // connection built with the list and one that adopted it at its |
| + // first quiet moment are both §5.2, and neither may be left on |
| + // the empty one. Counted globally, one connection's second update |
| + // could stand in for another's first (Codex S3-10). |
| + check(now.length > 0 && now.every((c) => c.servers === 2 && c.credentialed === 1), |
| + label + ' has every live connection configured with the two-entry list, one credentialed (' + |
| + JSON.stringify(now) + ' of ' + JSON.stringify(configs) + ')'); |
| check(s.ice.fetches === 1, |
| label + ' fetched the list once for the call, not once per connection (fetches=' + s.ice.fetches + ')'); |
| check(s.ice.expiresAt > Date.now() && s.ice.renewAt > Date.now() && s.ice.renewAt < s.ice.expiresAt, |
| @@ -1031,7 +1058,9 @@ const run = { |
| // carry this call either way (Codex S3-5). Digests, never |
| // credentials. |
| const configs = await iceConfigs(pageA); |
| - const credentialed = configs.filter((c) => c.servers === 2 && c.credentialed === 1); |
| + const live = await livePcs(pageA); |
| + const mine = configs.filter((c) => live.includes(c.pc)); |
| + const credentialed = mine.filter((c) => c.servers === 2 && c.credentialed === 1); |
| const digests = Array.from(new Set(credentialed.map((c) => c.digest))); |
| // Two credentialed configurations with *different* digests: the |
| // first list this connection was given, and the replacement the |
| @@ -1042,7 +1071,11 @@ const run = { |
| // page as anything but digests. |
| check(credentialed.length >= 2 && digests.length >= 2, |
| 'the renewal installed a credential different from the one this connection had (' + |
| - JSON.stringify(configs.map((c) => c.at + ':' + c.servers + ':' + c.digest)) + ')'); |
| + JSON.stringify(mine.map((c) => c.at + ':' + c.pc + ':' + c.servers + ':' + c.digest)) + ')'); |
| + const last = installedPerConnection(mine, live); |
| + check(last.length > 0 && last.every((c) => c.digest === digests[digests.length - 1]), |
| + 'and it is the newer credential each live connection is left on (' + |
| + JSON.stringify(last) + ')'); |
| } |
| // The call is what matters, not the restart: frames rising on both |
| @@ -1160,7 +1193,11 @@ const run = { |
| check(verdict.expired === false, |
| 'and it is not marked expired: a replacement credential was in hand throughout (' + |
| JSON.stringify(verdict) + ')'); |
| - check(verdict.attempts === 3, |
| + // Three or more: a connection that cannot renew keeps being |
| + // handed the next list as it arrives, and every restart it |
| + // spends counts. What matters is that the first verdict came |
| + // after a whole budget, not after one attempt. |
| + check(verdict.attempts >= 3, |
| 'it spent the whole three-restart budget first (' + verdict.attempts + ')'); |
| check(verdict.renewed === false, 'and nothing was proven (' + JSON.stringify(verdict) + ')'); |
| const notes = await tileNotes(pageA); |
diff --git a/test/browser/negotiation.test.mjs b/test/browser/negotiation.test.mjs| index 7aab2e8..e8d1698 100644 |
| --- a/test/browser/negotiation.test.mjs |
| +++ b/test/browser/negotiation.test.mjs |
| @@ -465,11 +465,28 @@ test('the proof stops when the connection is replaced under it', async () => { |
| // "built at or after ice.fetchedAt" exempted every connection in the |
| // call and marked nothing, ever. The stamp is captured before the fetch |
| // and passed in instead. |
| +// Through the real marking functions, not a stub for them: the last |
| +// round's version passed a spy for `markRelayExpired` and so proved |
| +// nothing about what the shipped one does when it gets there — which |
| +// was to return without a word, because an earlier success had left |
| +// `record.renewed` true for the rest of the call (Codex S3-8). The |
| +// sentence a person would read is lifted too, and asserted. |
| const watchdog = new Function( |
| - 'state', 'pcs', 'renewals', 'markRelayExpired', |
| - lift(src, 'expireUnrenewed') + '\nreturn { expireUnrenewed };', |
| + 'state', 'pcs', 'renewals', 'renderTiles', 'relayConfigured', |
| + 'ICE_EXPIRED', 'ICE_STUCK', 'FAILED_RELAY', 'FAILED_PLAIN', |
| + [lift(src, 'expireUnrenewed'), lift(src, 'markRelayExpired'), |
| + lift(src, 'markTrouble'), lift(src, 'renewalRecord'), |
| + lift(src, 'tileNote')].join('\n') + |
| + '\nreturn { expireUnrenewed, tileNote };', |
| ); |
| +const EXPIRED_SENTENCE = 'The relay credential expired for this connection.'; |
| + |
| +function watching(pcs, renewals) { |
| + return watchdog({ stopped: false }, pcs, renewals, () => {}, true, |
| + EXPIRED_SENTENCE, 'stuck sentence', 'relay sentence', 'plain sentence'); |
| +} |
| + |
| test('the must-succeed-by marks the connections that credential was about, and only those', () => { |
| const expiring = 1000; // the fetch stamp of the credential that ran out |
| const pcs = new Map([ |
| @@ -483,13 +500,12 @@ test('the must-succeed-by marks the connections that credential was about, and o |
| ['restarting', { running: true, renewed: false }], |
| ['proven-onto-the-new-one', { running: false, renewed: true }], |
| ]); |
| - const marked = []; |
| - const { expireUnrenewed } = watchdog( |
| - { stopped: false }, pcs, renewals, (id) => marked.push(id), |
| - ); |
| + const { expireUnrenewed } = watching(pcs, renewals); |
| expireUnrenewed(expiring); |
| + const marked = Array.from(renewals.entries()) |
| + .filter(([, r]) => r.trouble === 'expired').map(([id]) => id); |
| assert.deepEqual(marked.sort(), ['older', 'on-it'], |
| 'a connection built on the expiring credential, with nothing running, is the whole point'); |
| }); |
| @@ -505,17 +521,31 @@ test('a renewal in an earlier cycle does not exempt a connection from a later on |
| // Cycle 2's fetch then fails, and the credential that expires is that |
| // same list — which this connection is still using. |
| const cycleOne = 2000; |
| - const pcs = new Map([['them', { listAt: cycleOne }]]); |
| - const renewals = new Map([['them', { running: false, renewed: true, attempts: 1 }]]); |
| - const marked = []; |
| - const { expireUnrenewed } = watchdog( |
| - { stopped: false }, pcs, renewals, (id) => marked.push(id), |
| - ); |
| + const entry = { listAt: cycleOne, failed: false }; |
| + const pcs = new Map([['them', entry]]); |
| + const renewals = new Map([['them', { running: false, renewed: true, attempts: 1, trouble: '' }]]); |
| + const { expireUnrenewed, tileNote } = watching(pcs, renewals); |
| expireUnrenewed(cycleOne); |
| - assert.deepEqual(marked, ['them'], |
| + assert.equal(renewals.get('them').trouble, 'expired', |
| 'the second credential expired under a connection that had renewed once, and nobody was told'); |
| + assert.equal(tileNote('them', entry), EXPIRED_SENTENCE, |
| + 'and the tile has to say so, which is the whole point of marking it'); |
| +}); |
| + |
| +test('a connection already proven onto a newer list is left alone by the deadline', () => { |
| + // The other direction, so the fix above cannot be "mark everything": |
| + // this one really is on a newer credential. |
| + const entry = { listAt: 3000, failed: false }; |
| + const pcs = new Map([['them', entry]]); |
| + const renewals = new Map([['them', { running: false, renewed: true, attempts: 1, trouble: '' }]]); |
| + const { expireUnrenewed, tileNote } = watching(pcs, renewals); |
| + |
| + expireUnrenewed(2000); |
| + |
| + assert.equal(renewals.get('them').trouble, ''); |
| + assert.equal(tileNote('them', entry), '', 'and its tile says nothing'); |
| }); |
| @@ -980,6 +1010,7 @@ const machine = new Function( |
| 'state', 'pcs', 'renewals', 'ice', 'fetchIce', 'requestReset', 'renderTiles', |
| 'bareRestart', 'RENEW_ATTEMPTS', 'RENEW_WINDOW', 'RENEW_POLL', 'console', |
| [lift(src, 'renewOne'), lift(src, 'renewOutdated'), lift(src, 'retryRenewal'), |
| + lift(src, 'followUp'), |
| lift(src, 'renewalRecord'), lift(src, 'markTrouble'), lift(src, 'markRenewalStuck'), |
| lift(src, 'markRelayExpired'), lift(src, 'proveRenewed'), lift(src, 'renewedUfrag'), |
| lift(src, 'selectedPairUfrag'), lift(src, 'selectedUfrag'), lift(src, 'statsList'), |
| @@ -1039,7 +1070,11 @@ test('a fresh credential buys three restarts and the verdict is stuck, never exp |
| const them = renewable(['old0']); |
| const m = mesh({ them }); |
| - const ok = await m.renewOne('them'); |
| + // The second argument is deliberate and deliberately ignored: an old |
| + // deadline, passed the way the removed optional-deadline branch used |
| + // to take one. Restore that branch and this test fails on the first |
| + // attempt (Codex round 2's note on this test). |
| + const ok = await m.renewOne('them', Date.now() - 60000); |
| assert.equal(ok, false); |
| const record = m.renewals.get('them'); |
| @@ -1062,6 +1097,40 @@ test('a restart that lands is proven, stamped and quiet', async () => { |
| assert.equal(them.listAt, m.ice.fetchedAt, 'and the connection is stamped onto the list it took'); |
| }); |
| +test('a Retry reaches a connection whose own restart was already running', async () => { |
| + // Codex S3-9's other half. B is mid-restart when the Retry fetches: |
| + // renewOutdated skips it, rightly — cutting across an attempt is what |
| + // broke the media in an earlier round — so the debt is paid when that |
| + // attempt settles, and B ends up on the new list rather than keeping |
| + // the old one until the next schedule. |
| + const a = renewable(['a0', 'a0', 'a1']); |
| + // B's fragments have to carry two restarts — its own, and the |
| + // follow-up onto the list the Retry fetches — and the first has to |
| + // take long enough that the Retry really does land inside it. |
| + const b = renewable(['b0', 'b0', 'b0', 'b0', 'b1', 'b1', 'b1', 'b2']); |
| + const m = mesh({ a, b }, true); |
| + |
| + const running = m.renewOne('b'); // B is restarting already |
| + // Far enough in that B has installed the list it is renewing onto, |
| + // and not so far that its proof has already landed: a fetch before |
| + // the install is one B takes for itself, and one after the proof |
| + // finds B idle — both are different cases, and neither is this. |
| + await new Promise((resolve) => setTimeout(resolve, 15)); |
| + await m.retryRenewal('a', 'expired'); // and A's tile is clicked |
| + await running; |
| + await new Promise((resolve) => setTimeout(resolve, 600)); |
| + |
| + assert.equal(m.renewals.get('a').renewed, true); |
| + assert.equal(m.renewals.get('b').renewed, true); |
| + assert.equal(b.listAt, m.ice.fetchedAt, |
| + 'B is on the list the Retry fetched, not the one it was mid-restart onto'); |
| + // And it got there by actually restarting onto it. Without the |
| + // follow-up, B's first proof simply stamped whatever the newest list |
| + // happened to be, which reads the same and is not the same thing. |
| + assert.ok(b.calls.filter((c) => c === 'restartIce').length >= 2, |
| + 'B restarted again for the newer list rather than claiming it (' + JSON.stringify(b.calls) + ')'); |
| +}); |
| + |
| test('a Retry on one tile renews every connection the fetch re-credentialed', async () => { |
| // Codex S3-2. The fetch a Retry makes replaces the credential the |
| // whole call was using and resets the shared schedule with it, so |
| @@ -1142,3 +1211,33 @@ test('a margin under a second is not a schedule', () => { |
| test('the floor has nothing to say about a call with no relay', () => { |
| assert.equal(scheduling({ expiresAt: 0, servers: [], margin: 0 }, 1000).schedulable(), false); |
| }); |
| + |
| + |
| +test('a proof stamps the list it installed, not one that arrived while it was proving', async () => { |
| + // Codex S3-9. A restart installs list B and starts proving it. Another |
| + // tile's Retry fetches C in the meantime — renewOutdated skips this |
| + // connection, because a restart is running — and when B's proof landed |
| + // the connection was stamped with C: a credential it had never been |
| + // given, whose schedule then governed it. |
| + const them = renewable(['old0', 'old0', 'new1', 'new1', 'new1', 'new2']); |
| + const m = mesh({ them }, true); |
| + const B = m.ice.fetchedAt; |
| + |
| + // C arrives after the list is installed and while the proof polls. |
| + const real = them.pc.getStats.bind(them.pc); |
| + let calls = 0; |
| + them.pc.getStats = () => { |
| + calls += 1; |
| + if (calls === 2) m.ice.fetchedAt += 1000; |
| + return real(); |
| + }; |
| + |
| + assert.equal(await m.renewOne('them'), true); |
| + assert.equal(them.listAt, B, |
| + 'the connection is on the list it installed, not on one that merely arrived'); |
| + |
| + // And the debt that leaves is paid: nothing else was coming for this |
| + // connection, because renewOutdated had already passed it by. |
| + await new Promise((resolve) => setTimeout(resolve, 600)); |
| + assert.equal(them.listAt, m.ice.fetchedAt, 'and it is renewed onto the newer list afterwards'); |
| +}); |