amethyst/nestsClient/plans/2026-05-07-late-join-catalog-flake-investigation.md

late_join_listener_still_decodes_tail catalog-cancelled flake investigation

Status: ✅ closed by merging origin/main (5 :quic commits, see 2026-05-07-moq-relay-routing-investigation.md § Closure). 5/5 sweep BUILD SUCCESSFUL, 55/55 tests pass post-merge. Pre-merge baseline on the same branch: 3 fail / 5 sweeps, all here.

2026-05-07 update: relay-side hypothesis disproven

The "smoking gun" trace below (speaker logs an ANNOUNCE inbound but no SUBSCRIBE inbound for the failing broadcast) was correct as a description of the symptom but wrong about the cause. With the relay-side trace now captured (Step 1 of the routing-investigation plan), we can see:

• The relay DID receive the listener's wire SUBSCRIBE (subscribed started on conn{id=1}).
• The relay DID open a peer-initiated bidi to the speaker and encode Subscribe { id:0, track:"catalog.json" } onto it (subscribe started, encoding self=Subscribe on conn{id=0}).
• The speaker NEVER logs SUBSCRIBE inbound id=0 — the bidi doesn't reach MoqLiteSession.handleInboundBidi.

The same speaker connection HAS handled an earlier peer-bidi (the relay's AnnounceInterest at T=0) correctly. So the failure isn't a permanent dead pump; it's a per-bidi loss that affects bidi #2 some 40-60 % of the time when bidi #2 arrives ~2 s after bidi #1.

Pivot: action moved from "investigate moq-relay" to "investigate :quic peer-bidi surfacing under delayed arrival" in the routing-investigation plan, which reframes the closure-roadmap Priority 1 actor accordingly.

The flake also affects four browser-tier scenarios after the Browser I7 work landed: chromium_listener_late_join_still_decodes_tail, chromium_publisher_baseline_kotlin_listener_decodes, chromium_publisher_reconnect_kotlin_listener_recovers, and intermittently chromium_listener_long_broadcast_60s_tone_440. Browser scenarios soft-pass listener-side assertions on 0-frame outcomes; hard floors planned in 2026-05-07-tighten-cross-stack-assertions.md.

HangInteropTest.late_join_listener_still_decodes_tail, packet_loss_1pct_does_not_kill_audio, long_broadcast_60s_tone_round_trips, and amethyst_speaker_to_hang_listener_stereo_440_660 intermittently fail with hang-listen exiting non-zero on a subscribe error during catalog read. Pre-fix flake rate: 5/5 fail in a sweep. After three layered mitigations: ~2-3/5 fail. The remaining flake is in moq-relay 0.10.x's per-broadcast announce → subscribe-pump setup race; the test-side mitigations have hit diminishing returns.

Pre-fix root cause: moq-rs cancel cascade

The previous hang-listen catalog-read shape:

for attempt in 0..3 {
    let catalog_track = broadcast.subscribe_track(...)?;
    let mut catalog = hang::CatalogConsumer::new(catalog_track);
    match tokio::time::timeout(Duration::from_secs(2), catalog.next()).await { ... }
    // catalog_track + catalog drop at iteration boundary
}

is broken on moq-rs 0.10.x. The flow:

1. Attempt 0: subscribe_track creates a TrackConsumer. Wire subscribe id=0 fires.
2. Speaker's setOnNewSubscriber hook is supposed to write the catalog via send(catalogJson) + endGroup(). For some reason this doesn't deliver in time — see "residual root cause" below.
3. 2 s timeout fires. Loop iteration ends. catalog_track drops.
4. moq-rs sees track.unused() resolve (no consumers left), aborts the wire subscribe with Error::Cancel.
5. Error::Cancel maps to wire stream-reset code 0 per moq-lite/src/error.rs:96-105.
6. Attempt 1: subscribe_track(catalog.json) returns a consumer whose internal state is already in the just-cancelled state. .next() resolves immediately with cancelled.
7. Attempt 2+: subscribe_track itself returns Err(cancelled).
8. Loop bails; Error: subscribe catalog. cancelled.

Fix (commit 8cc7cbd42): hold ONE subscription open for the full 10 s budget; inner timeouts on .next() poll for the first group; outer timeout caps the total wait. Code is in hang-interop/hang-listen/src/main.rs.

This eliminates the cancel-cascade failure mode. 2 of 5 sweep runs post-fix go all-green; 3 hit the residual described next.

Residual root cause (unidentified)

Same test, post-fix, fresh repro from sweep run 4:

12:35:45.333625  subscribe started id=0 catalog.json
                 (no further logs from hang-listen for 2.94 s)
12:35:48.267341  subscribe error id=0 err=remote error: code=0
                 Error: catalog read | moq lite error: cancelled

The single, long-lived subscribe is cancelled by the peer (relay or speaker) ~3 s after start. Wallclock alignment:

• Speaker started broadcasting at T=0
• delay(listenerLateJoinDelayMs = 2_000) → T=2 s
• hang-listen connects + subscribes → T=2.05 s
• Speaker's broadcast window ends at T=5 s (helper does delay(speakerSeconds * 1_000 - listenerLateJoinDelayMs) = delay(3_000) AFTER hang-listen starts)
• Listener-observed cancel at speaker-T+~5 s = ~3 s after subscribe

So the cancel coincides with the speaker tearing down. The catalog data never arrived during the 3 s subscribe window, despite the speaker presumably having the hook installed AND the inbound SUBSCRIBE arriving normally.

Ruled out

• Hook installation race. MoqLiteNestsSpeaker.setOnNewSubscriber is called BEFORE the speaker transitions to Broadcasting state (MoqLiteNestsSpeaker.kt:176-182). Listener subscribes 2 s later — hook is definitively installed.
• Stale inboundSubs. @BeforeTest calls resetShared() which restarts the moq-relay subprocess. Speaker session is fresh per test (new pumpScope + fresh MoqLiteSession). No cross-test state leak.
• Hook captured-but-null. registerInboundSubscription reads onNewSubscriberHook inside the gate AFTER the sub is added. By T=2 s the hook is non-null.
• inboundSubs.isEmpty() race in send(). Hook is launched AFTER inboundSubs += sub inside the same gate. The hook's send() re-acquires the gate; sees inboundSubs non-empty.
• MAX_STREAMS_UNI exhaustion at speaker. Catalog uni stream is one stream per subscriber; cap is 10000.
• Idle timeout. Quinn's default (per moq-native) is 30 s, not 3.
• Audio publisher's onTerminalFailure firing. Only triggered by MAX_CONSECUTIVE_SEND_ERRORS thrown errors, not the no-subscribers return false path that the audio publisher takes during the 2 s warmup.

Plausible remaining hypotheses

1. Relay-side per-track state race. The relay's downstream subscriber (forwarding to hang-listen) is created when hang-listen's SUBSCRIBE arrives. The relay's upstream subscriber (subscribed-on-speaker) might be created on-demand and might race with the speaker's hook firing. If the relay's upstream consumer isn't fully alive by the time the speaker's uni stream arrives at the relay, the relay drops the uni without forwarding.
2. Catalog uni stream priority/scheduling. The audio publisher (running silent — inboundSubs.isEmpty() → return false) could somehow contend with the catalog publisher's uni-stream open via the shared transport.openUniStream(), even though they're separate publishers with separate gates. Less likely.
3. moq-rs CLIENT-side subscribe_track returning a stale consumer. Even on the first call, if the broadcast's track- producer pool has ANY residual entry from an earlier test (despite resetShared()), the consumer might be born already-cancelled. The 2/5 pass rate suggests there's a timing component.
4. Track.unused() racing with the long subscribe. The hang crate's CatalogConsumer::new(track) may temporarily drop an internal handle, causing a brief unused() flicker that aborts the upstream subscription before the speaker's data arrives.

What would confirm a hypothesis

1. Speaker-side log instrumentation. Add Log.d("NestTx") { "catalog hook fired for subId=$id" } inside the setOnNewSubscriber lambda; "catalog send returned $result for subId=$id" after each send(); "catalog endGroup completed for subId=$id". Run the failing test under --info Gradle output to see if the hook fires + writes succeed on the SPEAKER side. If yes → the data is being written but the listener isn't receiving it (relay-side issue).
2. Relay-side log instrumentation. Boot moq-relay with RUST_LOG=moq_relay=debug,moq_lite=debug and capture per-test stderr to a file. Look for "subscribe started" / "serving group" / "subscribe cancelled" timing on the relay side. Cross-reference with hang-listen's view.
3. Listener-side QUIC-level capture. Wrap hang-listen's UDP socket via udp-loss-shim modified to packet-log instead of drop. See exactly which streams open + close.

Mitigations attempted (in order)

1. Per-method resetShared() (706ccda67) — kills the relay subprocess between test methods. Closes a moq-rs accumulated- state class but the catalog-cancel pattern persists.
2. hang-listen single long-lived subscribe (8cc7cbd42) — replaces the create-drop-recreate retry shape with one subscribe held for the full 10 s read budget. Eliminates the moq-rs Error::Cancel cascade. 5/5 fail → ~2-3/5 pass.
3. Speaker warmup bump 150 ms → 600 ms (00f6cba31) — gave the relay more time to register the speaker's broadcast in its origin before the listener subscribed. NET NEGATIVE, reverted in 1ddf4967c — same failure pattern AND ate into the listener's catalog-read window (5 s broadcast minus 600 ms warmup leaves ~4.4 s instead of 4.85 s).
4. hang-listen 250 ms post-origin.announced() sleep (207057374) — gave the relay time to fully prime its per-broadcast upstream-subscribe pump. NET NEGATIVE, reverted in 9b8b5692b — combined with #3 produced 0/5 sweep pass (worse than single-subscribe-fix-alone's 2/5) because the cumulative ~850 ms of pre-subscribe delay shrank the catalog-read window into the speaker tear-down region.

Lesson: the failure window for the broken-routing case is ~3 seconds (until the speaker tears down at end of broadcast). ANY pre-subscribe delay shrinks the available retry budget on the listener side. Mitigations should NOT add delays.

Smoking gun (from speaker stderr trace)

For broadcasts that fail (10d4b6f2…, c75e2648…, f1be27ef…), the speaker-side Log.d("NestTx") trace shows ONE event for the broadcast suffix:

12:53:32.293 ANNOUNCE inbound prefix='' → emitted Active suffix='f1be27ef…'

…and then NOTHING for the entire 10 s catalog-read window. No SUBSCRIBE inbound, no openGroupStream. The audio publisher keeps logging send returning false — no inboundSubs at 50 fps until hang-listen times out. Meanwhile hang-listen's moq-rs client is logging subscribe started id=0 catalog.json and waiting.

Interpretation: the relay accepts the listener's wire SUBSCRIBE on the downstream connection, BUT does not open an upstream SUBSCRIBE bidi to the speaker. The two sides are disconnected; nothing the test code can fix from above.

For broadcasts that succeed (688e130b…, 6e577e5f…), the same trace shows:

12:58:10.334  ANNOUNCE inbound prefix='' → emitted Active suffix='6e577e5f…'
12:58:11.246  SUBSCRIBE inbound id=0 broadcast='6e577e5f…' track='catalog.json'
12:58:11.246  SUBSCRIBE registered id=0 …
12:58:11.247  openGroupStream subId=0 seq=0
…

The relay successfully forwards the upstream SUBSCRIBE. It's a binary "the relay does or does not forward" — there's no partial state.

Conclusion

The flake is moq-relay 0.10.x's relay-side per-broadcast forward-subscribe routing, not anything the test or speaker can mitigate from outside. Some component of the relay's Origin::announced() → broadcast.subscribe_track(...) → upstream subscribe pump is set up asynchronously and intermittently fails to wire up the upstream subscribe.

Possible next steps if this matters more:

1. Boot the relay with RUST_LOG=moq_relay=trace,moq_lite=trace under the test harness (currently RUST_LOG=info); capture per- test relay stderr to a tempfile; check whether the relay logs the upstream subscribe attempt for the failing broadcast suffix.
2. File an upstream issue at kixelated/moq with this reproducer (HangInteropTest 5x sweep, ~40-60% flake under load) citing the smoking-gun trace pair above.
3. Stop pinning to moq-relay 0.10.25 and try the next minor release — maybe the race has been fixed upstream since.

Currently rejected: bumping speakerSeconds to 8 s and changing the test's threshold. That masks a real bug; the failure mode is worth surfacing.

Files referenced

• nestsClient/tests/hang-interop/hang-listen/src/main.rs:160-220 (post-fix catalog read shape)
• nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/MoqLiteNestsSpeaker.kt:170-181 (setOnNewSubscriber hook installation)
• nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/moq/lite/MoqLiteSession.kt:1167-1192 (registerInboundSubscription + hook-launch path)
• nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/native/HangInteropTest.kt:170-180 (late_join_listener_still_decodes_tail scenario)
• Pre/post sweep results: 0/5 → 2/5 over 10 total sweep runs.