eea746a635
5/5 sweep BUILD SUCCESSFUL post-merge of `origin/main` (5 `:quic`
commits: ALPN-list threading `2a4c07ae`, PTO STREAM retransmits
`d5c854be`, RFC 9001 §6 1-RTT key update `b622d0c9`, multiconnect
pacing `86a4727e`, qlog flush `31d19258`). Pre-merge baseline on
the same branch with the same TRACE capture: 3 fail / 5,
all in `late_join_listener_still_decodes_tail`. 55/55 tests pass.
Updated:
- routing-investigation: marked CLOSED, added Closure section with
pre-merge vs post-merge sweep counts + sample 1.6 ms-RTT
late-join trace.
- late-join investigation: marked closed.
- closure-roadmap: Priority 1 ✅; Priorities 2 and 3 unblocked.
Preserved a post-merge passing late-join relay trace under
`nestsClient/plans/artefacts/2026-05-07-routing-race-closed-by-merge/`
as the "what healthy looks like" baseline.
516 lines
23 KiB
Markdown
516 lines
23 KiB
Markdown
# Plan: investigate moq-relay 0.10.x per-broadcast subscribe-routing race
|
||
|
||
**Status:** ✅ CLOSED. The flake was a `:quic` packet-acceptance bug,
|
||
not a moq-relay routing race. Merging
|
||
`origin/main` (5 commits: ALPN-list threading `2a4c07ae`, PTO STREAM
|
||
retransmits `d5c854be`, 1-RTT key update `b622d0c9`,
|
||
multiconnect/multiplex `86a4727e`, qlog flush `31d19258`) closes
|
||
it. Post-merge sweep:
|
||
**5/5 BUILD SUCCESSFUL, 55/55 tests pass** on
|
||
`./gradlew :nestsClient:jvmTest --tests HangInteropTest
|
||
-DnestsHangInterop=true -DnestsHangInteropTraceRelay=true --rerun-tasks`.
|
||
|
||
The acceptance bar of the closure roadmap's Priority 1 is met.
|
||
Priority 2 (`2026-05-07-tighten-cross-stack-assertions.md`) is now
|
||
unblocked; Priority 3 (`2026-05-07-cross-stack-interop-ci-gating.md`)
|
||
follows after that.
|
||
|
||
## Closure (2026-05-07, post-merge)
|
||
|
||
After the corrected diagnosis below pinned the actor on `:quic`,
|
||
five `:quic` commits had landed on `origin/main` between the
|
||
session's merge base and pickup. Merging them and re-running the
|
||
5× sweep gives:
|
||
|
||
```
|
||
sweep 1: BUILD SUCCESSFUL in 5m 9s (11/11 pass)
|
||
sweep 2: BUILD SUCCESSFUL in 2m 51s (11/11 pass)
|
||
sweep 3: BUILD SUCCESSFUL in 2m 41s (11/11 pass)
|
||
sweep 4: BUILD SUCCESSFUL in 2m 35s (11/11 pass)
|
||
sweep 5: BUILD SUCCESSFUL in 2m 34s (11/11 pass)
|
||
```
|
||
|
||
Pre-merge baseline on the same branch (commit `b2a42d9a`, same
|
||
TRACE capture, same `--rerun-tasks` shape): **3 fail / 5 sweeps**
|
||
(all `late_join_listener_still_decodes_tail`).
|
||
|
||
Post-merge sample relay trace for the previously-failing scenario
|
||
shows the speaker now responding to the upstream SUBSCRIBE in
|
||
~1.5 ms:
|
||
|
||
```
|
||
20:14:17.460567 conn{id=0} subscribe started catalog.json
|
||
20:14:17.460585 conn{id=0} encoding self=Subscribe …catalog.json
|
||
20:14:17.462141 conn{id=0} decoded result=SubscribeOk ← 1.6 ms RTT
|
||
20:14:17.462446 conn{id=0} decoded result=Group seq=0
|
||
```
|
||
|
||
vs the pre-merge failing trace where the same span had 2.94 s of
|
||
silence followed by Ended.
|
||
|
||
Likely actors among the merged `:quic` commits:
|
||
|
||
- `b622d0c9 feat(quic): RFC 9001 §6 1-RTT key update` — adds
|
||
`peekKeyPhase` + key-rotation tracking in
|
||
`QuicConnectionParser`. Pre-fix, every short-header packet whose
|
||
KEY_PHASE bit didn't match `currentReceiveKeyPhase` was silently
|
||
AEAD-failed and dropped. While quinn doesn't initiate key updates
|
||
by default, the parser path also touched the short-header
|
||
decoding side, plausibly fixing an adjacent off-by-one in
|
||
short-payload header protection (new test
|
||
`ShortPayloadHeaderProtectionTest.kt` lands alongside).
|
||
- `d5c854be fix(quic): PTO retransmits handshake CRYPTO + STREAM`
|
||
— fixes our outbound PTO when the peer never ACKs anything.
|
||
Outbound-only fix, less likely to affect the inbound bidi-data
|
||
parsing side.
|
||
- `2a4c07ae fix(quic): thread offered ALPN list through TlsClient
|
||
→ ClientHello` — affects handshake; speaker connection had
|
||
already established before the failing bidi arrived, so unlikely
|
||
to be the actor.
|
||
|
||
The empirical evidence is what counts: **5/5 sweep BUILD
|
||
SUCCESSFUL post-merge.** Bisecting WHICH of the 5 commits closes
|
||
it can be done if needed for the post-mortem; not necessary to
|
||
proceed with the closure roadmap.
|
||
|
||
## Corrected diagnosis (2026-05-07, post-trace)
|
||
|
||
5× sweep on `claude/t16-nestsclient-closure-1zBIc` (rustc 1.95,
|
||
moq-relay 0.10.25, `-DnestsHangInteropTraceRelay=true`) →
|
||
**3 failures / 5 sweeps**, all in
|
||
`late_join_listener_still_decodes_tail`. Sweeps 1, 2, 3 failed;
|
||
sweeps 4, 5 passed.
|
||
|
||
For one of the failing runs (sweep 1, broadcast suffix
|
||
`6d60532f…`), the relay's full trace + the speaker-side
|
||
`Log.d("NestTx")` lines in JUnit `<system-err>` confirm:
|
||
|
||
```
|
||
relay log (conn{id=0} = relay↔speaker, conn{id=1} = relay↔listener)
|
||
─────────────────────────────────────────────────────────────────
|
||
18:34:52.085 conn{id=0} session accepted (speaker connects)
|
||
18:34:52.085 conn{id=0} encoding AnnounceInterest (relay → speaker bidi #1)
|
||
18:34:52.092 conn{id=0} decoded Active suffix=6d60… (speaker replied to AI)
|
||
18:34:54.151 conn{id=1} session accepted (listener connects, T+2.07 s)
|
||
18:34:54.152 conn{id=1} decoded Subscribe id=0 catalog.json
|
||
18:34:54.152 conn{id=1} subscribed started …catalog.json
|
||
18:34:54.152 conn{id=0} subscribe started id=0 …catalog.json ← upstream
|
||
18:34:54.152 conn{id=0} encoding Subscribe …catalog.json ← bidi #2
|
||
18:34:57.095 conn{id=0} decoded Ended suffix=6d60… ← 2.94 s of silence
|
||
then speaker tears down
|
||
18:34:57.095 conn{id=1} subscribed cancelled id=0
|
||
18:34:57.096 conn{id=0} subscribe cancelled id=0
|
||
|
||
speaker NestTx log (matching window)
|
||
─────────────────────────────────────────────────────────────────
|
||
18:34:52.092 ANNOUNCE inbound prefix='' → emitted Active suffix='6d60…'
|
||
18:34:52.111 send returning false — no inboundSubs (count=1)
|
||
18:34:53.111 send returning false — no inboundSubs (count=51)
|
||
18:34:54.111 send returning false — no inboundSubs (count=101)
|
||
18:34:55.111 send returning false — no inboundSubs (count=151)
|
||
18:34:56.111 send returning false — no inboundSubs (count=201)
|
||
18:34:57.092 send returning false — no inboundSubs (count=250)
|
||
↑ NO `SUBSCRIBE inbound` LOG.
|
||
```
|
||
|
||
The relay opens **bidi #2** (peer-initiated bidi from relay TO
|
||
speaker) at 18:34:54.152 and writes a complete `Subscribe { id:0,
|
||
track:"catalog.json" }` message to it. The wire send succeeds (no
|
||
relay-side error). The speaker's `MoqLiteSession.handleInboundBidi`
|
||
never logs `SUBSCRIBE inbound id=0 broadcast=…6d60…` — meaning the
|
||
bidi never reaches the moq-lite session's bidi pump's
|
||
`launch { handleInboundBidi(bidi) }` body. It is silently lost
|
||
between the speaker's QUIC stack and the application layer.
|
||
|
||
The same speaker connection HAS handled bidi #1 (the relay's
|
||
AnnounceInterest at 18:34:52.085) correctly — see the
|
||
`ANNOUNCE inbound prefix=''` log at 18:34:52.092. So the speaker's
|
||
`pumpInboundBidis` is NOT permanently dead; it stops surfacing
|
||
peer-opened bidis sometime between T=0 and T+2 s, intermittently.
|
||
|
||
For comparison, sweep 4's identical scenario (which passed) shows
|
||
the relay's bidi #2 → speaker SubscribeOk round-trip in ~1.94 ms:
|
||
|
||
```
|
||
18:42:44.954530 conn{id=0} encoding Subscribe …catalog.json
|
||
18:42:44.956465 conn{id=0} decoded SubscribeOk
|
||
```
|
||
|
||
So the speaker CAN handle the late-join SUBSCRIBE bidi. It just
|
||
sometimes loses it. The 60 % flake rate matches what the prior
|
||
investigation observed.
|
||
|
||
## Why the prior investigation pointed at moq-relay
|
||
|
||
The prior plan's "smoking gun" trace observed
|
||
`ANNOUNCE inbound … emitted Active suffix='<x>'` followed by
|
||
**no** further `SUBSCRIBE inbound` for the failing broadcast on
|
||
the speaker side, and concluded the relay must have failed to
|
||
forward the SUBSCRIBE upstream. That conclusion was correct given
|
||
only the speaker-side trace; what we now have — the relay-side
|
||
trace from Step 1 capture — shows the relay DID forward, so the
|
||
gap is between the wire and the speaker's app code.
|
||
|
||
The route is therefore not `Origin::announced()` →
|
||
`broadcast.subscribe_track(...)` (relay-side) but
|
||
`QUIC bidi acceptance` → `WtPeerStreamDemux.readyStreams` →
|
||
`QuicWebTransportSession.incomingBidiStreams()` →
|
||
`MoqLiteSession.pumpInboundBidis` → `handleInboundBidi`
|
||
(speaker-side). One link in that chain drops the second bidi about
|
||
40-60 % of the time.
|
||
|
||
## What to investigate next (out of scope here)
|
||
|
||
The next agent picking this up should look at:
|
||
|
||
1. **`:quic` module's `WtPeerStreamDemux`** — the
|
||
`readyStreams = Channel<StrippedWtStream>(Channel.UNLIMITED)`
|
||
and its `consumeAsFlow()` consumer. `consumeAsFlow` is
|
||
single-collector; we already verified only `pumpInboundBidis`
|
||
collects on the speaker side (no `pumpUniStreams` runs on a
|
||
pure publisher), so the single-consumer constraint isn't
|
||
violated, but a peer-bidi that wins the "is this the WT bidi
|
||
prefix or a control stream" classification race might be
|
||
misrouted to a different sink.
|
||
2. **WT_BIDI_STREAM prefix stripping under flow control pressure.**
|
||
`emitStripped` (`WtPeerStreamDemux.kt:292-327`) fires
|
||
`readyStreams.trySend(...)`. The path that PREBUFFERS bytes
|
||
between connection acceptance and prefix recognition is the
|
||
most likely place a long-tail bidi gets lost — there's an
|
||
`ArrayDeque<ByteArray> pending` per stream that gets flushed
|
||
into the data Flow only after the prefix is identified.
|
||
3. **Concurrent uni-stream openings during the warmup window.**
|
||
The audio publisher's `send()` returns false fast when
|
||
`inboundSubs.isEmpty()` (no uni stream opened), so the speaker
|
||
shouldn't be opening 50 fps of uni streams pre-listener. But
|
||
the audio publisher DOES eventually call
|
||
`endGroup()` on a per-group cadence (every 100 ms at
|
||
framesPerGroup=5/50fps); confirm `endGroup()` is a no-op when
|
||
there's no current group. The trace shows it firing 50 times
|
||
between T=0 and T+5 s.
|
||
|
||
This rules out **any** test-side mitigation that changes the
|
||
moq-relay version, the speaker warmup duration, or the
|
||
listener-side subscribe shape — the fault is below moq-lite, in
|
||
the QUIC stack's bidi accept path.
|
||
|
||
## Implications for the closure roadmap
|
||
|
||
- **Priority 1 of the closure roadmap is misnamed.** It's not
|
||
a moq-relay routing race; it's a `:quic` peer-bidi
|
||
surfacing race. The CI gating (Priority 3) still can't be
|
||
re-enabled until this is fixed, but the fix is in `:quic`,
|
||
not in test code or moq-rs.
|
||
- **Priority 2 (tighten cross-stack assertions) is still
|
||
blocked** by the same flake — replacing soft-passes with hard
|
||
floors makes 60 % of sweeps red, same as today.
|
||
- **Step 4 of THIS plan (bump moq-relay version) is moot.**
|
||
The bug isn't in moq-relay 0.10.x; it's in our QUIC stack's
|
||
bidi accept under a 2 s warmup. Bumping moq-relay would not
|
||
change this. (Also confirmed: 0.10.25 IS the latest crates.io
|
||
release; main HEAD `bdda6bd1` does not modify
|
||
`recv_subscribe`'s synchronous lookup either.)
|
||
|
||
## Trace artefact locations
|
||
|
||
- Per-test relay trace logs:
|
||
`nestsClient/build/relay-logs-sweep-{1..5}/<methodName>-<seq>-<ts>.log`
|
||
(kept on the branch for the next pickup; small enough to commit
|
||
if needed).
|
||
- Per-test JUnit XML with speaker `<system-err>`:
|
||
`nestsClient/build/sweep-logs/results-{1..5}/`.
|
||
- Per-sweep gradle log (build + first 50 lines of test output):
|
||
`nestsClient/build/sweep-logs/sweep-{1..5}.log`.
|
||
- Cross-reference helper:
|
||
`nestsClient/build/sweep-logs/analyze-sweep.sh` (matches by
|
||
test method name).
|
||
|
||
## Progress log (2026-05-07)
|
||
|
||
- Step 1 instrumentation landed. `NativeMoqRelayHarness` now accepts an
|
||
optional `testTag` and writes the relay subprocess's combined
|
||
stdout/stderr to
|
||
`nestsClient/build/relay-logs/<methodName>-<seq>-<ts>.log` whenever
|
||
`-DnestsHangInteropTraceRelay=true` is set. The subprocess runs with
|
||
`RUST_LOG=info,moq_relay=trace,moq_lite=trace,moq_native=debug` so
|
||
the per-broadcast subscribe-routing path is observable; quinn /
|
||
rustls / h3 stay at info to keep the file < ~10 MB per scenario.
|
||
`HangInteropTest` and `BrowserInteropTest` now expose a JUnit 4
|
||
`TestName` rule and pass the method name into `resetShared` so each
|
||
scenario's per-method log is easy to locate by name.
|
||
- Step 4 ruled out — `cargo info moq-relay` confirms `0.10.25` is the
|
||
current `crates.io` release; no newer minor exists. The plan's
|
||
Step 4 path (next minor on crates.io) does not apply. The fallback
|
||
is a `cargo install --git https://github.com/moq-dev/moq.git --rev
|
||
<main-head>` against `bdda6bd19a37ccdf7f7b66f3d760d8892ea8db59`
|
||
(main HEAD as of investigation) — moq-relay-v0.10.25 tag matches
|
||
the published crate, so post-0.10.25 work lives only on `main`.
|
||
Also note the upstream moved from `kixelated/moq` to `moq-dev/moq`;
|
||
REV's `KIXELATED_MOQ_GIT_REV` predates the move.
|
||
|
||
### Source-level analysis (moq-rs 0.10.25 + main HEAD)
|
||
|
||
Working through `moq-relay/src/connection.rs`, `moq-lite/src/lite/publisher.rs`,
|
||
`moq-relay/src/cluster.rs` and `moq-lite/src/model/{origin,broadcast}.rs`
|
||
the routing path is:
|
||
|
||
1. Speaker connects → relay's `subscriber.start_announce` runs
|
||
(`moq-lite/src/lite/subscriber.rs:198-227`). It creates the
|
||
`BroadcastDynamic` with `dynamic = 1` BEFORE calling
|
||
`cluster.publisher.publish_broadcast(...)`. publish_broadcast
|
||
pushes to the `primary` origin.
|
||
2. `cluster.run_combined()` (`moq-relay/src/cluster.rs:199-215`) is
|
||
a tokio shovel that loops on `primary.announced()` /
|
||
`secondary.announced()` and calls `combined.publish_broadcast(...)`.
|
||
This is the only place primary→combined gets fanned in, and
|
||
`tokio::select!` doesn't run in the same task as start_announce,
|
||
so there's a scheduling gap between primary publish and combined
|
||
publish.
|
||
3. Listener connects → relay's `publisher.run_announces` reads from
|
||
`combined.consume_only(...)` and forwards announces over the wire.
|
||
4. Listener subscribes → relay's `publisher.recv_subscribe`
|
||
(`moq-lite/src/lite/publisher.rs:217-250`) runs
|
||
`self.origin.consume_broadcast(&subscribe.broadcast)`
|
||
**synchronously** against combined. If the broadcast is in
|
||
combined's tree, returns Some; otherwise None → `Error::NotFound`
|
||
(wire code 13).
|
||
|
||
Even on main HEAD `bdda6bd1` the `consume_broadcast` lookup is
|
||
synchronous (`moq-lite/src/lite/publisher.rs:243-250`). Commit
|
||
`8d4a175` only renamed it to `get_broadcast` — same semantics.
|
||
Commit `bea9b3a` introduced `OriginConsumer::wait_for_broadcast`
|
||
as an async alternative AND added a TODO at
|
||
`moq-relay/src/web.rs:325`: "switch to `announced_broadcast`
|
||
(bounded by the fetch deadline) so freshly-connected subscribers
|
||
don't get a spurious 404 before the broadcast has gossiped." That
|
||
is upstream's own acknowledgement that the relay's subscribe path
|
||
inherits the gossip race, but the fix has not been applied to
|
||
`recv_subscribe` (the path this investigation cares about).
|
||
|
||
### Failure-mode hypotheses (post-source-read)
|
||
|
||
- **H1 (gossip race):** still the leading candidate, but with a
|
||
more specific mechanism. The Speaker→Relay primary publish and
|
||
the Relay→Listener combined publish are in different async
|
||
tasks; `consume_broadcast` is synchronous. The listener receives
|
||
the wire ANNOUNCE only AFTER `combined.publish_broadcast(...)`,
|
||
so by the time the listener-issued SUBSCRIBE arrives at the
|
||
relay's `recv_subscribe`, combined SHOULD contain the broadcast.
|
||
But the smoking-gun trace shows the speaker-side never logs the
|
||
upstream SUBSCRIBE for the failing path — i.e. either (a) the
|
||
listener-side ANNOUNCE→SUBSCRIBE wire ordering is being broken
|
||
by something between the relay's combined update and the wire
|
||
emit, or (b) `consume_broadcast` returns None despite combined
|
||
knowing about the broadcast. The trace from Step 1 should
|
||
disambiguate.
|
||
|
||
- **H1b (`subscribe_track` Cancel due to `dynamic == 0`):**
|
||
`BroadcastConsumer::subscribe_track` returns `Error::NotFound`
|
||
(mapped to wire code 13) if the underlying state's
|
||
`dynamic == 0` (`moq-lite/src/model/broadcast.rs:300-302`).
|
||
start_announce increments `dynamic` BEFORE publish_broadcast,
|
||
so the combined consumer's clone-of-clone-of-broadcast SHOULD
|
||
always observe `dynamic >= 1`. But it relies on `BroadcastConsumer`
|
||
/ `BroadcastProducer` sharing the same `state: conducer::Producer`
|
||
cell; if the broadcast got `Clone`d through combined's
|
||
`publish_broadcast`'s `broadcast.clone()` call into a position
|
||
where the state is shared, dynamic stays correct. (Confirmed —
|
||
`BroadcastConsumer::Clone` shares state.) So this isn't the
|
||
cause.
|
||
|
||
- **H1c (run_combined backlog):** the cluster's run_combined loop
|
||
is a SINGLE-CONSUMER pump from primary.announced(); if the loop
|
||
is parked on a slow combined publish (rare; publish_broadcast is
|
||
effectively a tree insert), a follow-up announce sits in the
|
||
primary queue. But the listener doesn't observe the announce
|
||
via combined until the pump runs — so this doesn't cause a
|
||
spurious subscribe-without-announce. It only delays the
|
||
listener's announce notification.
|
||
|
||
The trace from Step 1 is needed to pick between H1, H1c, and a
|
||
bug we haven't surfaced yet. **Step 4 will not yield a fix** —
|
||
verified by reading post-0.10.25 commits on main; no fix to
|
||
`recv_subscribe`'s synchronous lookup has landed. The most
|
||
viable upstream fix would be to switch `recv_subscribe` to
|
||
`origin.wait_for_broadcast(path).await` with a bounded deadline.
|
||
|
||
**Owns:** the residual flake that affects four T16 scenarios:
|
||
`late_join_listener_still_decodes_tail`,
|
||
`packet_loss_1pct_does_not_kill_audio`,
|
||
`long_broadcast_60s_tone_round_trips`, and the new
|
||
`chromium_publisher_*_kotlin_listener_recovers` tests in browser-tier.
|
||
|
||
**Blocks:** CI gating for `:nestsClient:jvmTest -DnestsHangInterop=true`
|
||
and `-DnestsBrowserInterop=true`. Re-evaluate the
|
||
`hang-interop` / `browser-interop` workflow jobs once this is closed.
|
||
|
||
**Cross-refs:**
|
||
- `nestsClient/plans/2026-05-07-late-join-catalog-flake-investigation.md`
|
||
(smoking-gun trace + 4 mitigation attempts, 2 of which were
|
||
net-negative and reverted).
|
||
- `nestsClient/plans/2026-05-07-i7-post-reconnect-cliff-investigation.md`
|
||
(same kind of routing issue surfacing across publisher cycles).
|
||
|
||
## What we know
|
||
|
||
For broadcasts that fail (sample suffixes from the trace:
|
||
`10d4b6f2…`, `c75e2648…`, `f1be27ef…`):
|
||
|
||
1. The Kotlin speaker side logs:
|
||
- `ANNOUNCE inbound prefix='' → emitted Active suffix='<broadcast>'`
|
||
- …then NOTHING for the entire test window.
|
||
- Audio publisher's `send()` repeats `no inboundSubs` at 50 fps
|
||
until the test times out.
|
||
|
||
2. The Rust hang-listen side logs:
|
||
- `connected, version=moq-lite-03`
|
||
- `broadcast announced path=<broadcast>`
|
||
- `subscribe started id=0 broadcast=<broadcast> track=catalog.json`
|
||
- …then `subscribe error err=remote error: code=0` exactly when
|
||
the speaker tears down at the broadcast-window end (= relay
|
||
forwarding `Cancel`).
|
||
|
||
The relay accepts the listener's wire SUBSCRIBE on its downstream
|
||
connection but **never opens an upstream SUBSCRIBE bidi to the
|
||
speaker** for the failing broadcast. The upstream subscribe-pump
|
||
that's supposed to forward downstream subscribes to the speaker
|
||
isn't wired up by the time the listener subscribes.
|
||
|
||
For broadcasts that succeed (same trace, same JVM, different test):
|
||
|
||
```
|
||
ANNOUNCE inbound prefix='' → emitted Active suffix=<broadcast>
|
||
SUBSCRIBE inbound id=0 broadcast=<broadcast> track='catalog.json'
|
||
SUBSCRIBE registered id=0 …
|
||
openGroupStream subId=0 seq=0
|
||
…
|
||
```
|
||
|
||
All log lines fire; the relay forwards the upstream subscribe
|
||
within ~1 ms of the downstream subscribe. Failure mode is binary:
|
||
the relay does or does not forward.
|
||
|
||
## Hypotheses, ranked by next step
|
||
|
||
### H1 — moq-rs 0.10.x bug in `Origin::announced()` → upstream-pump setup race
|
||
|
||
`Origin::announced().await` returns the broadcast as soon as the
|
||
speaker's announce lands in the relay's origin map. The relay's
|
||
upstream-subscribe pump for that broadcast is set up on a separate
|
||
async path. If a downstream listener subscribes before the pump is
|
||
fully wired, the SUBSCRIBE accepts on the listener's wire (the
|
||
relay has the broadcast in its origin) but never propagates
|
||
upstream.
|
||
|
||
**Status:** prime suspect; see "smoking gun" in
|
||
`2026-05-07-late-join-catalog-flake-investigation.md`.
|
||
|
||
### H2 — interaction with the `--auth-public ""` minimal config
|
||
|
||
The harness boots moq-relay with `--auth-public ""` to skip JWT
|
||
issuance. Production runs with full auth. It's possible the
|
||
auth-public path takes a different code path through the relay's
|
||
origin/subscribe wiring that's racier than the auth'd path.
|
||
|
||
**Status:** plausible; would explain why the flake isn't reported
|
||
against the production deployment.
|
||
|
||
### H3 — local-only timing race that resolves at higher latency
|
||
|
||
Loopback (127.0.0.1) has near-zero RTT. The relay's internal
|
||
async setup may rely on the natural RTT cushion of a real network
|
||
to sequence upstream-subscribe-pump setup vs. downstream-subscribe
|
||
acceptance. We bypass that cushion in the test.
|
||
|
||
**Status:** less likely (the cliff plan's evidence shows lossy
|
||
network actually makes things *worse* via the `serve_group` task
|
||
pool) but worth ruling out.
|
||
|
||
## Investigation plan
|
||
|
||
### Step 1 — capture relay-side traces
|
||
|
||
`NativeMoqRelayHarness.boot` currently launches `moq-relay` with
|
||
`RUST_LOG=info`. Bump to `RUST_LOG=moq_relay=trace,moq_lite=trace`
|
||
and capture stderr to a per-test tempfile. Cross-reference with
|
||
the failing test's hang-listen stdout AND the speaker-side
|
||
`Log.d("NestTx")` traces (already captured in
|
||
`<system-err>` per JUnit XML).
|
||
|
||
Concretely: in `NativeMoqRelayHarness.kt` add a `--log-stderr`
|
||
option that the @BeforeTest hook sets to a `<test-method>.log`
|
||
path under `nestsClient/build/relay-logs/`. The Kotlin side
|
||
already has the speaker-side traces; the Rust side is the gap.
|
||
|
||
What to look for in the failed-broadcast log:
|
||
- Was a SUBSCRIBE bidi opened to the speaker for the failing
|
||
broadcast suffix? (moq_lite span: `subscribe`).
|
||
- Did the relay's `Origin::publish_broadcast` call complete
|
||
before the listener's SUBSCRIBE arrived?
|
||
- Any `track.unused()` resolves on the publisher-side track that
|
||
would explain immediate cancellation?
|
||
|
||
### Step 2 — write a minimal reproducer
|
||
|
||
If Step 1 shows the bug is independent of our test framework,
|
||
extract a minimum reproducer:
|
||
|
||
```rust
|
||
// reproducer.rs
|
||
let mut cmd = std::process::Command::new("moq-relay")
|
||
.args(&["--server-bind", "127.0.0.1:0", "--auth-public", "",
|
||
"--tls-generate", "localhost"])
|
||
.spawn()?;
|
||
// Run a moq-lite SPEAKER on one client, a moq-lite LISTENER on
|
||
// another, both pointed at the relay. Listener subscribes immediately
|
||
// after the speaker announces. Repeat 100×; count how many succeed.
|
||
```
|
||
|
||
Then strip the SPEAKER's announce timing, the LISTENER's subscribe
|
||
timing, the relay's `--auth-public` flag — bisect to the smallest
|
||
form that still reproduces.
|
||
|
||
### Step 3 — file upstream
|
||
|
||
If Step 1 / 2 confirm a moq-rs bug, file a `kixelated/moq` issue
|
||
with:
|
||
- The reproducer.
|
||
- Smoking-gun trace pair from our test harness.
|
||
- Pin to moq-rs version `0.10.25` (per `nestsClient/tests/hang-interop/REV`).
|
||
- Cross-link to existing
|
||
`2026-05-01-quic-stream-cliff-investigation.md`'s open follow-up
|
||
#1 (the per-subscriber forward-queue cliff is a sister bug).
|
||
|
||
### Step 4 — try newer moq-relay version
|
||
|
||
Bump `MOQ_RELAY_VERSION` in `nestsClient/tests/hang-interop/REV`
|
||
and `nestsClient/build.gradle.kts` to the next minor release on
|
||
crates.io (whatever's current at the time of pickup). Run the 5×
|
||
sweep. If the flake disappears, the upstream may have already
|
||
fixed it; we can pin past 0.10.x.
|
||
|
||
**Risk:** newer moq-relay versions may have wire-format changes
|
||
that break our current `moq-lite-03` ALPN pin. The browser
|
||
harness's `@moq/lite` 0.2.x client offers `moq-lite-04` AND
|
||
`moq-lite-03`, so a newer relay that drops `03` would still
|
||
negotiate fine via 04.
|
||
|
||
## Acceptance criteria
|
||
|
||
- Sweep `for i in 1 2 3 4 5; do ./gradlew :nestsClient:jvmTest
|
||
--tests HangInteropTest -DnestsHangInterop=true --rerun-tasks; done`
|
||
passes 5/5.
|
||
- Browser-tier sweep similarly stable.
|
||
- Either:
|
||
(a) Upstream issue filed with reproducer (if the bug is in
|
||
moq-rs and we can't fix it locally), OR
|
||
(b) Local fix applied (e.g. version bump + REV update +
|
||
Cargo.lock regenerate).
|
||
|
||
## Out of scope
|
||
|
||
- The `:quic` module's `MAX_STREAMS_UNI` extension fix
|
||
(`d391ae1d`) — already shipped, separate concern.
|
||
- The production-side `framesPerGroup` reconciliation
|
||
(`2026-05-07-framespergroup-production-rerun.md`) — independent.
|