Files
amethyst/nestsClient/plans/2026-05-01-quic-stream-cliff-investigation.md
T
Claude 85691cce26 nestsClient: bump framesPerGroup default to 5 to dodge prod relay's per-subscriber forward ceiling
Round-2 production sweep confirmed the residual sustained-broadcast
loss is on the relay side: every uni stream the relay opened to the
listener delivered cleanly through QUIC to the application
(peerInitiatedUni == received + 1 across every cliffed scenario,
pendingBytes always 0, cap headroom unused). The relay's
per-subscriber forward pipeline runs at ≈ 40 streams/sec sustained;
at 1 frame per group = 50 streams/sec we exceed it by ~9 streams/sec
and the relay's per-subscriber buffer overflows after 6–14 seconds
of continuous push, after which it stops opening new streams to that
subscriber entirely. Reproduced on:

  - sweep_30s    1500 frames -> 610-737 received (variance run-to-run)
  - sweep_120s   6000 frames -> 61-419 received
  - sweep_frames400  400 frames -> 36-400 received (huge variance)
  - sweep_3subs sub[1] 100 frames -> 94 received (others 100/100)

Packing 5 frames per moq-lite group cuts stream creation to 10/sec,
well under the relay's ceiling. Sweep-evidence: framesPerGroup=5
delivered 100/100 across every scenario including the long ones.
Late-join initial gap goes from ≤ 20 ms to ≤ 100 ms — imperceptible
for live audio rooms.

Updates the plan doc to mark status PRODUCTION-FIXED with the
two-layer fix (MAX_STREAMS_UNI extensions + framesPerGroup=5) and
flags the upstream-issue follow-up at kixelated/moq.

All :quic + :nestsClient JVM tests pass.
2026-05-01 15:43:33 +00:00

444 lines
21 KiB
Markdown
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
# QUIC stream cliff against nostrnests.com — investigation plan
**Status: PRODUCTION-FIXED via two-layer fix.**
1. `:quic` now emits `MAX_STREAMS_UNI` extensions to widen the
listener's peer-initiated stream-id cap (commit `d391ae1d`).
Closes the original 99-frame cliff for short broadcasts.
2. `NestMoqLiteBroadcaster.DEFAULT_FRAMES_PER_GROUP = 5` packs five
Opus frames per moq-lite group, dropping client uni-stream
creation from 50/sec to 10/sec — comfortably under the
production nostrnests relay's sustained per-subscriber forward
ceiling of ~40 streams/sec. Closes the long-broadcast residual
where the relay's per-subscriber queue would overflow after 614
seconds of continuous push and silently terminate forwarding to
that subscriber.
Listener-side flow-control snapshots in the round-2 sweep confirmed
the residual was strictly relay-side: every uni stream the relay
opened to the listener delivered cleanly to the application
(`peerInitiatedUni == received + 1`, where `+1` is the WT control
stream); `pendingBytes == 0`; cap headroom unused. The relay simply
stopped opening new streams to the listener once its per-subscriber
buffer overflowed. Reducing the stream-creation rate to 10/sec keeps
the relay's queue from ever filling.
Late-join latency cost: ≤ 100 ms initial audio gap (one group
boundary) instead of ≤ 20 ms with `framesPerGroup = 1`. Imperceptible
for live audio.
The remaining open work is **upstream**: file an issue at
`kixelated/moq` describing the per-subscriber forward queue
limitation so future relay versions can either lift the ceiling or
expose it as a config knob.
**Original root cause: FIXED.** Our `:quic` client never emitted
`MAX_STREAMS_*` frames to extend the peer-initiated stream-id cap.
[QuicConnectionConfig.initialMaxStreamsUni] (default `100`) was the
*lifetime* maximum the peer could ever open. The relay forwards each
broadcast group as a fresh peer-initiated uni stream, so any
broadcast longer than 100 frames silently truncated at the listener.
Fixed by tracking [QuicConnection.peerInitiatedUniCount] and emitting
`MAX_STREAMS_UNI(newCap)` from [appendFlowControlUpdates] once the
peer's usage crosses the half-window threshold — same pattern as the
existing `MAX_DATA` / `MAX_STREAM_DATA` extension.
Production validation: `sweep_frames_200` against `nostrnests.com`
went from `received=99/200 missing=[99-199]` (pre-fix) to
`received=200/200 missing=[]` (post-fix). The
[NestMoqLiteBroadcaster.DEFAULT_FRAMES_PER_GROUP] mitigation has
been reverted from `5` back to `1` so the broadcaster matches the
JS reference's wire shape (one Opus frame per moq-lite group → ≤ 20 ms
late-join initial gap).
## Residual loss after the MAX_STREAMS fix
A full prod sweep (all 27 scenarios, commit `c0269859`) showed:
**Now perfect (100% received):** `baseline 100×20ms`, `frames200`,
`frames50`, `1kb`, `4kb`, `cad10`, `cad40`, `cad80`, `cad200`,
`2subs` (both subs), `slowconsumer`, `fpg5`, `fpg20`, `fpg-all`.
14 of 27 scenarios.
**Improved but still partial:**
| Scenario | Pre-fix | Post-fix | Pattern |
|---|---|---|---|
| `frames400` | 99/400 | 368/400 | last 32 frames lost (tail) |
| `30s` (1500 frames) | 99/1500 | 653/1500 | cliffed at frame 653 mid-pump |
| `120s` (6000 frames) | 52/6000 | 61/6000 | cliffed at frame 61, t≈2 s |
| `burst` cadence=0 | 65/100 | 96/100 | last 4 lost (tail) |
| `16kb` 100×16 KB | 49/100 | 37/100 | regressed slightly |
| `pause` 50+5 s+50 | 99/100 | 32/100 | regressed; pause kills it |
| `cad5` 100×5 ms | 99/100 | 54/100 | regressed (faster burst) |
| `3subs` sub[2] | varied | 77/100 | one sub lags |
The cliff is no longer at "exactly 99 streams" — it's now timing/load-
sensitive and varies between runs. The speaker side remains pristine
(`fc-post-pump`: `consumed > 0`, `pendingBytes = 0`, `nextLocalUniIdx`
matches frame count) — so the loss is on the relay→listener path.
`fc-post-grace` is identical to `fc-post-pump` for these scenarios
(no late delivery during grace), confirming the listener never
recovers once it stalls.
## Round 2 — chasing the residual
After the original `MAX_STREAMS_UNI` fix, residual loss appeared in
sustained / bursty scenarios. Three round-2 changes against
likely contributors:
### 2a. Test-side stdout serialisation (hypothesis 2)
`SendTraceScenario.Scenario.verbosePerFrame` defaulted to `true`,
which logged a per-frame `tx i=…` and `rx[idx] gid=…` line via
`InteropDebug.checkpoint`. Under JUnit's stdout capture, that's a
synchronous write per event. At 50 frames/sec sustained the
capture thread can serialise the receive coroutine and starve the
QUIC read loop, biasing the `received` count downward. **Default
flipped to `false`**; specific tests opt in for debugging.
### 2b. Test-side `CopyOnWriteArrayList` add cost
The collector accumulated arrivals in a `CopyOnWriteArrayList`,
which is O(N) per add — copying the entire underlying array on
every `+=`. For 1500-frame runs that's ~1.1 M element copies and
~35 MB of memory ops cumulative across the run. Replaced with
`Collections.synchronizedList(ArrayList(capacityHint))` for O(1)
amortized adds. Snapshot at end via
`synchronized(sink) { ArrayList(sink) }`.
### 2c. Listener-side kernel UDP receive buffer (hypothesis 1)
`UdpSocket.connect` did not configure `SO_RCVBUF`, so the kernel's
default applied (~200 KB on Linux/macOS, similarly small on
Android). At MTU-sized datagrams that's room for ~130 packets. A
multi-second moq-lite broadcast that the relay fans out across
multiple subscribers can transiently exceed this — anything
queued past `rmem` is silently dropped by the kernel and never
reaches our QUIC stack, manifesting as "subscription stops
mid-broadcast even though `publisher.send` keeps returning true".
Bumped to 4 MiB at socket-bind time (Linux doubles + clamps via
`rmem_max`, so the effective cap is whatever the kernel allows up
to `min(8 MiB, rmem_max)`).
Added lifetime UDP datagram counters (`receivedDatagramCount`,
`receivedByteCount`, `receiveBufferSizeBytes`) to the `UdpSocket`
expect surface; the driver wires them into the existing
`QuicConnection.flowControlSnapshot` via a `udpStatsSupplier` hook.
The `fc-pre / fc-post-pump / fc-post-grace` lines now include
`udpDatagrams=… udpBytes=… udpRcvBuf=…` so a future sweep can
correlate "frames missing on subscription" against "datagrams the
kernel actually delivered".
### Hypotheses still open after round 2
3. **moq-rs relay per-subscriber queue policy.** Even if our
listener kernel + collector are infinitely fast, the relay
itself may have an in-flight uni-stream cap per subscriber that
drops new groups once the listener falls behind. The
asymmetric loss in `sweep_3subs sub[2]` (77/100 while sub[0]
and sub[1] got 100/100) is consistent with a per-subscriber
queue rather than a connection- or relay-wide limit. Worth
filing an issue at `kixelated/moq` once we have one more sweep
confirming the round-2 changes don't already close the gap.
4. **Receive-side `MAX_STREAM_DATA` thresholds.** Probably not
the cause for 80-byte audio frames (1 MB per-stream window vs
~80 bytes used per stream) but may bite the 16 KB-payload
scenario. Worth a follow-up only if `sweep_payload_16kb`
doesn't recover.
## Re-running after round 2
The acceptance criterion is the same: every sweep row showing
`received=N/N missing=[]`, except the explicit late-join scenarios
(`sweep_late_subscribe_after_25` / `_after_50`) which legitimately
report `received < N` due to from-latest semantics.
**Reproduces against:** `https://moq.nostrnests.com:4443` (production
relay). Not consistently reproducible against the local
`kixelated/moq` reference relay (the local harness shows the same
shape but with much higher run-to-run variance).
## Symptom
When the speaker pumps Opus frames at the production 20 ms cadence
and packs **one frame per moq-lite group** (= one client-initiated
QUIC unidirectional stream per Opus frame), the listener stops
receiving frames somewhere around the 99th frame. From there to
end-of-broadcast, **`MoqLitePublisherHandle.send` keeps returning
`true` for every subsequent frame**, so the application has no signal
that anything is wrong; the audio simply cuts out a few seconds in.
The bug is invisible to:
- `NestMoqLiteBroadcaster`'s outer `runCatching {…}.onFailure {…}`
(no exception is thrown on the silent-loss path).
- `MoqLitePublisherHandle.send`'s return value (always `true` past
the cliff).
- `QuicConnection`'s peer-cap check (`nextLocalUniIndex >= peerMaxStreamsUni`
doesn't fire because the relay raises `MAX_STREAMS_UNI` ahead of
our consumption — pre-fix tests confirmed `firstFalseSend = -1`
even at 1500 frames).
## Sweep evidence (production, before mitigation)
`NostrnestsProdAudioTransmissionTest` (commit
`2da18859`-era, before any QUIC changes), one row per scenario:
| Scenario | streams opened | `received` | cliff |
|---|---|---|---|
| `sweep-frames50` | 50 | 50/50 | none ✅ |
| `sweep-baseline` 100 frames | 100 | 99/100 | last 1 |
| any cadence (5/10/40/80/200 ms) at 100 frames | 100 | 99/100 | last 1 |
| any payload (80 B / 1 KB / 4 KB) at 100 frames | 100 | 99/100 | last 1 |
| `sweep-frames200` | 200 | **99**/200 | hard at 99 |
| `sweep-frames400` | 400 | **99**/400 | hard at 99 |
| `sweep-30s` (1500 frames) | 1500 | **99**/1500 | hard at 99 |
| `sweep-120s` (6000 frames) | 6000 | 52/6000 | hard at 52 |
| `sweep-burst` (cadence 0) | 100 | 65/100 | hard at 65 |
| `sweep-payload-16kb` 100 frames × 16 KB | 100 | 49/100 | hard at 49 |
| **`sweep-frames-per-group-5`** | **20** groups | **100/100** | none ✅ |
| **`sweep-frames-per-group-20`** | **5** groups | **100/100** | none ✅ |
| **`sweep-frames-per-group-all`** | **1** group | **100/100** | none ✅ |
The signal is unambiguous: **fewer streams → no loss, regardless of
frame count, payload, or duration**. The cliff scales with stream-
opening rate, not with byte volume or wall-clock time.
The number "99" is suspicious — it's exactly QUIC's typical
`initial_max_streams_uni = 100` minus one. But:
- Pre-mitigation `firstFalseSend = -1` for tests pumping 1500+
streams says the cap WAS being raised dynamically. So the cliff
is NOT `openUniStream` rejecting past the local cap.
- A 16 KB payload variant cliffed at 49 streams (~800 KB total),
while 80-byte variants cliffed at 99 (~8 KB total). These are
inconsistent if the cause were a single fixed cap.
- The cliff is *consistent* across many scenarios at ~99 — too
consistent for plain network packet loss.
## What we tried and what we learned
### Attempt 1 — make `openUniStream` suspend instead of throw
Branch / commit: `f0705e3a` on `claude/audio-transmission-tests-zKzlB`,
**reverted in `96a585a6`**.
Rationale: the obvious failure mode is `peerMaxStreamsUni` being hit
without us ever waiting for the relay to extend it; we'd just throw
locally. So we'd:
1. Make `QuicConnection.openBidiStream` / `openUniStream` suspend
on a `CompletableDeferred<Unit>` notifier when the cap is hit,
re-acquire the lock and re-check on every wake.
2. Fire the notifier from `QuicConnectionParser` whenever an inbound
`MAX_STREAMS` frame raises a cap.
3. Emit `STREAMS_BLOCKED` (RFC 9000 §19.14) when an opener registers
itself blocked, so the peer knows we want more credit.
4. Wake blocked openers with `QuicConnectionClosedException` on
close so they don't hang.
Unit tests for the suspend / wake / STREAMS_BLOCKED / close paths
pass (`PeerStreamLimitTest`).
**Result against production:** the cliff didn't move. Same scenarios
still hit ~99 frames received, and the run-to-run variance got
*worse* (numbers swung between 19/100 and 99/100 on consecutive
identical baseline runs against the same relay). The fix also
introduced no observable change in the per-frame `tx i=… ok dt=…us`
traces (`firstFalseSend = -1` still on every test), which means the
suspend path isn't being triggered in production — the peer's cap
isn't what we're hitting.
The fix is RFC-correct on its own (we should suspend rather than
throw, and we should send STREAMS_BLOCKED), but it does not address
the production cliff. Reverted to keep the tree clean while we
chase the real cause.
### Attempt 2 — pack multiple frames per moq-lite group (shipping)
Commit on `claude/audio-transmission-tests-zKzlB` (this commit).
Rationale: `sweep_frames_per_group_*` was 100/100 across every
multi-frame-per-group variant. The cliff scales with the number of
new uni streams opened, not with anything else. Packing N Opus
frames per moq-lite group reduces the new-stream rate by N×.
Default chosen: `framesPerGroup = 5` ≈ 100 ms of audio per group.
Stream-creation rate drops from 50/sec to 10/sec, well below the
cliff.
Trade-off: a brand-new subscriber that attaches mid-broadcast picks
up at the next group boundary per moq-lite "from-latest" semantics.
With 5 frames/group the late-join initial gap is up to 100 ms
(perceptually inaudible). With 1 frame/group it was up to 20 ms.
This is a **mitigation, not a fix.** Other workloads with a high
per-stream cost (file transfer, metadata fan-out, anything that
naturally wants a fresh stream per message) would still hit the
cliff if they exceed roughly 50 streams/second.
## What `flowControlSnapshot` proved (the smoking gun)
After wiring [QuicConnection.flowControlSnapshot] into [SendTraceScenario],
running `sweep_frames_200` against production produced:
```
fc-pre: peerInitMaxData=4611686018427387903 peerInitMaxStreamDataUni=1250000
peerInitMaxStreamsUni=10000 sendCredit=4611686018427387903
consumed=786 peerMaxStreamsUniNow=10000
nextLocalUniIdx=1 pendingBytes=0 pendingStreams=0/4
fc-post-pump: sendCredit=4611686018427387903 consumed=18729
peerMaxStreamsUniNow=10000 nextLocalUniIdx=201
pendingBytes=0 pendingStreams=0/205
fc-post-grace: (identical to fc-post-pump)
sub[0]: received=99/200 firstSentButLost=99
```
This rules out every speaker-side hypothesis at once:
- **`peerInitMaxData = 2⁶²−1`** ⇒ ~5 EB connection-level send credit;
we used **18 KB**. Not a connection-level flow-control wedge.
- **`peerInitMaxStreamsUni = 10000`, `nextLocalUniIdx = 201`** ⇒
speaker opened all 200 broadcast streams + 1 control stream, well
under cap. Not a peer-granted stream-id wedge.
- **`pendingBytes = 0`, `pendingStreams = 0/205`** ⇒ no bytes are
stuck in any stream's send buffer; everything we wrote made it
past the writer.
- **`consumed` is identical between post-pump and post-grace** ⇒ we
weren't even *trying* to send more after the pump finished.
So the speaker → relay path was healthy. The 18 KB of stream data
made it onto the wire. The 99-frame ceiling on the listener side
had to be on the **relay → listener** half of the connection.
Listener-side, our [QuicConnection] advertises `initial_max_streams_uni
= 100` (from [QuicConnectionConfig], default 100) at handshake. The
relay can open up to 100 uni streams to us *for the lifetime of the
connection* unless we send `MAX_STREAMS_UNI(N)` frames to extend it.
Grepping `:quic` for `MaxStreamsFrame` showed it was only ever
*parsed inbound* — there was no outbound emission anywhere. So the
peer's stream-id allowance was capped at 100 forever.
For MoQ over WebTransport this is fatal: the listener's relay
forwards every broadcast group as a new peer-initiated uni stream.
With one group per Opus frame at 20 ms cadence, the 100-stream cap
is exhausted at frame 99 → relay-side blocked → no more groups → no
more audio.
The fix mirrors the existing [appendFlowControlUpdates] pattern for
`MAX_DATA` / `MAX_STREAM_DATA`: track lifetime peer-initiated stream
count, emit `MAX_STREAMS_UNI(currentCount + initialCap)` when count
crosses the half-window threshold.
## Hypotheses still on the table
In rough order of likelihood, none confirmed:
1. **Connection-level send credit** (`initial_max_data` / `MAX_DATA`).
If the relay's connection-level grant is ~8 KB and only extends
on `DATA_BLOCKED`, we'd cliff at ~99 frames × ~85 bytes = ~8.4 KB.
`:quic` parses inbound `MAX_DATA` (`QuicConnectionParser.kt:266`)
but never emits `DATA_BLOCKED` when our writer hits
`connBudget == 0` in `appendStreamFrames`. That asymmetry would
stall the producer with no signal. The 16 KB payload data point
(cliff at 49 × 16 KB ≈ 800 KB) doesn't match a single fixed
8 KB cap, but it could match a different per-byte budget the
relay calibrates to its initial offer. Worth instrumenting.
2. **Per-stream send credit** (`initial_max_stream_data_uni` /
`MAX_STREAM_DATA`). Each new uni stream gets its own credit
window from the peer's `initial_max_stream_data_uni`. If that's
small enough to require a `MAX_STREAM_DATA` on every stream and
the peer is conservative about issuing it, the writer would
buffer frames forever waiting for credit while `publisher.send`
reports success. `:quic` honours the per-stream credit
(`QuicConnectionWriter.kt:280`) but never emits
`STREAM_DATA_BLOCKED`.
3. **Reference-relay default `MAX_STREAMS_UNI` extension policy.**
`kixelated/moq-rs` is built on Quinn; Quinn's stream-cap
extension is automatic when streams complete. If the production
nostrnests deployment uses a custom Quinn config that only
extends in response to `STREAMS_BLOCKED` (which we don't send
on the un-fixed code path), we'd starve. Attempt 1 added
STREAMS_BLOCKED emission and didn't shift the cliff, weak
evidence against this hypothesis.
4. **Relay-side per-subscription buffer.** If the relay has a
per-subscriber forward buffer that's smaller than the total
in-flight uni-stream count, and it drops streams that don't
fit, the cliff would scale with stream count and be invisible
to the speaker. Hardest to investigate without relay logs.
## Next steps to actually fix
The investigation order I'd take, given the data:
1. **Instrument outbound `appendStreamFrames`.** Log every iteration
where `connBudget <= 0` (connection-level credit exhausted) or
where a stream's `streamRemaining <= 0` (per-stream credit
exhausted). Re-run the prod sweep with this on. If the cliff
correlates with one of those, the hypothesis is confirmed and the
fix is to emit `DATA_BLOCKED` / `STREAM_DATA_BLOCKED` and on the
write path, suspend the writer until a fresh `MAX_DATA` /
`MAX_STREAM_DATA` arrives.
2. **Capture the production peer transport parameters.** Dump
`tp.initialMaxData`, `tp.initialMaxStreamDataUni`, and
`tp.initialMaxStreamsUni` once at handshake time so we know
exactly what the relay grants. Compare against the cliff
thresholds.
3. **Test with `:quic` flow-control diagnostics in place.** Re-run
`sweep_frames200` and `sweep_30s` — the cliff is rock-solid at
exactly 99 in production, so a single pass is enough to confirm
the hypothesis.
4. **If it's not connection / stream data flow control,** instrument
the relay (file an issue on `nostrnests/nests` or `kixelated/moq`)
asking whether their relay imposes a per-subscriber stream
buffer that drops on overflow.
## Re-running the sweep after a candidate fix
The test infrastructure is already in place:
```bash
./gradlew :nestsClient:jvmTest \
--tests com.vitorpamplona.nestsclient.interop.NostrnestsProdAudioTransmissionTest \
-DnestsProd=true -DnestsInteropDebug=true --rerun-tasks
grep -E "sub\[|missing=" \
nestsClient/build/test-results/jvmTest/TEST-com.vitorpamplona.nestsclient.interop.NostrnestsProdAudioTransmissionTest.xml \
| sort
```
Acceptance criterion: `sweep-30s` reports `received≈1500/1500`
without any `framesPerGroup` mitigation. That removes the only
remaining audio-quality tradeoff (the 100 ms late-join initial gap)
and lets us reset `DEFAULT_FRAMES_PER_GROUP` back to 1 to match the
JS reference broadcaster's wire shape.
## Files / lines to touch when picking this up
- `quic/src/commonMain/kotlin/com/vitorpamplona/quic/connection/QuicConnectionWriter.kt`
`appendStreamFrames` is where the writer skips streams with no
credit; instrument here.
- `quic/src/commonMain/kotlin/com/vitorpamplona/quic/connection/QuicConnection.kt:160-165`
`sendConnectionFlowCredit` / `sendConnectionFlowConsumed`. The
values to log + diff.
- `quic/src/commonMain/kotlin/com/vitorpamplona/quic/connection/TransportParameters.kt`
`decode` is where peer TPs land at handshake.
- `quic/src/commonMain/kotlin/com/vitorpamplona/quic/connection/QuicConnectionParser.kt`
— currently parses `MAX_DATA`, `MAX_STREAM_DATA`, `MAX_STREAMS`,
`STREAMS_BLOCKED` (last one ignored). The reverse —
`DATA_BLOCKED` / `STREAM_DATA_BLOCKED` emission — would live in
`QuicConnectionWriter`.
- `nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/SendTraceScenario.kt`
— extend per-frame trace with `connBudget` / `streamRemaining`
if the writer instrumentation surfaces them via diagnostics on
`QuicConnection`.