From b2a42d9ab28c11a357da5a334588dbacdd97b8cc Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 7 May 2026 18:49:23 +0000 Subject: [PATCH] diag(nests-interop): trace data disproves moq-relay routing-race hypothesis MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Step 1 of `2026-05-07-moq-relay-routing-investigation.md` ran a 5× sweep on `HangInteropTest` with per-test moq-relay trace capture. Failure rate: 3/5, all in `late_join_listener_still_decodes_tail`. Cross-referencing the relay trace (`encoding self=Subscribe …catalog.json` on conn{id=0} at T+2.07 s) with the speaker's `Log.d("NestTx")` lines (only `ANNOUNCE inbound prefix=''` at T=0; NO `SUBSCRIBE inbound id=0` in the failing window) shows the relay correctly forwards the upstream SUBSCRIBE — the bidi just never reaches `MoqLiteSession.handleInboundBidi`. So the prior plan's "moq-relay 0.10.x per-broadcast subscribe-routing race" hypothesis is wrong. Re-scoped Priority 1 of the closure roadmap to point at `:quic`'s peer-bidi surfacing path instead. The actual bug is between QUIC's bidi-accept and `incomingBidiStreams()` flow. Spotless-formatted Kotlin imports. Trace artefacts preserved under `nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/` so the next agent (QUIC owner) doesn't have to re-run the sweep. --- ...7-late-join-catalog-flake-investigation.md | 35 +++- ...6-05-07-moq-relay-routing-investigation.md | 161 +++++++++++++++- .../plans/2026-05-07-t16-closure-roadmap.md | 23 ++- .../README.md | 61 ++++++ .../sweep-1-FAIL-relay-trace.trace.txt | 39 ++++ .../sweep-1-FAIL-speaker-NestTx.trace.txt | 11 ++ .../sweep-4-PASS-relay-trace.trace.txt | 175 ++++++++++++++++++ .../interop/native/BrowserInteropTest.kt | 4 +- .../interop/native/HangInteropTest.kt | 4 +- 9 files changed, 500 insertions(+), 13 deletions(-) create mode 100644 nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/README.md create mode 100644 nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/sweep-1-FAIL-relay-trace.trace.txt create mode 100644 nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/sweep-1-FAIL-speaker-NestTx.trace.txt create mode 100644 nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/sweep-4-PASS-relay-trace.trace.txt diff --git a/nestsClient/plans/2026-05-07-late-join-catalog-flake-investigation.md b/nestsClient/plans/2026-05-07-late-join-catalog-flake-investigation.md index c04414d7a..4818f9ea2 100644 --- a/nestsClient/plans/2026-05-07-late-join-catalog-flake-investigation.md +++ b/nestsClient/plans/2026-05-07-late-join-catalog-flake-investigation.md @@ -2,8 +2,39 @@ **Status: partially fixed (commit `8cc7cbd42` shipped; commits `00f6cba31` + `207057374` reverted as net-negative). Residual -flake is upstream-territory in moq-relay 0.10.x. Action plan -moved to `2026-05-07-moq-relay-routing-investigation.md`.** +flake is NOT in moq-relay 0.10.x — confirmed by Step 1 trace +capture in +`2026-05-07-moq-relay-routing-investigation.md`. The relay +correctly forwards the upstream SUBSCRIBE; the speaker-side QUIC +stack silently drops the relay's peer-initiated bidi opened +~2 s after the speaker connects. The fix lives in the `:quic` +module's `WtPeerStreamDemux` / bidi-surfacing path.** + +## 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: diff --git a/nestsClient/plans/2026-05-07-moq-relay-routing-investigation.md b/nestsClient/plans/2026-05-07-moq-relay-routing-investigation.md index 94bbe9588..ac9d6f796 100644 --- a/nestsClient/plans/2026-05-07-moq-relay-routing-investigation.md +++ b/nestsClient/plans/2026-05-07-moq-relay-routing-investigation.md @@ -1,6 +1,165 @@ # Plan: investigate moq-relay 0.10.x per-broadcast subscribe-routing race -**Status:** Step 1 instrumentation landed; sweep + analysis in progress. +**Status:** ❌ HYPOTHESIS DISPROVEN. Step 1 trace data shows the relay +**does** forward upstream SUBSCRIBE correctly. The failure is on the +**speaker side** — the speaker's QUIC connection silently drops a +peer-initiated bidi opened by the relay ~2 s after speaker connect. +The work continues but the actor changes — see "Corrected diagnosis" +below. **The investigation moves to `:quic`** (or to whatever owns +`incomingBidiStreams` plumbing), which is out of scope for this +session per project guidance. + +## 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 `` 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=''` 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(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 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}/--.log` + (kept on the branch for the next pickup; small enough to commit + if needed). +- Per-test JUnit XML with speaker ``: + `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) diff --git a/nestsClient/plans/2026-05-07-t16-closure-roadmap.md b/nestsClient/plans/2026-05-07-t16-closure-roadmap.md index d962e0c3f..a2f728ca0 100644 --- a/nestsClient/plans/2026-05-07-t16-closure-roadmap.md +++ b/nestsClient/plans/2026-05-07-t16-closure-roadmap.md @@ -17,16 +17,27 @@ parallelized — each unblocks the next. ## Priority 1 — `2026-05-07-moq-relay-routing-investigation.md` -**Why first.** The race is the root cause of every soft-pass and +> **Re-scoped 2026-05-07.** Trace capture (Step 1 of the routing +> plan) disproved the "moq-relay 0.10.x routing race" hypothesis. +> The actual fault is in **`:quic`**'s peer-bidi surfacing path: +> the speaker's QUIC stack silently drops a peer-opened bidi that +> arrives ~2 s after another bidi has been processed. The relay +> forwards the upstream SUBSCRIBE correctly. See the +> "Corrected diagnosis" section of the routing-investigation +> plan for the full trace pair. So the actor here is whoever +> owns `:quic` (different agent), not moq-rs upstream. + +**Why first.** The flake is the root cause of every soft-pass and the reason CI isn't wired. Without resolving it, downstream plans mask flake rather than catch regressions. **What lands.** -- Either an upstream moq-relay version bump that closes the bug, - OR a documented relay configuration tweak that does. -- Or, if neither: a filed `kixelated/moq` issue with reproducer + - trace pair, plus a documented decision to keep CI unwired until - upstream resolves. +- Either a fix in `:quic`'s `WtPeerStreamDemux` / + `incomingBidiStreams` path that closes the bug, +- Or, if the QUIC owner can't reproduce: the cross-stack + trace-capture artefacts (relay log + speaker NestTx log + JUnit + XML) handed off, with a written 60 % flake repro on + `late_join_listener_still_decodes_tail`. **Acceptance bar.** 5/5 sweep BUILD SUCCESSFUL on the existing HangInteropTest + BrowserInteropTest with their CURRENT soft-pass diff --git a/nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/README.md b/nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/README.md new file mode 100644 index 000000000..f901ae27f --- /dev/null +++ b/nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/README.md @@ -0,0 +1,61 @@ +# Trace artefacts: `late_join_listener_still_decodes_tail` flake (2026-05-07) + +These three files are the evidence that disproves the +"moq-relay 0.10.x per-broadcast subscribe-routing race" hypothesis +in `nestsClient/plans/2026-05-07-moq-relay-routing-investigation.md`. + +Captured by Step 1 of that plan: per-test moq-relay trace logging +(`-DnestsHangInteropTraceRelay=true`) over a 5× sweep of +`HangInteropTest`. Failure rate observed: 3/5 sweeps, all in +`late_join_listener_still_decodes_tail`. Sweeps 1, 2, 3 failed; +4, 5 passed. + +## Files + +- `sweep-1-FAIL-relay-trace.trace.txt` — moq-relay subprocess stderr + with `RUST_LOG=info,moq_relay=trace,moq_lite=trace,moq_native=debug` + for the failing scenario in sweep 1 (broadcast suffix + `6d60532f…`). 39 lines; ANSI stripped. +- `sweep-1-FAIL-speaker-NestTx.trace.txt` — `Log.d("NestTx")` lines from + the JUnit XML `` filtered to the failing test's time + window (`18:34:52`–`18:34:57`). +- `sweep-4-PASS-relay-trace.trace.txt` — same scenario, sweep 4, where + the speaker DID respond to the relay's upstream SUBSCRIBE. Use + this for the diff. + +## How to read them + +The crucial claim is: in the FAIL trace, the relay opens a +peer-initiated bidi to the speaker at 18:34:54.152 and writes +a complete `Subscribe { id:0, track:"catalog.json" }` message +to it (lines containing `subscribe started` and +`encoding self=Subscribe`). The speaker's NestTx log has NO +matching `SUBSCRIBE inbound id=0`. Therefore the wire SUBSCRIBE +message is lost between QUIC's bidi accept path and +`MoqLiteSession.handleInboundBidi`. + +The PASS trace shows the same scenario completing the +relay→speaker SubscribeOk round-trip in ~1.94 ms, confirming the +speaker-side handler IS capable of processing this bidi when it +manages to reach the application. + +## What this rules out + +- moq-relay 0.10.x's `Origin::announced()` → `consume_broadcast` + race. The relay's lookup succeeds and the upstream subscribe + IS opened. +- Speaker-side hook installation race. The speaker logs + `ANNOUNCE inbound prefix=''` correctly at T=0 but the LATER + bidi never reaches handleInboundBidi at all. +- Test framework / test ordering. Same failure recurs across + per-method `resetShared()` boots and survives sweep 5's + successful run vs sweep 1's failure on the same harness. + +## What it points to + +The QUIC stack's path from peer-initiated bidi acceptance → +`WtPeerStreamDemux.readyStreams.trySend(...)` → +`incomingStrippedStreams.consumeAsFlow()` → +`MoqLiteSession.pumpInboundBidis`. One of those handoffs drops the +bidi 40-60 % of the time when bidi #2 arrives ~2 s after bidi #1 +on the same connection. diff --git a/nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/sweep-1-FAIL-relay-trace.trace.txt b/nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/sweep-1-FAIL-relay-trace.trace.txt new file mode 100644 index 000000000..5711d7e91 --- /dev/null +++ b/nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/sweep-1-FAIL-relay-trace.trace.txt @@ -0,0 +1,39 @@ +2026-05-07T18:34:52.026436Z TRACE moq_relay::config: final config config=Config { server: ServerConfig { bind: Some("127.0.0.1:36015"), backend: None, quic_lb_id: None, quic_lb_nonce: None, max_streams: None, version: [], tls: ServerTlsConfig { cert: [], key: [], generate: ["localhost"], root: [] } }, client: ClientConfig { bind: 127.0.0.1:0, backend: None, max_streams: None, version: [], tls: ClientTls { root: [], cert: None, key: None, disable_verify: None }, backoff: Backoff { initial: 1s, multiplier: 2, max: 30s, timeout: None }, websocket: ClientWebSocket { enabled: true, delay: Some(200ms) } }, log: Log { level: Level(Info) }, cluster: ClusterConfig { root: None, token: None, node: None, prefix: "internal/origins" }, auth: AuthConfig { key: None, key_dir: None, tls: AuthTls { root: [], cert: None, key: None, disable_verify: None }, public: Some(Simple([""])), public_subscribe: None, public_publish: None, public_api: None }, web: WebConfig { http: HttpConfig { listen: None }, https: HttpsConfig { listen: None, cert: None, key: None }, ws: true }, file: None, iroh: IrohEndpointConfig { enabled: None, secret: None, bind_v4: None, bind_v6: None, disable_relay: None } } +2026-05-07T18:34:52.074954Z INFO moq_relay: listening addr=127.0.0.1:36015 +2026-05-07T18:34:52.075041Z INFO moq_relay::cluster: running as root, accepting leaf nodes +2026-05-07T18:34:52.081425Z WARN rustls::msgs::handshake: Illegal SNI extension: ignoring IP address presented as hostname (3132372e302e302e31) +2026-05-07T18:34:52.081527Z WARN moq_native::tls: no SNI certificate found server_name=None +2026-05-07T18:34:52.082207Z DEBUG moq_native::quinn: accepting host= ip=127.0.0.1:48534 alpn=h3 +2026-05-07T18:34:52.085126Z DEBUG moq_native::quinn: accepted host= ip=127.0.0.1:48534 alpn=h3 +2026-05-07T18:34:52.085638Z INFO conn{id=0}: moq_relay::connection: session accepted transport="quic" root=nests/30312:6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458:rt-59e2aebe-a5f0-4241-8bce-3d093763fbac publish= subscribe= +2026-05-07T18:34:52.085900Z INFO conn{id=0}: moq_relay::connection: negotiated version=moq-lite-03 transport="quic" +2026-05-07T18:34:52.085976Z TRACE conn{id=0}: moq_lite::lite::message: encoding self=AnnounceInterest { prefix: Path(""), exclude_hop: 0 } +2026-05-07T18:34:52.092094Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Probe { bitrate: 32000, rtt: None } +2026-05-07T18:34:52.092167Z DEBUG conn{id=0}: moq_lite::lite::subscriber: probe stream closed +2026-05-07T18:34:52.092405Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Active { suffix: Path("6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458"), hops: [] } +2026-05-07T18:34:52.092451Z DEBUG conn{id=0}: moq_lite::lite::subscriber: announce broadcast=nests/30312:6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458:rt-59e2aebe-a5f0-4241-8bce-3d093763fbac/6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458 +2026-05-07T18:34:54.149303Z WARN moq_native::tls: no SNI certificate found server_name=None +2026-05-07T18:34:54.150149Z DEBUG moq_native::quinn: accepting host= ip=127.0.0.1:41457 alpn=h3 +2026-05-07T18:34:54.150976Z DEBUG moq_native::quinn: accepted host= ip=127.0.0.1:41457 alpn=h3 +2026-05-07T18:34:54.151521Z INFO conn{id=1}: moq_relay::connection: session accepted transport="quic" root=nests/30312:6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458:rt-59e2aebe-a5f0-4241-8bce-3d093763fbac publish= subscribe= +2026-05-07T18:34:54.151697Z INFO conn{id=1}: moq_relay::connection: negotiated version=moq-lite-03 transport="quic" +2026-05-07T18:34:54.151710Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=AnnounceInterest { prefix: Path(""), exclude_hop: 0 } +2026-05-07T18:34:54.152094Z TRACE conn{id=1}: moq_lite::lite::message: decoded result=AnnounceInterest { prefix: Path(""), exclude_hop: 0 } +2026-05-07T18:34:54.152164Z DEBUG conn{id=1}: moq_lite::lite::publisher: announce broadcast=nests/30312:6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458:rt-59e2aebe-a5f0-4241-8bce-3d093763fbac/6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458 +2026-05-07T18:34:54.152184Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Active { suffix: Path("6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458"), hops: [] } +2026-05-07T18:34:54.152434Z TRACE conn{id=1}: moq_lite::lite::message: decoded result=Probe { bitrate: 45593982, rtt: None } +2026-05-07T18:34:54.152699Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Probe { bitrate: 193376453, rtt: Some(0) } +2026-05-07T18:34:54.152809Z TRACE conn{id=1}: moq_lite::lite::message: decoded result=Subscribe { id: 0, broadcast: Path("6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458"), track: "catalog.json", priority: 100, ordered: true, max_latency: 0ns, start_group: None, end_group: None } +2026-05-07T18:34:54.152832Z INFO conn{id=1}: moq_lite::lite::publisher: subscribed started id=0 broadcast=nests/30312:6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458:rt-59e2aebe-a5f0-4241-8bce-3d093763fbac/6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458 track=catalog.json +2026-05-07T18:34:54.152923Z INFO conn{id=0}: moq_lite::lite::subscriber: subscribe started id=0 broadcast=nests/30312:6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458:rt-59e2aebe-a5f0-4241-8bce-3d093763fbac/6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458 track=catalog.json +2026-05-07T18:34:54.152963Z TRACE conn{id=0}: moq_lite::lite::message: encoding self=Subscribe { id: 0, broadcast: Path("6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458"), track: "catalog.json", priority: 100, ordered: true, max_latency: 0ns, start_group: None, end_group: None } +2026-05-07T18:34:57.095776Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Ended { suffix: Path("6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458"), hops: [] } +2026-05-07T18:34:57.095828Z DEBUG conn{id=0}: moq_lite::lite::subscriber: unannounced broadcast=nests/30312:6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458:rt-59e2aebe-a5f0-4241-8bce-3d093763fbac/6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458 +2026-05-07T18:34:57.095922Z DEBUG conn{id=0}: moq_lite::lite::subscriber: broadcast closed err=cancelled +2026-05-07T18:34:57.095986Z DEBUG conn{id=1}: moq_lite::lite::publisher: unannounce broadcast=nests/30312:6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458:rt-59e2aebe-a5f0-4241-8bce-3d093763fbac/6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458 +2026-05-07T18:34:57.095996Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Ended { suffix: Path("6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458"), hops: [] } +2026-05-07T18:34:57.095999Z INFO conn{id=1}: moq_lite::lite::publisher: subscribed cancelled id=0 broadcast=nests/30312:6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458:rt-59e2aebe-a5f0-4241-8bce-3d093763fbac/6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458 track=catalog.json +2026-05-07T18:34:57.096013Z INFO conn{id=0}: moq_lite::lite::subscriber: subscribe cancelled id=0 broadcast=nests/30312:6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458:rt-59e2aebe-a5f0-4241-8bce-3d093763fbac/6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458 track=catalog.json +2026-05-07T18:34:57.097496Z WARN web_transport_quinn::session: failed to read capsule e=UnexpectedEnd +2026-05-07T18:34:57.097577Z INFO conn{id=0}: moq_lite::lite::session: session terminated +2026-05-07T18:34:57.097800Z WARN moq_relay: connection closed err=transport: connection error: closed diff --git a/nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/sweep-1-FAIL-speaker-NestTx.trace.txt b/nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/sweep-1-FAIL-speaker-NestTx.trace.txt new file mode 100644 index 000000000..301219272 --- /dev/null +++ b/nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/sweep-1-FAIL-speaker-NestTx.trace.txt @@ -0,0 +1,11 @@ +18:34:52.092 DEBUG: [NestTx] ANNOUNCE inbound prefix='' → emitted Active suffix='6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458' (publisher.suffix='6d60532fccc6e96fbd52693ce7cb3d7bc0977e1d10149aff7f967937f22e1458') +18:34:52.111 WARN : [NestTx] send returning false — no inboundSubs (count=1, payload=120B) +18:34:53.091 WARN : [NestTx] broadcaster send returned false — frame dropped (count=50, sent=0) +18:34:53.111 WARN : [NestTx] send returning false — no inboundSubs (count=51, payload=85B) +18:34:54.091 WARN : [NestTx] broadcaster send returned false — frame dropped (count=100, sent=0) +18:34:54.111 WARN : [NestTx] send returning false — no inboundSubs (count=101, payload=89B) +18:34:55.091 WARN : [NestTx] broadcaster send returned false — frame dropped (count=150, sent=0) +18:34:55.111 WARN : [NestTx] send returning false — no inboundSubs (count=151, payload=85B) +18:34:56.092 WARN : [NestTx] broadcaster send returned false — frame dropped (count=200, sent=0) +18:34:56.111 WARN : [NestTx] send returning false — no inboundSubs (count=201, payload=85B) +18:34:57.092 WARN : [NestTx] broadcaster send returned false — frame dropped (count=250, sent=0) diff --git a/nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/sweep-4-PASS-relay-trace.trace.txt b/nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/sweep-4-PASS-relay-trace.trace.txt new file mode 100644 index 000000000..4d6747d2b --- /dev/null +++ b/nestsClient/plans/artefacts/2026-05-07-routing-race-disproven/sweep-4-PASS-relay-trace.trace.txt @@ -0,0 +1,175 @@ +2026-05-07T18:42:42.832496Z TRACE moq_relay::config: final config config=Config { server: ServerConfig { bind: Some("127.0.0.1:46327"), backend: None, quic_lb_id: None, quic_lb_nonce: None, max_streams: None, version: [], tls: ServerTlsConfig { cert: [], key: [], generate: ["localhost"], root: [] } }, client: ClientConfig { bind: 127.0.0.1:0, backend: None, max_streams: None, version: [], tls: ClientTls { root: [], cert: None, key: None, disable_verify: None }, backoff: Backoff { initial: 1s, multiplier: 2, max: 30s, timeout: None }, websocket: ClientWebSocket { enabled: true, delay: Some(200ms) } }, log: Log { level: Level(Info) }, cluster: ClusterConfig { root: None, token: None, node: None, prefix: "internal/origins" }, auth: AuthConfig { key: None, key_dir: None, tls: AuthTls { root: [], cert: None, key: None, disable_verify: None }, public: Some(Simple([""])), public_subscribe: None, public_publish: None, public_api: None }, web: WebConfig { http: HttpConfig { listen: None }, https: HttpsConfig { listen: None, cert: None, key: None }, ws: true }, file: None, iroh: IrohEndpointConfig { enabled: None, secret: None, bind_v4: None, bind_v6: None, disable_relay: None } } +2026-05-07T18:42:42.883697Z INFO moq_relay: listening addr=127.0.0.1:46327 +2026-05-07T18:42:42.883971Z INFO moq_relay::cluster: running as root, accepting leaf nodes +2026-05-07T18:42:42.889910Z WARN rustls::msgs::handshake: Illegal SNI extension: ignoring IP address presented as hostname (3132372e302e302e31) +2026-05-07T18:42:42.889964Z WARN moq_native::tls: no SNI certificate found server_name=None +2026-05-07T18:42:42.890731Z DEBUG moq_native::quinn: accepting host= ip=127.0.0.1:42874 alpn=h3 +2026-05-07T18:42:42.893638Z DEBUG moq_native::quinn: accepted host= ip=127.0.0.1:42874 alpn=h3 +2026-05-07T18:42:42.894105Z INFO conn{id=0}: moq_relay::connection: session accepted transport="quic" root=nests/30312:8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f:rt-c1c8c715-8751-40f2-a551-2b556d8e53c5 publish= subscribe= +2026-05-07T18:42:42.894382Z INFO conn{id=0}: moq_relay::connection: negotiated version=moq-lite-03 transport="quic" +2026-05-07T18:42:42.894510Z TRACE conn{id=0}: moq_lite::lite::message: encoding self=AnnounceInterest { prefix: Path(""), exclude_hop: 0 } +2026-05-07T18:42:42.896959Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Probe { bitrate: 32000, rtt: None } +2026-05-07T18:42:42.896984Z DEBUG conn{id=0}: moq_lite::lite::subscriber: probe stream closed +2026-05-07T18:42:42.896997Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Active { suffix: Path("8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f"), hops: [] } +2026-05-07T18:42:42.897009Z DEBUG conn{id=0}: moq_lite::lite::subscriber: announce broadcast=nests/30312:8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f:rt-c1c8c715-8751-40f2-a551-2b556d8e53c5/8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f +2026-05-07T18:42:44.950403Z WARN moq_native::tls: no SNI certificate found server_name=None +2026-05-07T18:42:44.951302Z DEBUG moq_native::quinn: accepting host= ip=127.0.0.1:37438 alpn=h3 +2026-05-07T18:42:44.952123Z DEBUG moq_native::quinn: accepted host= ip=127.0.0.1:37438 alpn=h3 +2026-05-07T18:42:44.952693Z INFO conn{id=1}: moq_relay::connection: session accepted transport="quic" root=nests/30312:8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f:rt-c1c8c715-8751-40f2-a551-2b556d8e53c5 publish= subscribe= +2026-05-07T18:42:44.952936Z INFO conn{id=1}: moq_relay::connection: negotiated version=moq-lite-03 transport="quic" +2026-05-07T18:42:44.952976Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=AnnounceInterest { prefix: Path(""), exclude_hop: 0 } +2026-05-07T18:42:44.953705Z TRACE conn{id=1}: moq_lite::lite::message: decoded result=AnnounceInterest { prefix: Path(""), exclude_hop: 0 } +2026-05-07T18:42:44.953803Z DEBUG conn{id=1}: moq_lite::lite::publisher: announce broadcast=nests/30312:8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f:rt-c1c8c715-8751-40f2-a551-2b556d8e53c5/8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f +2026-05-07T18:42:44.953828Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Active { suffix: Path("8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f"), hops: [] } +2026-05-07T18:42:44.953943Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Probe { bitrate: 168163791, rtt: Some(0) } +2026-05-07T18:42:44.954321Z TRACE conn{id=1}: moq_lite::lite::message: decoded result=Subscribe { id: 0, broadcast: Path("8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f"), track: "catalog.json", priority: 100, ordered: true, max_latency: 0ns, start_group: None, end_group: None } +2026-05-07T18:42:44.954359Z INFO conn{id=1}: moq_lite::lite::publisher: subscribed started id=0 broadcast=nests/30312:8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f:rt-c1c8c715-8751-40f2-a551-2b556d8e53c5/8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f track=catalog.json +2026-05-07T18:42:44.954414Z TRACE conn{id=1}: moq_lite::lite::message: decoded result=Probe { bitrate: 50438976, rtt: None } +2026-05-07T18:42:44.954508Z INFO conn{id=0}: moq_lite::lite::subscriber: subscribe started id=0 broadcast=nests/30312:8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f:rt-c1c8c715-8751-40f2-a551-2b556d8e53c5/8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f track=catalog.json +2026-05-07T18:42:44.954530Z TRACE conn{id=0}: moq_lite::lite::message: encoding self=Subscribe { id: 0, broadcast: Path("8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f"), track: "catalog.json", priority: 100, ordered: true, max_latency: 0ns, start_group: None, end_group: None } +2026-05-07T18:42:44.956465Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=SubscribeOk { priority: 100, ordered: true, max_latency: 0ns, start_group: None, end_group: None } +2026-05-07T18:42:44.956585Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 0, sequence: 0 } +2026-05-07T18:42:44.956938Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=0 track=catalog.json sequence=0 +2026-05-07T18:42:44.956970Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 0, sequence: 0 } +2026-05-07T18:42:44.957531Z TRACE conn{id=1}: moq_lite::lite::message: decoded result=Subscribe { id: 1, broadcast: Path("8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f"), track: "audio/data", priority: 1, ordered: true, max_latency: 0ns, start_group: None, end_group: None } +2026-05-07T18:42:44.957552Z INFO conn{id=1}: moq_lite::lite::publisher: subscribed started id=1 broadcast=nests/30312:8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f:rt-c1c8c715-8751-40f2-a551-2b556d8e53c5/8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f track=audio/data +2026-05-07T18:42:44.957627Z INFO conn{id=0}: moq_lite::lite::subscriber: subscribe started id=1 broadcast=nests/30312:8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f:rt-c1c8c715-8751-40f2-a551-2b556d8e53c5/8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f track=audio/data +2026-05-07T18:42:44.957673Z TRACE conn{id=0}: moq_lite::lite::message: encoding self=Subscribe { id: 1, broadcast: Path("8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f"), track: "audio/data", priority: 1, ordered: true, max_latency: 0ns, start_group: None, end_group: None } +2026-05-07T18:42:44.957812Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=0 +2026-05-07T18:42:44.959359Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=SubscribeOk { priority: 1, ordered: true, max_latency: 0ns, start_group: None, end_group: None } +2026-05-07T18:42:44.975490Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 0 } +2026-05-07T18:42:44.975533Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=0 +2026-05-07T18:42:44.975552Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 0 } +2026-05-07T18:42:44.995637Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=0 +2026-05-07T18:42:45.014717Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 1 } +2026-05-07T18:42:45.014753Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=1 +2026-05-07T18:42:45.014772Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 1 } +2026-05-07T18:42:45.054271Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Probe { bitrate: 251620461, rtt: Some(0) } +2026-05-07T18:42:45.095830Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=1 +2026-05-07T18:42:45.115298Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 2 } +2026-05-07T18:42:45.115361Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=2 +2026-05-07T18:42:45.115386Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 2 } +2026-05-07T18:42:45.154014Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Probe { bitrate: 322831229, rtt: Some(0) } +2026-05-07T18:42:45.195572Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=2 +2026-05-07T18:42:45.214841Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 3 } +2026-05-07T18:42:45.214924Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=3 +2026-05-07T18:42:45.214947Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 3 } +2026-05-07T18:42:45.295078Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=3 +2026-05-07T18:42:45.315181Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 4 } +2026-05-07T18:42:45.315252Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=4 +2026-05-07T18:42:45.315277Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 4 } +2026-05-07T18:42:45.354785Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Probe { bitrate: 476207011, rtt: Some(0) } +2026-05-07T18:42:45.395471Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=4 +2026-05-07T18:42:45.415599Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 5 } +2026-05-07T18:42:45.415682Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=5 +2026-05-07T18:42:45.415705Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 5 } +2026-05-07T18:42:45.515304Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 6 } +2026-05-07T18:42:45.515352Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=6 +2026-05-07T18:42:45.515374Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 6 } +2026-05-07T18:42:45.515617Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=5 +2026-05-07T18:42:45.595537Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=6 +2026-05-07T18:42:45.614794Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 7 } +2026-05-07T18:42:45.614891Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=7 +2026-05-07T18:42:45.614937Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 7 } +2026-05-07T18:42:45.654016Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Probe { bitrate: 607694937, rtt: Some(0) } +2026-05-07T18:42:45.695065Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=7 +2026-05-07T18:42:45.715434Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 8 } +2026-05-07T18:42:45.715501Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=8 +2026-05-07T18:42:45.715525Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 8 } +2026-05-07T18:42:45.815047Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 9 } +2026-05-07T18:42:45.815159Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=9 +2026-05-07T18:42:45.815192Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 9 } +2026-05-07T18:42:45.815447Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=8 +2026-05-07T18:42:45.915751Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 10 } +2026-05-07T18:42:45.915852Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=10 +2026-05-07T18:42:45.915902Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 10 } +2026-05-07T18:42:45.916188Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=9 +2026-05-07T18:42:45.995272Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=10 +2026-05-07T18:42:46.015621Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 11 } +2026-05-07T18:42:46.015700Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=11 +2026-05-07T18:42:46.015750Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 11 } +2026-05-07T18:42:46.115073Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 12 } +2026-05-07T18:42:46.115119Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=12 +2026-05-07T18:42:46.115142Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 12 } +2026-05-07T18:42:46.115548Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=11 +2026-05-07T18:42:46.195372Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=12 +2026-05-07T18:42:46.215598Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 13 } +2026-05-07T18:42:46.215644Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=13 +2026-05-07T18:42:46.215667Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 13 } +2026-05-07T18:42:46.295682Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=13 +2026-05-07T18:42:46.314964Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 14 } +2026-05-07T18:42:46.315025Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=14 +2026-05-07T18:42:46.315048Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 14 } +2026-05-07T18:42:46.415260Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 15 } +2026-05-07T18:42:46.415326Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=15 +2026-05-07T18:42:46.415383Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 15 } +2026-05-07T18:42:46.415649Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=14 +2026-05-07T18:42:46.495623Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=15 +2026-05-07T18:42:46.514908Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 16 } +2026-05-07T18:42:46.515009Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=16 +2026-05-07T18:42:46.515052Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 16 } +2026-05-07T18:42:46.595126Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=16 +2026-05-07T18:42:46.615336Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 17 } +2026-05-07T18:42:46.615399Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=17 +2026-05-07T18:42:46.615424Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 17 } +2026-05-07T18:42:46.714906Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 18 } +2026-05-07T18:42:46.714988Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=18 +2026-05-07T18:42:46.715014Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 18 } +2026-05-07T18:42:46.715269Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=17 +2026-05-07T18:42:46.815586Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 19 } +2026-05-07T18:42:46.815671Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=19 +2026-05-07T18:42:46.815744Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 19 } +2026-05-07T18:42:46.816005Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=18 +2026-05-07T18:42:46.915364Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 20 } +2026-05-07T18:42:46.915431Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=20 +2026-05-07T18:42:46.915462Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 20 } +2026-05-07T18:42:46.915756Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=19 +2026-05-07T18:42:47.014999Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 21 } +2026-05-07T18:42:47.015057Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=21 +2026-05-07T18:42:47.015087Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 21 } +2026-05-07T18:42:47.015331Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=20 +2026-05-07T18:42:47.095214Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=21 +2026-05-07T18:42:47.115641Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 22 } +2026-05-07T18:42:47.115712Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=22 +2026-05-07T18:42:47.115735Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 22 } +2026-05-07T18:42:47.215569Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 23 } +2026-05-07T18:42:47.215624Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=23 +2026-05-07T18:42:47.215701Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 23 } +2026-05-07T18:42:47.216035Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=22 +2026-05-07T18:42:47.315453Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 24 } +2026-05-07T18:42:47.315510Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=24 +2026-05-07T18:42:47.315557Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 24 } +2026-05-07T18:42:47.315816Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=23 +2026-05-07T18:42:47.395946Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=24 +2026-05-07T18:42:47.415332Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 25 } +2026-05-07T18:42:47.415392Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=25 +2026-05-07T18:42:47.415414Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 25 } +2026-05-07T18:42:47.495904Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=25 +2026-05-07T18:42:47.515884Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 26 } +2026-05-07T18:42:47.515985Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=26 +2026-05-07T18:42:47.516028Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 26 } +2026-05-07T18:42:47.615707Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 27 } +2026-05-07T18:42:47.615791Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=27 +2026-05-07T18:42:47.615832Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 27 } +2026-05-07T18:42:47.616096Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=26 +2026-05-07T18:42:47.695763Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=27 +2026-05-07T18:42:47.715155Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 28 } +2026-05-07T18:42:47.715225Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=28 +2026-05-07T18:42:47.715245Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 28 } +2026-05-07T18:42:47.815714Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Group { subscribe: 1, sequence: 29 } +2026-05-07T18:42:47.815781Z DEBUG conn{id=1}: moq_lite::lite::publisher: serving group subscribe=1 track=audio/data sequence=29 +2026-05-07T18:42:47.815824Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Group { subscribe: 1, sequence: 29 } +2026-05-07T18:42:47.816113Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=28 +2026-05-07T18:42:47.895975Z DEBUG conn{id=1}: moq_lite::lite::publisher: finished group sequence=29 +2026-05-07T18:42:47.898640Z TRACE conn{id=0}: moq_lite::lite::message: decoded result=Ended { suffix: Path("8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f"), hops: [] } +2026-05-07T18:42:47.898669Z DEBUG conn{id=0}: moq_lite::lite::subscriber: unannounced broadcast=nests/30312:8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f:rt-c1c8c715-8751-40f2-a551-2b556d8e53c5/8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f +2026-05-07T18:42:47.898821Z INFO conn{id=0}: moq_lite::lite::subscriber: subscribe cancelled id=1 broadcast=nests/30312:8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f:rt-c1c8c715-8751-40f2-a551-2b556d8e53c5/8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f track=audio/data +2026-05-07T18:42:47.898867Z INFO conn{id=1}: moq_lite::lite::publisher: subscribed cancelled id=1 broadcast=nests/30312:8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f:rt-c1c8c715-8751-40f2-a551-2b556d8e53c5/8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f track=audio/data +2026-05-07T18:42:47.898930Z INFO conn{id=0}: moq_lite::lite::subscriber: subscribe cancelled id=0 broadcast=nests/30312:8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f:rt-c1c8c715-8751-40f2-a551-2b556d8e53c5/8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f track=catalog.json +2026-05-07T18:42:47.898963Z INFO conn{id=1}: moq_lite::lite::publisher: subscribed cancelled id=0 broadcast=nests/30312:8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f:rt-c1c8c715-8751-40f2-a551-2b556d8e53c5/8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f track=catalog.json +2026-05-07T18:42:47.898986Z DEBUG conn{id=0}: moq_lite::lite::subscriber: broadcast closed err=cancelled +2026-05-07T18:42:47.899017Z DEBUG conn{id=1}: moq_lite::lite::publisher: unannounce broadcast=nests/30312:8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f:rt-c1c8c715-8751-40f2-a551-2b556d8e53c5/8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f +2026-05-07T18:42:47.899020Z TRACE conn{id=1}: moq_lite::lite::message: encoding self=Ended { suffix: Path("8471729302d935df5f527f5d789dde9163968487839a1148cbd542836ea6ac2f"), hops: [] } +2026-05-07T18:42:47.899927Z WARN web_transport_quinn::session: failed to read capsule e=UnexpectedEnd +2026-05-07T18:42:47.899980Z INFO conn{id=0}: moq_lite::lite::session: session terminated +2026-05-07T18:42:47.900177Z WARN moq_relay: connection closed err=transport: connection error: closed diff --git a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/native/BrowserInteropTest.kt b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/native/BrowserInteropTest.kt index f0a765712..0de6c729b 100644 --- a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/native/BrowserInteropTest.kt +++ b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/native/BrowserInteropTest.kt @@ -45,6 +45,8 @@ import kotlinx.coroutines.flow.first import kotlinx.coroutines.launch import kotlinx.coroutines.runBlocking import kotlinx.coroutines.withTimeoutOrNull +import org.junit.Rule +import org.junit.rules.TestName import java.io.File import java.nio.ByteBuffer import java.nio.ByteOrder @@ -52,8 +54,6 @@ import java.util.UUID import kotlin.test.BeforeTest import kotlin.test.Test import kotlin.test.assertTrue -import org.junit.Rule -import org.junit.rules.TestName /** * Phase 4 (T16) — browser-side cross-stack interop scenarios. diff --git a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/native/HangInteropTest.kt b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/native/HangInteropTest.kt index 414de8c66..51379c8cd 100644 --- a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/native/HangInteropTest.kt +++ b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/native/HangInteropTest.kt @@ -48,6 +48,8 @@ import kotlinx.coroutines.flow.take import kotlinx.coroutines.flow.toList import kotlinx.coroutines.runBlocking import kotlinx.coroutines.withTimeoutOrNull +import org.junit.Rule +import org.junit.rules.TestName import java.io.File import java.nio.ByteBuffer import java.nio.ByteOrder @@ -58,8 +60,6 @@ import kotlin.test.Test import kotlin.test.assertEquals import kotlin.test.assertFalse import kotlin.test.assertTrue -import org.junit.Rule -import org.junit.rules.TestName /** * Cross-stack interop scenarios driving the reference `kixelated/moq`