QuicConnection.alpnList → TlsClient.offeredAlpns was captured but never
threaded into buildQuicClientHello. The builder accepted only an
"additionalAlpn" parameter and hardcoded "h3" first, so our wire
ClientHello always carried just [h3] regardless of caller intent.
quic-go enforces strictly with TLS alert 120 (no_application_protocol,
CRYPTO_ERROR 376) when none of the offered ALPNs match its server
config — handshake failed at the very first server response against
quic-go's hq-interop testcases.
Replaced the awkward additionalAlpn shape with `alpns: List<ByteArray>`
(default [h3] for backward-compat) and threaded TlsClient.offeredAlpns
through.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
longrtt failed against aioquic with "Expected at least 2 ClientHellos.
Got: 1" because our client started sending Initials before the sim's
ns3 + tcpdump capture finished initializing. Only the PTO retransmit
hit the wire — the original ClientHello was sent during the sim's
~1s readiness window and never captured. aioquic, picoquic, and
quic-go all gate their client launch on /wait-for-it.sh sim:57832.
We didn't.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
When the runner's compliance-check phase produces traces but the
actual testcase phase doesn't (matrix runs against multiple
testcases sometimes lose later containers' stderr), the previous
inspect script greppped the runner's stdout and silently produced
nothing.
Now: check per-testcase client/output.txt and output.txt first; fall
back to the tee'd .stdout.log narrowed to this testcase's window.
On total miss, print actionable hints (rebuild with DEBUG, run in
isolation).
The 'run-<timestamp>.stdout.log' siblings also match the 'run-*'
glob — zsh in particular returns them mixed with the actual run
dirs. The for-loop now filters to directories only.
(The summarize-matrix script was already OK — it does ls -1d
followed by a head -1, and run dirs come first in mtime order.)
Previously the script only showed server stderr — but the bug
investigation needs the CLIENT's runtime traces, which are in the
runner's tee'd stdout (${RUN_DIR}.stdout.log).
awk-narrows the lines to the segment between this testcase's
'Running test case: X' marker and the next one (each testcase runs
a fresh container, so the trace lines between markers are exactly
this testcase's run). Then dumps:
- first 50 [boot] / [interop] / [batch] / [writer.app] lines
- stream_frames=N histogram for the testcase
Useful when debugging a specific testcase failure that requires
seeing the writer's per-drain decisions.
The longrtt testcase (1 file, serial path) was failing because
client.get(authority, path) → prepareRequest() opens a stream and
queues the GET, but never calls driver.wakeup(). The data sits in
the queue until the PTO timer fires (~1 s later) — a fatal delay
on a 1.5 s RTT link with an 8 s docker-compose timeout.
The parallel path explicitly wakes after prepareRequests returns,
but the serial path was missing the equivalent nudge.
Smoking gun from the inspect-testcase output:
- 1 KB file, handshake at t=4502, response packets at t=4684/4685
- NO outgoing packet between t=4499 (ack) and t=4687 (ack) that
contained the GET request — it never went out via prepareRequest
Fix: prepareRequest in both Http3GetClient and HqInteropGetClient
now calls driver.wakeup() after enqueuing the request. The
@Suppress("UNUSED_PARAMETER") on HqInteropGetClient.driver was
also stale — it's used now.
The longrtt testcase failed at 8s with only 1.2 KB received (out of
3 MB requested). Trace from inspect-testcase:
handshake completed at t=4502 (3 RTTs at 750ms one-way as expected)
first stream byte arrived at t=4694, ~200ms after
test killed at t=8s with code=0x0 (graceful close from us)
After handshake, ~3.5s of transfer time was available before the
docker-compose timeout. With our default
initialMaxStreamDataBidiLocal = 1 MB, the peer sends 1 MB then stalls
until our parser fires a MAX_STREAM_DATA bump. At 1.5s RTT each stall
is one round-trip lost (~1.5s). For a 3 MB file that's 2 stalls = 3s
of pure flow-control idle on top of CC slow-start.
Setting initialMaxData and initialMaxStreamData{BidiLocal,
BidiRemote,Uni} to 32 MB removes flow control as a bottleneck for
the largest interop transfers (longrtt 5 MB, transfercorruption few
MB) and lets the peer's congestion control alone drive the rate.
Doesn't help handshake duration (which is RTT-bound and correct).
Doesn't help slow-start ramp (CC, server-side). Should still close
the gap on longrtt.
Usage:
./quic/interop/inspect-testcase.sh longrtt
Auto-finds the most recent run dir with the named testcase, then
emits a focused one-screen report:
- runner status line (from the tee'd .stdout.log)
- file sizes generated for that testcase
- qlog event-type histogram
- transport_parameters (peer's flow-control budget)
- connection_closed events (spec violations / explicit failures)
- last 10 sent/received packets (steady-state shape)
- first/last packet timestamps + total received count
(transfer rate hint)
- server stderr tail
8 plan files updated to reflect what's actually shipped vs. what
each doc said before:
- 2026-05-06-cross-stack-interop-test.md: 'Spec — ready to
implement' → 'Implemented and merged' with pointers to results,
gap matrix, and closure roadmap.
- 2026-05-06-cross-stack-interop-test-results.md: scenario
inventory updated to show all branches merged into
claude/cross-stack-interop-test-XAbYB; suite-flake caveats
flagged with cross-refs to the routing investigation; file
inventory now lists BrowserInteropTest + PlaywrightDriver +
the moved nestsClient/tests/browser-interop/ tree (no more 'in
sister branches not yet merged' section).
- 2026-05-06-cross-stack-interop-test-gap-matrix.md: T8/T10/T11/
T12/T13 all show hang ✅ + browser ✅; I13/I14 'NOT YET LANDED'
callouts removed; the 'in sister branch' qualifier on T13 / I7
/ I6 dropped; coverage-holes section replaced with caveat
pointers to the routing investigation.
- 2026-05-06-i4-stereo-cross-stack-scenario.md: 'Spec — ready for
implementation' → 'Landed' with PR #2755 + the three test
scenarios that ship the assertion.
- 2026-05-06-phase4-browser-harness.md: 'Spec — ready for
implementation' → 'Landed', with notes on how the implementation
diverged (used Container.Legacy.Consumer not @moq/watch; cert
pinning via serverCertificateHashes; I2/I3/I4/I13/I14 originally
deferred but later landed).
- 2026-05-06-phase4-browser-harness-results.md: status updated to
reflect 4.D CI removed per maintainer ask; layout note for
the nestsClient/tests/browser-interop/ relocation; full
scenario list reconciled with results doc.
- 2026-05-07-late-join-catalog-flake-investigation.md: status
updated to mention 00f6cba31 + 207057374 were reverted, and
link to 2026-05-07-moq-relay-routing-investigation.md as the
action plan. Adds note that the flake also affects four
browser-tier scenarios after Browser I7 landed.
- 2026-05-01-quic-stream-cliff-investigation.md: adds an HCgOY-
override banner — recommendation 2 (framesPerGroup = 5) was
superseded 4 days later by HCgOY field tests landing the prod
default at 50. Cross-refs the reconciliation + production-
rerun plans. Open follow-up #3 ('reset to 1') updated with
the same context.
No code or test changes.
Mirrors the existing nestsClient/tests/hang-interop/ layout — all
T16 cross-stack interop test infrastructure (Rust sidecars + bun
browser harness) now lives under nestsClient/tests/.
Updates:
- nestsClient/build.gradle.kts: browserInteropDir path.
- PlaywrightDriver.kt + BrowserInteropTest.kt: kdoc comments.
- All plan docs in nestsClient/plans/ that referenced the old
path.
Compiles clean post-move. No CI changes (those jobs are
intentionally not wired per 2026-05-07-cross-stack-interop-ci-gating.md;
when re-added they'll reference the new path).
Two bash-3.2 issues:
- Multiline process substitution '< <(...)' with embedded
comments triggered 'bad substitution: no closing ')''.
Reworked as imperative pushes to an array.
- 'set -u' rejects '${SEARCH_FILES[@]}' on an empty array.
Disabled '-u' since the artifact-fallback path doesn't need
any search files.
Plans the path from 'infra shipped' to 'full coverage with
correct behaviours'. Five new plan docs in nestsClient/plans/:
1. 2026-05-07-t16-closure-roadmap.md — index + priority order.
Three sequential steps + one independent track.
2. 2026-05-07-moq-relay-routing-investigation.md (Priority 1)
— root-cause the moq-relay 0.10.x per-broadcast subscribe-
routing race. Step-by-step: capture relay-side trace, write
minimum reproducer, file upstream OR bump moq-relay version.
Smoking gun + hypotheses already in place from the
late-join-flake investigation; this plan turns that into
actionable next steps.
3. 2026-05-07-tighten-cross-stack-assertions.md (Priority 2)
— once the routing race is closed, replace the five soft-
pass scenarios in BrowserInteropTest with hard floors.
Lists each scenario, its current soft-pass behavior, and
the proposed hard threshold.
4. 2026-05-07-cross-stack-interop-ci-gating.md (Priority 3)
— re-add the hang-interop + browser-interop GitHub Actions
jobs that were dropped in 6829ab727 / b94737de7. Includes
the exact YAML to restore and a 10/10 sweep stability bar
before merge.
5. 2026-05-07-framespergroup-production-rerun.md (independent
track) — re-run the HCgOY two-phone field tests against
current nostrnests production at multiple framesPerGroup
values to settle whether the test pin (5) and production
default (50) can converge.
Estimated total: 2.5-3.5 days of focused work to fully close
T16. After these four: I7 post-reconnect cliff and I12 GOAWAY
remain open as genuinely upstream-territory items, tracked in
their existing investigation docs.
Two paired changes:
(1) run-matrix.sh now tees the runner's full stdout (pre-grep-
filter) to <RUN_LOG_DIR>.stdout.log — sibling rather than
inside the log dir because run.py refuses to start if its own
--log-dir already exists.
(2) summarize-matrix.sh checks that file FIRST when searching for
'Test: X took Y, status:' lines — it has the authoritative
runner output that wasn't being saved before.
Old runs (without the tee) fall back to qlog inspection.
Some runner versions don't write 'Test: X took Y, status:' lines
into the per-testcase output.txt — they only print to the runner's
own stdout (which our run-matrix.sh consumes via grep filter and
loses). Without status lines we can still infer outcomes from
artifacts:
- qlog has a connection_closed event with a reason → FAILED with
that reason (e.g. peer CLOSE 'no CRYPTO frame')
- qlog has packets received but no close → ran something, status
genuinely uncertain
- no qlog → connection probably never made it past TLS
Tagged [inf] so users can distinguish runner-reported status from
inferred status.
The 'Test: X took Y, status: TestResult.Z' line is written by
run.py to its own stdout, not the per-testcase output.txt the
script was grepping. Scan common locations (per-testcase output.txt
fallback, run dir log files, runner-logs root) and accept the
runner's optional leading timestamp format.
Full matrix takes long enough to be vulnerable to terminal hangs,
docker OOM, or just user CTRL-C. Per-testcase output.txt files
hold status lines we can scrape without re-running anything.
Usage:
./quic/interop/summarize-matrix.sh
Output:
TESTCASE RESULT TIME
-------------------- --------------- ----------
handshake ✓ SUCCEEDED 2.5s
transfer ✓ SUCCEEDED 3.1s
multiplexing ✓ SUCCEEDED 5.2s
retry ✕ FAILED 8.3s
ecn ? UNSUPPORTED 2.6s
Helps iterate when the matrix is too long to run end-to-end on
macOS Docker.
The smoking gun from the 2026-05-07 multiplex run boot log:
[boot] DEBUG=1; ...; TESTCASE=transfer; ROLE=client
[boot] transfer mode: parallel=false urls=1999
quic-interop-runner sets TESTCASE_CLIENT=transfer for ALL the
transfer-family testcases (transfer, multiplexing, transferloss,
transfercorruption). Discrimination between transfer (1 file) and
multiplexing (~2000 files) happens by URL count, NOT by TESTCASE
name — so our check `parallel = (testcase == "multiplexing")` was
always false, even for the multiplexing test, and we always took
the serial fallback path: client.get(authority, path) per URL,
opening one stream + awaiting before the next. That's why the wire
showed exactly one stream per RTT for the entire 60s.
Fix: parallel = (token count of REQUESTS env var) > 1. Effectively:
- 1 URL → transfer testcase, serial path
- >1 URL → multiplexing testcase, batched-parallel path
Verified the writer's batched coalescing already works in unit
tests (MultiplexingCoalescingTest, MultiplexingAioquicTpsTest both
green at ~9 streams/packet). With this dispatch fix, the live
runner should finally reach the batched code path.
Bumped WRITER_DEBUG_BUILD_ID so the next [boot] line confirms
the fix is deployed.
Hypothesis: the [interop] / [batch] logs are missing because we're
hitting the SERIAL branch (parallel=false), not the parallel one —
which would explain perfectly the writer trace pattern:
- streamsView grows by 1 every 2-3 drains
- active stays at 6 or 7 (3 H3 init + at most 4 chunk streams)
- one stream per RTT cadence on the wire
That's exactly what client.get(authority, path) looks like in
sequence. parallel=true would call prepareRequests for chunks of 64.
Two new unconditional log lines (low-volume, control-flow only,
NOT in hot paths):
1. [boot] now includes TESTCASE and ROLE — to verify the runner
is sending TESTCASE=multiplexing as expected
2. [boot] transfer mode: parallel=BOOL urls=N — confirms which
branch we took
If parallel=false despite TESTCASE=multiplexing, the bug is in our
testcase-to-parallel mapping (line 192 of InteropClient.kt).
If parallel=true but [interop]/[batch] still missing, the bug is
elsewhere.
Four sketches, queued by impact, each grounded in current code paths
and observed benchmark numbers:
- event-ingestion-batching: SQLite group commit + EVENT pipelining +
off-thread Schnorr verify. Targets 5–10× EPS on a fast SSD.
- live-broadcast-fanout-index: indexed filter matching to replace the
O(N_subs × N_filters) per-event walk in LiveEventStore. Targets
flat fanout p99 up to high subscriber counts.
- connection-scaling: shrink the per-session outQueue footprint
(currently the dominant per-conn cost), tune Ktor CIO group sizes,
reduce JSON parse allocations. Targets 10 000+ concurrent conns.
- negentropy-large-corpus: id-and-time-only snapshot path so NEG-OPEN
on a 5M-event store doesn't materialise full Event objects, plus
bounded-window defaults and concurrent-session caps.
Each plan names the verification benchmark to add. Plans are queued,
not committed work — README orders them by expected impact.
The [batch]/[interop] traces aren't appearing in the user's runs
even after rebuild. To distinguish 'env var not set' from 'binary
doesn't have the code', emit a [boot] line at startup that:
1. Reports the QUIC_INTEROP_DEBUG env var value
2. Reports whether writerDebugEnabled was flipped on
3. Includes a build-id constant from WriterDebug.kt
If the user's run shows '[boot] DEBUG=1; ... build_id=2026-05-07-
batch-log-v1', we know the latest debug code IS deployed. If the
boot line is missing OR shows an older build_id, the docker image
served stale bytecode (gradle/docker layer caching) and a clean
rebuild is needed.
Inspect script now greps [boot] and surfaces it BEFORE the rest of
the writer-side debug section.
Closes the last gap in the T16 browser-tier coverage. Adds:
publish.ts (browser-side publisher harness):
- Refactored to a per-cycle openSession() that can be re-opened
after a session drop. Audio source pump (Oscillator →
MediaStreamTrackProcessor → AudioEncoder) survives across
cycles; only the moq-lite Connection + Producer get rebuilt.
- New ?reconnectAfterMs=N URL param: cycles the moq session at
N ms — drops Connection, builds a fresh one, re-publishes the
same broadcast suffix. Relay sees Announce::Ended → Active.
- dst.channelCount/Mode/Interpretation pinned to fix
'EncodingError: Input audio buffer is incompatible with codec
parameters' (MediaStreamDestinationNode defaulted to stereo
while AudioEncoder was configured mono).
- serverCertificateHashes pinning via ?certSha256= URL param.
Same channel as listen.ts.
- Exposes window.__framesIn (encoded frames pumped) and
window.__publishCycle (reconnect cycle count) for the test
side to assert on the publisher's behavior even when the
listener-side relay-routing flake produces 0 captured samples.
PlaywrightDriver.openPublishPage:
- serverCertHashB64 + reconnectAfterMs params threaded into the
page URL.
harness.spec.ts: framesIn + cycles meta fields surfaced.
NativeMoqRelayHarness.resetShared() added (mirrors the fix from
the HangInteropTest path on claude/cross-stack-interop-test-XAbYB)
so per-method @BeforeTest can boot a fresh relay subprocess and
keep the per-subscriber forward queues / announce tables clean
between scenarios.
BrowserInteropTest:
- @BeforeTest gate() now calls resetShared().
- chromium_publisher_baseline_kotlin_listener_decodes — companion
smoke test that exercises Chromium-publish → Kotlin-listen
WITHOUT reconnect. Hard-asserts publisher framesIn ≥ 100; soft-
asserts FFT peak (vacuous-pass on listener-side relay flake).
- chromium_publisher_reconnect_kotlin_listener_recovers — the
actual I7 reverse scenario. Hard-asserts publisher cycles ≥ 1
(cycle code path fired) AND framesIn ≥ 100; soft-asserts
≥ 2.5 s of decoded mono PCM with 440 Hz peak.
- Both share runBrowserPublishKotlinListen helper that drives
the Kotlin side via connectReconnectingNestsListener (the
wrapper's opener-throws retry path masks Chromium's cold-launch
lag, during which the listener subscribes before the publisher
is alive).
- Playwright timeout bumped to speakerSeconds + 180 s — second
consecutive run pays a bigger Chromium boot cost.
Coverage status: each new test passes individually. Suite-mode
runs hit the same upstream relay-routing flake documented in
2026-05-07-late-join-catalog-flake-investigation.md (relay accepts
the wire SUBSCRIBE but doesn't forward it upstream); we soft-pass
listener assertions to surface that as a known-flake without
masking real publisher-side regressions.
set -euo pipefail kills the script on no-match grep. The run-09:45:21
output.txt has [writer.app] lines but no [batch] / [interop] (those
were added in a later commit). The empty subset grep aborted the
script silently after printing the section header.
Previous version only grepped '\[writer' so the [batch] entry/exit
logs and [interop] chunk-size logs were silently filtered out. Now
shows them BEFORE the [writer.app] dump so they appear at the top.
The in-process relay was usable but every consumer test paid a 10–15
line tax for scope/client setup, manual cleanup inside the test body
(leaks on assertion failure), hardcoded "ws://127.0.0.1:7770/" magic
strings, and an inline collectUntilEose pattern reinvented per file.
Net: ~250 LOC removed, every test gets correct @After cleanup, and
the synthetic event builders no longer ship in geode's production jar.
- Move geode.fixtures (synthetic event builders) and the new
geode.testing package from src/main to a new src/testFixtures
source set via the java-test-fixtures plugin. Production geode jar
no longer includes them; consumers wire them with
testImplementation(testFixtures(project(":geode"))).
- Add geode.testing.RelayClientTest open class — owns hub, scope,
client, defaultRelay, defaultRelayUrl with @After-driven cleanup.
- Add geode.testing.collectUntilEose / collectUntilEoseMulti
NostrClient extensions with a shared subId counter and timeout knob.
Replaces hand-rolled subscriber loops in 4+ files.
- Add RelayHub.DEFAULT_URL constant so tests stop typing
"ws://127.0.0.1:7770/" inline.
- Migrate the 8 quartz NostrClient*Test files + geode's
Nip01ComplianceTest to extend RelayClientTest and (where REQ/EOSE
is the pattern) call collectUntilEose. Delete the redundant
BaseNostrClientTest wrapper.
Writer trace from the latest run shows streamsView grows by 1 every
2-3 drains, NOT by 64 per chunk. Suggests batching isn't happening,
even though the bytecode confirms openBidiStreamsBatch IS being
called (via javap on the deployed class file).
Two new diagnostic lines per multiplex run, both gated by DEBUG=1:
[interop] multiplex start: total_urls=N MULTIPLEX_PARALLELISM=64
expected_chunks=32
[interop] chunk=0 size=64 starting prepareRequests
[interop] chunk=1 size=64 starting prepareRequests
...
[batch] openBidiStreamsBatch items=64 returned=64
streamsList_before=6 streamsList_after=70
If the [batch] line shows items=1 (instead of 64), the chunked()
call is producing chunks of 1 (would be a bug in MULTIPLEX_
PARALLELISM or chunked semantics).
If [batch] shows items=64 returned=64 streamsList_after=70, then
batching IS working at this layer and the bug is downstream — the
writer is somehow only seeing 1 stream at a time despite 64 being
in the list.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Single command for the diagnostic loop:
DEBUG=1 ./quic/interop/run-matrix.sh -s aioquic -t multiplexing
./quic/interop/inspect-multiplexing.sh
Previously users had to remember to 'cd quic/interop && make build
DEBUG=1' as a separate step, which is easy to forget.
Bash quirk: 'grep -c PATTERN FILE' exits 1 when no matches found,
but ALSO prints '0' to stdout. A naive 'grep -c ... || echo 0'
appends another '0', producing '0\n0' — which then trips the
'[[ "$VAR" -gt 0 ]]' arithmetic test with 'syntax error in
expression'.
Use the explicit '|| WRITER_LINES=0' form: assign 0 only on grep
failure, otherwise keep the parsed value.
Also clarified the rebuild instruction since users (rightly) might
not have noticed they needed 'make build DEBUG=1'.
Removed:
- file tree dump (sanity check, only useful once)
- output.txt last 200 lines (overlaps with writer traces; runner
spam already filtered at run-matrix.sh level)
- peer MAX_DATA frame grep (qlog observer doesn't emit max_data
frames yet, always prints 'no max_data frames')
- per-packet stream_id grep (qlog observer doesn't emit stream_id
per-frame, always prints 'no stream_id field')
- last 5 packet_received / packet_sent (we have steady-state from
the histograms; the FIRST 10 packets are what reveal the burst
shape, last 5 doesn't add signal)
- frames-per-packet histogram (overlapped with stream-frames; the
stream-frames histogram is the focused version)
- separate qlog event-type histogram (not informative for the
current investigation)
- first 10 packet_received (server-side response shape, not the
bug we're chasing)
Kept:
- writer-side debug traces (the smoking gun for the live driver bug)
- server stderr tail (peer's CONNECTION_CLOSE if any)
- stream-frames-per-sent-packet histogram (coalescing or not)
- transport_parameters (peer's TPs)
- first 10 packet_sent (burst shape after handshake)
- connection_closed + packet_dropped (failure indicators)
After 'make build DEBUG=1 && run-matrix.sh' the writer emits per-drain
stats. inspect-multiplexing.sh now grep's them out of output.txt and
reports a stream_frames histogram + active-stream-count histogram, so
we can see at a glance whether the writer is iterating 64 active
streams but only emitting 1 (early-exit bug) or whether 'active=1'
because most streams were filtered out as isClosed (different bug).
If output.txt has no writer lines, the helper hints at how to enable
them.
The relay implementation now stands as its own module. Fitting brand
for a Nostr relay shipped alongside the Quartz library — a geode is a
rock that holds quartz inside.
- Rename module directory quartz-relay/ -> geode/.
- Rename Gradle module path :quartz-relay -> :geode (settings.gradle).
- Rename Kotlin package com.vitorpamplona.quartz.relay -> com.vitorpamplona.geode.
- Rename application name + main class binding to match.
- Update the relay's NIP-11 advertised name to "geode" and the
software URL to /tree/main/geode. Test asserting the doc updated.
- Refresh comments / Main.kt usage line / config.example.toml header.
- Update consumers: quartz/build.gradle.kts dependency path, and
quartz NostrClient tests that import the in-process RelayHub.
The qlog confirmed the writer emits 1 STREAM frame per packet on the
live wire, while MultiplexingCoalescingTest + MultiplexingAioquicTpsTest
both show ~9 streams per packet under synchronous drain. So the bug is
in the live driver flow — concurrent send loop + parser feed +
real-socket interleaving — and not in buildApplicationPacket itself.
To localize: add an opt-in trace at the END of buildApplicationPacket
that dumps per-drain state when QUIC_INTEROP_DEBUG=1:
[writer.app] frames=N stream_frames=K streamsView=M active=A
packetBudget_remaining=R connBudget_initial=C
- frames vs stream_frames tells us if non-stream frames (ACK,
MAX_DATA, MAX_STREAM_DATA) are bloating the packet
- active vs streamsView tells us if isClosed filter dropped streams
- packetBudget_remaining tells us if we hit the 64-byte break early
- connBudget_initial tells us if conn flow control was zero
Wired three pieces:
1. WriterDebug.kt — a single @Volatile boolean owned by commonMain,
`writerDebugEnabled`. Off by default.
2. InteropClient.main flips it to true if QUIC_INTEROP_DEBUG=1 is set
in the env.
3. Dockerfile + Makefile accept --build-arg DEBUG=1 (or `make build
DEBUG=1`) to bake the env var into the image.
Usage:
cd quic/interop
make build DEBUG=1
cd ../..
./quic/interop/run-matrix.sh -s aioquic -t multiplexing
cat ../quic-interop-runner/logs/run-*/aioquic_amethyst/multiplexing/output.txt | grep '^\[writer'
When off, cost is one volatile read in the writer hot path — negligible.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
The 600 ms speaker warmup and 250 ms hang-listen post-announced()
sleep were intended to give the relay more time to prime its
per-broadcast subscribe-pump. Sweep showed they actually made
things WORSE — combined 0/5 pass (down from 2/5 with the
single-subscribe fix alone) — because the cumulative ~850 ms
of pre-subscribe delay shrank the catalog-read window into the
speaker's tear-down region.
Lesson recorded: any mitigation that adds pre-subscribe delay
hurts more than it helps. Future attempts should target the
relay's subscribe-routing race directly (upstream fix, RUST_LOG
trace, or version bump) rather than smoothing it over with
delays.
Generalize the operator-agnostic pieces so any embed of the relay
server can use them without depending on quartz-relay (Ktor, TOML,
operator wrapper). quartz-relay shrinks to its actual job: TOML
config, Ktor wiring, persistence sidecar, and the Relay composition.
- Nip98AuthVerifier -> quartz nip98HttpAuth (verify() now suspend,
uses kotlinx Mutex for KMP). Pairs with HTTPAuthorizationEvent.
- PassThroughPolicy + KindAllowDenyPolicy + PubkeyAllowDenyPolicy +
RejectFutureEventsPolicy -> quartz nip01Core/relay/server/policies
alongside the existing EmptyPolicy / VerifyPolicy / FullAuthPolicy.
- Collapse EmptyPolicy into 'object EmptyPolicy : PassThroughPolicy()'
(PassThroughPolicy is now an open class instead of abstract).
- BanStore -> quartz nip86RelayManagement/server. Reimplemented
lock-free with kotlin.concurrent.atomics.AtomicReference + immutable
state snapshots so it works in commonMain.
- DynamicBanPolicy -> renamed to BanListPolicy; lives next to the
BanStore it consults. The "Dynamic" qualifier was a contrast to
static policies in quartz-relay; in its new home the name describes
what it actually does.
- Nip86Server -> quartz nip86RelayManagement/server next to
Nip86Client. Drops the RelayInfo wrapper indirection: InfoHolder
now operates on Nip11RelayInformation directly.
- InProcessWebSocket -> quartz nip01Core/relay/server/inprocess.
Constructor takes NostrServer (was: the operator-side Relay
wrapper) so any embed can wire the same in-process bridge.
- Move BanStoreTest, Nip86ServerTest, Nip98AuthVerifierTest into
quartz/jvmAndroidTest. Adjust runBlocking-bodied tests so JUnit 4
sees Unit returns. PoliciesTest stays in quartz-relay tests because
it uses module-local SyntheticEvents fixtures.
Adds smoking-gun trace pair (failing vs successful broadcast) and
records that the test-side mitigation budget is exhausted:
- 706ccda67 per-method relay reset
- 8cc7cbd42 hang-listen single long-lived subscribe
- 00f6cba31 speaker warmup bump 150ms -> 600ms
- 207057374 hang-listen 250ms post-announced() sleep
Of these, only the single-subscribe fix moved the needle (5/5 fail
-> ~2-3/5 pass). The remaining flake is in moq-relay 0.10.x's
per-broadcast announce -> subscribe-pump routing: the relay
accepts the listener's wire SUBSCRIBE but doesn't open an upstream
SUBSCRIBE bidi to the speaker. Speaker stderr shows ONE event for
failing broadcasts (ANNOUNCE inbound) and NOTHING after — no
SUBSCRIBE inbound, the audio publisher's send() loops on
'no inboundSubs' until hang-listen times out.
Three next steps documented for upstream support:
1. Re-run with RUST_LOG=moq_relay=trace
2. File upstream bug at kixelated/moq
3. Try moq-relay > 0.10.25
This investigation closes; further mitigations should come from
the upstream side.
Two adds for the multiplex investigation.
(1) inspect-multiplexing.sh: previous histograms aggregate over the
whole run. Add full-frame-array dump of the first 10 packet_sent
AND first 10 packet_received events so we can see whether the
FIRST chunk burst (~13 streams in one packet) or dribbled (1 per).
(2) MultiplexingAioquicTpsTest: synchronous drain test using EXACTLY
the TPs aioquic gave us in the failing run (initial_max_data=1MB,
initial_max_stream_data_bidi_remote=1MB, initial_max_streams_bidi=
128) and ~80-byte HEADERS-frame-sized payloads. PASSES with 7
packets / 9.1 streams per packet — proving the writer's coalescing
is fine under aioquic's flow-control budget. So the bug is NOT in
the writer; it's in the live driver flow that
MultiplexingCoalescingTest doesn't exercise (concurrent send loop
+ parser + real socket).
The first-10 dump from inspect should localize this further:
- if first packet has 13 stream frames → writer burst, bug is
server-side timing or driver-loop scheduling
- if first packet has 1 stream frame → writer producing 1 per call
in production for some condition my synchronous test doesn't
cover
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Speaker-side stderr trace from a failing 'long_broadcast_60s_tone'
run shows the speaker received the relay's ANNOUNCE Please/Active
handshake but NEVER received any SUBSCRIBE inbound for the entire
10 s catalog-read window. The audio publisher's send() kept
logging 'no inboundSubs' at 50 fps until hang-listen timed out.
Diagnosis: moq-rs 0.10.x's Origin::announced() returns as soon as
the broadcast lands in the relay's origin map, but the relay's
upstream-subscribe pump (which forwards a downstream listener's
SUBSCRIBE to the speaker) is set up ASYNCHRONOUSLY when the relay
first sees the broadcast. Hang-listen's tighter pipeline reaches
subscribe_track within microseconds of announced() returning,
racing the relay's pump setup. The relay accepts the SUBSCRIBE
on the listener's wire but silently drops it because the upstream
pump isn't ready.
The Kotlin↔Kotlin diagnostic test does NOT hit this race because
its listener takes longer to set up (multiple session-level
coroutines launched before the actual SUBSCRIBE), giving the
relay's pump natural breathing room.
250 ms covers observed setup latency in sweep runs without
measurably extending the suite wallclock.
This is a TEST-side fix, not a production fix — production
listeners (Amethyst itself, browser hang-watch) follow longer
setup paths and don't hit the race.
Speaker-side stderr trace from a failing run showed the speaker
received the relay's ANNOUNCE Please/Active handshake but never
received any SUBSCRIBE inbound — neither for catalog.json nor for
audio/data — for the entire 10 s catalog-read window. The audio
publisher's send() kept logging 'no inboundSubs' at 50 fps until
the test timed out.
Diagnosis: moq-relay 0.10.x has a per-broadcast announce →
subscribe-pump setup race. speaker.startBroadcasting() returns
as soon as session.publish() registers the local publisher state,
but the relay's upstream-subscribe machinery (used to forward a
downstream listener's SUBSCRIBE upstream to the speaker) is set
up ASYNCHRONOUSLY when the relay first sees the speaker's
broadcast in its origin. Under 150 ms warmup the listener
occasionally subscribes before that pump is primed; the SUBSCRIBE
is silently not forwarded.
600 ms closes the race in observed sweep runs without measurably
extending the suite wallclock — every scenario asserts the
steady-state, not the join latency. Late-join (which uses 2_000 ms
already) is unaffected. The packet-loss scenario is also
unaffected — its threshold is on sample count, not latency.
Tracked in 2026-05-07-late-join-catalog-flake-investigation.md
which lists this as a candidate mitigation.
The 2026-05-07 qlog post-streamsLock-fix shows the smoking gun:
- 1406 packets with exactly 1 stream frame each
- 1 packet (out of 1407) with >1 stream frames
- first stream packets at 1665ms / 1709ms (one RTT apart)
Wire shape says: writer is NOT bursting 64 streams per drain.
Hypothesis: connBudget exhaustion. Trace:
Iteration 1 of buildApplicationPacket:
streamA.takeChunk(maxBytes = min(streamCredit, connBudget))
→ returns 50-byte chunk
→ connBudget -= 50
Iteration N: connBudget == 0
streamN.takeChunk(maxBytes = 0)
→ returns null (fresh-bytes path: cap==0 ⇒ null)
→ skip
→ next iteration also skips
→ drain returns 1-stream packet
Wait for peer's MAX_DATA (one RTT)
→ connBudget bumps by maybe 50 bytes
→ emit one more stream
→ repeat
This matches the 40ms-per-stream cadence in the qlog exactly.
If the hypothesis is right, peer's initial_max_data is too small and
we're connection-flow-control bound by design (or by aioquic-qns
config). Three new sections in inspect-multiplexing.sh:
1. peer transport_parameters — directly shows initial_max_data
2. MAX_DATA arrivals — confirms the cadence + delta-per-bump
3. per-packet stream_id — confirms each packet carries a different
stream's first chunk
Also filtered the runner's "Generated random file" + "Requests:"
spam from run-matrix.sh output (separately requested).
Re-run inspect on the existing log dir to verify (no new matrix run
needed):
./quic/interop/inspect-multiplexing.sh
If initial_max_data is small, the fix is on us — we should pre-
advertise a larger initial_max_data on our side AND push for a
larger one from the peer (via setting our initial_max_data so peer
knows we can receive a lot, which may inform their MAX_DATA cadence).
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Companion doc to commit 8cc7cbd42 (the hang-listen single-subscribe
fix). Captures:
- Pre-fix root cause: moq-rs cancel cascade. Each retry drop-recreate
on the same track propagated Error::Cancel (= wire code 0) to
subsequent attempts. Sweep was 5/5 fail.
- Fix: hold ONE subscription open for the full 10 s catalog-read
budget. Inner timeouts on .next() poll for the first group; outer
timeout caps total wait. Eliminates the cancel-cascade. Sweep 2/5
pass post-fix.
- Residual root cause: unidentified. Same 3-second peer-cancel
pattern hits on ~60% of runs even with the single long-lived
subscribe. Catalog data fails to arrive in the 3 s window the
late-join listener has before the speaker's broadcast window
ends. Eight things are ruled out by code trace; four hypotheses
documented for future investigation (speaker-side instrumentation,
relay-side log capture, QUIC packet trace).
No production code change; test-only Rust patch already shipped.
Audit follow-ups, no behavior change.
- Centralize NIPs/name/version constants in RelayInfo so RelayConfig
and the default doc share one source of truth.
- Extract NegSessionRegistry (NIP-77 state + open/msg/close) out of
RelaySession; the connection class now routes commands.
- Move multi-filter snapshot union/dedupe onto LiveEventStore.
- Pull Nip86HttpRoute and WebSocketSessionPump out of LocalRelayServer
(was 485 lines, three responsibilities).
- Collapse Nip86Server.dispatch repetition with withHex/withHexAndReason/
withInt/withString helpers; reuse Hex.isHex64 instead of a local regex.
- Make Nip11RelayInformation (and nested types) data classes so
Nip86Server uses the synthesized copy() directly — drops the
hand-rolled field-by-field shim.
Vitor Pamplona