quinn is now treated as a flawless-required interop target alongside
aioquic, picoquic, and quic-go. Most Rust-based Nostr/MoQ relays our
users run their servers on are built on quinn, so an interop regression
there is a user-visible regression.
Validated by a 3-round flakiness sweep (1 full matrix + 2 audio-critical
subsets) — zero result flakiness across 528 test executions across all
four peers, with two environmental docker-compose stall classes documented
separately.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
Pre-fix, [QuicConnection.initiateKeyUpdate] only checked that 1-RTT
keys were installed — which fires when the TLS handshake derives
Finished, well before HANDSHAKE_DONE arrives. RFC 9001 §6.1 + §4.1.2
require the CLIENT to consider the handshake confirmed (HANDSHAKE_DONE
received) before rolling KEY_PHASE; quinn / quic-go / picoquic
correctly close the connection with PROTOCOL_VIOLATION ("illegal
packet: key update error") when an early update arrives.
The interop runner's keyupdate testcase against quinn flushed this:
the client polled `status == CONNECTED` (which flips on TLS Finished
via `onHandshakeComplete`) and called `initiateKeyUpdate()` before
HANDSHAKE_DONE landed. ~33% repro rate; the rest of the runs HANDSHAKE_DONE
happened to arrive in the gap between the status check and the
update.
Fix:
- Add `QuicConnection.handshakeConfirmed: Boolean` flipped only by
the parser when a HANDSHAKE_DONE frame is processed.
- Add `awaitHandshakeConfirmed()` for callers that need the
spec-confirmed state.
- Gate `initiateKeyUpdate()` on `handshakeConfirmed` (returns
false otherwise — same shape as the existing app-keys-not-yet
branch).
- Tighten `triggerPathMigrationLocked` to also gate on
`handshakeConfirmed` (RFC 9000 §9.1: same confirmation
requirement). Pre-fix it gated on `handshakeComplete`, which
flips at TLS-Finished too.
- InteropClient's keyupdate flow now waits on
`awaitHandshakeConfirmed` (with a 2s upper bound) rather than
polling `status == CONNECTED`.
The test fixture in ConnectedClientFixture.newConnectedClient now
delivers HANDSHAKE_DONE by default — most tests want the
production "fully ready" state. New `deliverHandshakeDone = false`
parameter for tests that need to exercise the pre-confirmation
window (KeyUpdateClientInitiatedTest).
Tests:
- KeyUpdateClientInitiatedTest:
initiateKeyUpdateBeforeHandshakeDoneIsRejectedAndDoesNotRotateKeys
initiateKeyUpdateAfterHandshakeDoneRotatesBothDirections
awaitHandshakeConfirmedSuspendsUntilHandshakeDone
triggerPathMigrationBeforeHandshakeDoneReturnsNotConnected
Verified against the live interop runner — 5/5 against quinn,
3/3 against quic-go, 3/3 against picoquic (pre-fix: ~33% pass rate
against quinn).
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
The amplificationlimit testcase scenario drops client→server packets
2–7. Recovering past 6 consecutive drops via RFC 9000 PTO doublings
(0.3+0.6+1.2+2.4+4.8+9.6 ≈ 19s) is more than the previous 10s
budget allowed — we declared handshake_failed mid-recovery. Bumping
to 30s matches the multiconnect handshake budget and gives clean
PTO headroom.
Fixes: amplificationlimit ✕→✓ vs picoquic. No regression vs quinn
(was already passing at ~14s). Normal handshakes complete in <1s
so the bump is invisible outside lossy paths.
Still fails: amplificationlimit vs quic-go and msquic. Their
server-side handshake-progress watchdog gives up at ~10s of silence
regardless of our budget. The proper fix is RFC 9002 §6.2.4 — send
2 ack-eliciting packets per PTO probe instead of 1, halving the
recovery time for consecutive drops. That's a writer-side change,
deferred.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
`ls -1dt run-*` returns both the per-run directories AND the
`.stdout.log` files run-matrix.sh tees alongside them, interleaved by
mtime. `head -n 1` could land on a `.stdout.log` regular file, after
which the rest of the script trying to walk subdirectories under it
silently produced empty output ("no <pair> dir under …"). Walk the
listing instead and pick the first entry that is actually a directory.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
`LC_CTYPE=C tr -dc '[:alnum:]' </dev/urandom` in the upstream runner's
certs.sh trips "tr: Illegal byte sequence" on macOS — LC_CTYPE alone
doesn't override the runtime locale chain. Only the amplificationlimit
testcase exercises this loop (chain length > 1 → fakedns SAN inflation),
but if it aborts the runner stops the whole matrix BEFORE any later
test in TESTCASES_QUIC runs: handshakeloss, transferloss,
handshakecorruption, transfercorruption, ipv6, v2, rebind-port,
rebind-addr, connectionmigration, and the goodput/crosstraffic
measurements all silently never execute. The post-mortem summary
shows the 12 testcases that ran before the abort and looks deceptively
complete.
Add an idempotent `sed` step to run-matrix.sh that rewrites the line
to `LC_ALL=C tr` on every invocation, plus a plan-file note so the
next person hitting the deceptive summary doesn't repeat the
diagnosis. The patch is a working-tree edit to ../quic-interop-runner/,
not a fork; re-applied on every clone.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
Two coupled gaps surfaced when running the runner's zerortt testcase
against aioquic (picoquic + quic-go already passed because they
fault-tolerate harder).
1) Wire format. The 0-RTT pre-handshake batch was sending raw
"GET /<path>\r\n" on bidi streams regardless of ALPN. aioquic's
h3 server accepts 0-RTT at the TLS layer (early_data extension
echoed in EE) but its h3 layer silently drops bidi streams whose
payload isn't a valid HEADERS frame — server log shows N "Stream
X created by peer" lines and zero responses. Switch the
pre-handshake builder to fork on the cached ALPN: h3 →
Http3GetClient (three uni control streams + HEADERS-framed bidi
requests via prepareRequests); else → HqInteropGetClient (raw
text). The post-handshake side then reuses the pre-handshake
client and collects responses via awaitResponse(handle), so 1-RTT
replay (after rejection) lands on the right parser.
2) TLS-layer rejection. When the server skips the early_data
extension in EncryptedExtensions, the client must replay all
in-flight 0-RTT app data through the 1-RTT keys (RFC 9001 §4.6.2).
TlsClient now exposes earlyDataAccepted, set in the
WAITING_ENCRYPTED_EXTENSIONS branch. QuicConnection's
onApplicationKeysReady checks it: if 0-RTT was offered but EE
didn't carry early_data, we requeueAllInflightStreamData() +
cryptoSend.requeueAllInflight() + sentPackets.clear() BEFORE
installing 1-RTT keys, so the next writer drain ships the
identical stream/CRYPTO bytes under 1-RTT protection. Same
stream handles, same response collection — invisible to the
request layer.
Result, ./quic/interop/run-matrix.sh -t zerortt:
aioquic ✓(Z)
picoquic ✓(Z)
quic-go ✓(Z)
Resumption sweep regression-clean across all three.
334 :quic unit tests pass.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
Closes the matrix gap. The TLS layer now drives a full RFC 9001 §4.10
0-RTT path:
- Resumption ClientHello includes the empty `early_data` extension
when the cached TlsResumptionState carries maxEarlyDataSize > 0
(parsed from the prior connection's NewSessionTicket early_data
extension).
- TlsClient.start, post-CH-transcript-snapshot: derive
client_early_traffic_secret + surface via
TlsSecretsListener.onEarlyDataKeysReady.
- QuicConnection.zeroRttSendProtection slot installed in the listener
and cleared in onApplicationKeysReady (RFC 9001 §4.10 forbids 0-RTT
use after 1-RTT keys are available).
- TlsResumptionState now also carries peerTransportParameters +
negotiatedAlpn from the issuing connection so a resumed connection
can pre-load flow-control limits (initial_max_data,
initial_max_streams_bidi, etc.) BEFORE the new ServerHello arrives.
Without this, peerMaxStreamsBidi=0 and pre-handshake stream
creation fails. RFC 9001 §7.4.1 explicitly carves out which
parameters MUST be remembered for 0-RTT vs which MUST NOT (CIDs,
ack delay).
- QuicConnectionWriter.buildApplicationPacket: dual 0-RTT / 1-RTT
path. When 1-RTT keys are absent but 0-RTT keys are present, build
a long-header type=0x01 ZERO_RTT packet (sharing the Application
packet number space per RFC 9000 §17.2.3) and skip ACK frames
(server cannot ACK 0-RTT-level packets). Once 1-RTT installs, the
writer naturally falls through to short-header.
- InteropClient runResumptionTest gains a `zerortt` flag. When set,
iter 0 fetches NOTHING (just establishes + waits the existing
200ms post-handshake window for the NewSessionTicket to arrive +
closes), and iter 1 opens all URLs as bidi streams + enqueues GETs
+ driver.wakeup BEFORE awaitHandshake so the writer ships them as
0-RTT packets coalesced with (or right after) the resumed
ClientHello in the first datagram.
Results:
- ✓ picoquic: 0-RTT 10682 bytes, 1-RTT 238 bytes — within the
runner's 50% / 5000-byte 1-RTT cap.
- ✓ quic-go: 0-RTT 10693 bytes, 1-RTT 1488 bytes — same.
- ✕ aioquic: server rejects our 0-RTT (only 3 STREAM frames come
back from 40 GETs sent); no rejection-fallback wired (a real
implementation would track which app data was sent in 0-RTT and
replay in 1-RTT after EE comes back without early_data
acceptance). Out of scope for this pass.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
Closes the gap that left the runner's `resumption` testcase as the
last unsupported standard test. The TLS layer now:
- Derives `resumption_master_secret` (RFC 8446 §7.1) right after
appending client Finished to the transcript. Cached on the key
schedule so it can seed PSK derivations from any subsequent
NewSessionTicket the server emits.
- Parses NewSessionTicket bodies (RFC 8446 §4.6.1) when they arrive
post-handshake at Application level. For each ticket: derive the
per-ticket PSK via `HKDF-Expand-Label(resumption_master_secret,
"resumption", ticket_nonce, 32)` and surface a self-contained
TlsResumptionState (ticket bytes + PSK + cipher suite + age-add +
issued-at) through a new TlsSecretsListener.onNewSessionTicket
callback. QuicConnection's tlsListener forwards to a public
onResumptionTicket lambda the application sets.
- On a fresh TlsClient construction with a non-null `resumption`
argument: seed the early secret from the cached PSK
(`HKDF-Extract(IKM=PSK, salt=0)` — the Quartz Hkdf.extract
signature is `(IKM, salt)` despite the misleading first-parameter
name; non-PSK deriveEarly passes zeros for both so the order
didn't matter and the bug only surfaced now), build the resumption
ClientHello with `pre_shared_key` as the LAST extension carrying a
single identity (the cached ticket) and a binder over the
PartialClientHello, splice the binder bytes into the encoded
message after a one-shot SHA-256 hash of bytes 0..len-35.
- State machine: when ServerHello carries `pre_shared_key` with the
selected_identity we offered (we only ever send identity index 0,
any other value is a hard fail), latch `pskAccepted = true`.
WAITING_CERTIFICATE_OR_FINISHED then accepts Finished without the
Certificate/CertificateVerify pair the full-handshake path
requires — the PSK itself transitively authenticates the server
via the prior issuing connection.
- If we offered PSK but the server didn't pick it (full-handshake
fallback), hard-fail. The fallback path needs to clear the
PSK-seeded early secret and re-run derivation against zeros, which
is real work; the runner's resumption testcase requires server
acceptance anyway, so this gate isn't load-bearing for matrix
green. Production callers that care about the fallback can wire
it later.
InteropClient adds a `runResumptionTest` that splits the runner's
URL list in half across two sequential connections — first runs a
full handshake and captures the NewSessionTicket via
onResumptionTicket, second runs the PSK handshake with the cached
state. ✓ R against aioquic, picoquic, quic-go.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
The runner's keyupdate testcase has TESTCASE_CLIENT=keyupdate (server
runs plain transfer). The runner verifies the pcap shows BOTH sides
emit packets in phase 1 — pre-fix our receive-only key-update path
satisfied a server-initiated rotation but not this test, because
aioquic's transfer-server doesn't rotate spontaneously. Result: 0
phase-1 packets either direction, "Expected to see packets sent with
key phase 1 from both client and server".
QuicConnection.initiateKeyUpdate() (now public) is the send-side
analogue of commitKeyUpdate: derives next-phase secrets for both
directions via HKDF-Expand-Label "quic ku", installs as live
(reusing old HP keys per RFC §6.1), flips currentSendKeyPhase +
currentReceiveKeyPhase together. The receive side has to roll too
because the peer responds in the new phase — leaving currentReceive
at 0 would force feedShortHeaderPacket to take the
deriveNextPhase-then-commit path on the response and orphan the
keys we just installed in previousReceiveProtection.
InteropClient adds an `initiateKeyUpdate` flag to runTransferTest;
the keyupdate dispatch sets it true. After awaitHandshake (TLS done,
1-RTT keys derived) the flag-flow polls briefly for status=CONNECTED
(HANDSHAKE_DONE arrived → handshake confirmed per RFC 9001 §6.5
prerequisite) before calling initiateKeyUpdate, then sends the GET.
The GET goes out in phase 1, the server mirrors phase 1 in its
response, runner is satisfied.
Also added ecn, amplificationlimit, blackhole to the runTransferTest
dispatch (all reuse the plain-transfer flow; the runner verifies
behaviour via pcap independent of any client-side dance). aioquic
phase 3 result: ✓(retry, keyupdate, blackhole),
?(resumption, zerortt, ecn — feature gaps requiring session tickets,
0-RTT, and IP-layer ECT codepoints respectively),
amplificationlimit blocked by a runner-side cert-gen bug on macOS
(tr LC_CTYPE=C doesn't suppress UTF-8 errors, the chainlen=9 cert
inflation step fails).
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
After the handshake timeout bump and the faster PTO landed, the last
remaining flake was picoquic's handshakecorruption iter ~35: the
handshake recovers from 2-3 PTO rounds and smoothed_rtt is left at
~1s (RFC 9002 §5.2 takes the sample from the largest-acked packet's
SEND time, and that's the PTO retransmit, not the original).
post-handshake PTO is then 3s+, doubling. Three doublings under 30%
bit-flip eat 24s before the GET retransmit lands — 30s is a cliff.
60s gives the slow-recovery iterations real headroom. Total budget:
50 iters × ~3s typical = 150s, plus a few 60s outliers, comfortably
within the runner's 300s testcase budget.
Verified clean: aioquic, picoquic, quic-go each pass all 7 tests
(handshake, multiplexing, longrtt, transferloss, transfercorruption,
handshakeloss, handshakecorruption). 21/21.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
The 10s HANDSHAKE_TIMEOUT and 60s TRANSFER_TIMEOUT were tuned for
single-connection tests against well-behaved peers. multiconnect under
30% packet drop / bit-flip routinely needs three to four PTO rounds
just for the handshake — the 10s default hit "handshake_failed" mid-
recovery on the unlucky iter. Bump per-iter handshake to 30s and
transfer to 30s; 50 iters × ~5s typical = ~250s within the runner's
300s testcase budget, with headroom for the slow-recovery iters.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
Pre-fix QlogWriter only flushed in close(); the 60s runner timeout
SIGKILLs the JVM before runTransferTest reaches its qlogWriter?.close().
On every failed quic-go transferloss, the trace ended at exactly 32768
bytes — 4 × 8KB BufferedWriter blocks — masking ~50 seconds of
late-connection behavior. Made every interop debugging session start
with "is this a connection wedge or a qlog wedge?".
Per-event flush was the original shape and was removed in 99a1a91de
because it caused multi-ms stalls on macOS Docker virtualized
filesystems (broke handshakes mid-flight). 250 ms is the compromise:
cheap enough to not stall the send path, fine-grained enough to
capture per-PTO behavior under heavy loss.
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
Two interop-runner gaps closed in one InteropClient pass plus a
QuicConnection snapshot helper:
1. multiconnect testcase. The runner's handshakeloss /
handshakecorruption tests reuse TESTCASE_CLIENT=multiconnect — 50
sequential connections, each fetching a 1KB file under 30% packet
drop or bit-flip, with the runner verifying _count_handshakes()==50
in the pcap. Pre-fix our InteropClient dispatch returned 127 (skip)
for "multiconnect", so both tests showed as ?(L1, C1). Added
runMulticonnectTest: loops fresh socket + conn + driver + GET +
close per URL. Per-iteration qlog files at $QLOGDIR/client-N.sqlog
so a stuck iteration leaves a focused trace.
2. multiplex pacing against quic-go. Pre-fix the parallel path
chunked the URL list into fixed groups of MULTIPLEX_PARALLELISM=64.
Worked against aioquic + picoquic (initial_max_streams_bidi=128)
but blew up against quic-go (advertises 100, ramps slowly via
MAX_STREAMS_BIDI bumps): second chunk pushed cumulative used past
limit, threw QuicStreamLimitException. Now each iteration takes
min(MULTIPLEX_PARALLELISM, peerMaxStreamsBidi - used). When budget
hits 0, brief 50ms idle waits for the peer's bump.
New QuicConnection.localBidiStreamsUsedSnapshot() exposes the
consumed-side counter; combined with the existing
peerMaxStreamsBidiSnapshot() the InteropClient computes the live
available budget without holding streamsLock.
Result against quic-go: H, M, LR, L2, C2, C1 pass; was 0/7 at
session start (handshake itself failed pre-ALPN-fix), 4/6 after
key-update fix, now 6/7. Only L1 (handshakeloss) remains as
multiconnect-under-30%-drop flake (same flake picoquic shows).
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
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.
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.
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.
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.
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 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
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
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
The matrix run on 2026-05-07 showed the same 1-stream-per-packet wire
shape AFTER the streamsLock fix — meaning the lock fix was correct
but didn't address the root cause. Adding diagnostics so the next
investigation has data to work with, instead of more theorizing.
Two pieces, both quiet by default:
(1) inspect-multiplexing.sh: histograms over packet_sent events that
answer "is the writer coalescing or not" without re-running the
matrix. Re-run on the existing run dir and we get:
- frames-per-packet histogram: should be skewed high (≥4) if
coalescing is working; skewed to 1 if regressed
- stream-frames-per-packet histogram: same shape but only
counting STREAM frames (filters out ack-only packets)
- first 30 packet_sent timestamps: did we burst 64 streams in
<50ms or did we dribble them out one-RTT-per-stream?
(2) InteropClient: per-chunk wall-clock split (enqueue ms vs
responses ms vs cumulative). Behind QUIC_INTEROP_DEBUG=1, off in
matrix runs by default. Tells us whether the bottleneck is
client-side (long enqueue ms — writer can't pack the batch) or
server-side (long responses ms — server processes streams
serially).
These together should localize bug to either:
A) our writer regressing one-stream-per-packet under live driver
load (despite MultiplexingCoalescingTest passing synchronously)
B) aioquic-qns serving 32-byte files from disk on macOS Docker FS
at 30-40ms each, so 32 chunks * 64 streams sequential = 60s
If (A), we have a writer bug to fix. If (B), the test runner is the
bottleneck and we should validate against a faster server (quic-go).
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Audit follow-up. Two cleanups consolidated into one commit since they
share the goal of "make the lock contract obvious from the API".
(1) Remove LevelState.levelLock entirely.
The lock-split refactor introduced a per-level Mutex with a docstring
claiming the writer/parser would acquire it around encode + sentPackets
record + ACK observation. Neither actually does. SendBuffer's internal
synchronized(this) is what serializes cryptoSend mutations against
takeChunk and markAcked. handlePtoFired's levelLock acquisition was
the only production usage and it serialized only against itself.
Removed:
- LevelState.levelLock
- handlePtoFired's withLock wrapper (now a non-suspend fun)
- All docstring references to a third lock domain
The pre-existing sentPackets HashMap race (writer mutates under
streamsLock, parser reads without sync) is unchanged — out of scope
for this PR. Acquisition order is now `lifecycleLock → streamsLock`,
flat.
(2) Add openBidiStreamsBatch + openUniStreamsBatch — the bug-resistant
high-level API for the prepareRequests / moq audio-rooms patterns.
The previous shape required callers to manually do
`streamsLock.withLock { repeat(N) { openBidiStreamLocked() ... } }`.
That contract regressed twice on this very branch: once held the wrong
lock (lifecycleLock alias), once skipped the wrap entirely. Both shapes
silently emitted one STREAM per packet under multiplex load.
The new API encapsulates the lock + the per-item init lambda:
conn.openBidiStreamsBatch(items) { stream, item ->
stream.send.enqueue(encode(item))
stream.send.finish()
Handle(stream)
}
Callers physically cannot hold the wrong lock. Migrated:
- Http3GetClient.prepareRequests
- HqInteropGetClient.prepareRequests
Also added `openUniStreamLocked` + `openUniStreamsBatch` symmetric to
the bidi versions. moq audio-rooms eventually wants to open many uni
streams in burst; the same one-stream-per-packet bug lurks if every
open serializes through its own lock acquisition.
`openBidiStreamLocked` / `openUniStreamLocked` remain public (with
their `check(streamsLock.isLocked)` guards) for the rare custom-batch
callers that need to mix bidi+uni opens under a single hold. Most
callers should use the *Batch variants going forward.
Test coverage extended:
- openBidiStreamsBatch happy path
- openUniStreamLocked throws without streamsLock
- openUniStreamsBatch happy path
Six tests in BatchedOpenLockContractTest now pin the contract.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Audit of recent multiplex / PTO commits surfaced three concrete
improvements:
1. **Pre-encode requests outside streamsLock** in both prepareRequests
impls. QPACK encoding (Http3GetClient) and string formatting
(HqInteropGetClient) are non-trivial under multiplex load — 1999
paths means we were holding streamsLock across all 32 chunks ×
~2KB of QPACK encoding per chunk = ~64 KB of CPU work serialised
against the send loop. Now done outside the lock.
2. **Fix O(N²) byte merging in MultiplexingRoundTripTest.** Previous
shape allocated a new array per STREAM frame; for real-size
payloads this would dominate test runtime. Switched to a per-
stream MutableList<ByteArray> joined once at the end.
3. **Pin coalescing end-to-end in MultiplexingRoundTripTest.**
Pre-existing test verified per-stream content arrived but said
nothing about the wire shape. Added totalDatagrams ≤ 12 assertion
so the matrix's "one stream per datagram" failure mode would
break the test instead of passing silently.
Audit also surfaced two non-actionable items, flagged for future
cleanup but not changed in this commit:
- LevelState.levelLock docstring claims writer/parser acquire it
around sentPackets mutations; in practice neither does. The
handlePtoFired call that takes levelLock currently serialises
only against itself; SendBuffer's internal synchronized is what
prevents the actual cryptoSend race. Kept the call (matches the
documented design intent and future-proofs against the writer
actually taking levelLock) but the docstring is stale.
- openBidiStreamLocked's check(streamsLock.isLocked) catches "no
lock" and "wrong lock" callers but not "another coroutine holds
streamsLock and I'm calling without holding it" — kotlinx Mutex
doesn't expose owner-aware checks without an explicit owner arg
we don't pass. Acceptable since the bug we just fixed and any
future regression in the same shape are caught.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
aioquic interop multiplexing 2026-05-06 qlog post-mortem:
- 2898 packets sent in 60s, each carrying ONE STREAM frame
- server log: streams created/discarded strictly serially, ~30-40ms apart
- 1421/2000 files completed before the runner's 60s timeout
- shape ≈ 1 RTT per stream — wire was emitting one stream per datagram
Cause: Http3GetClient.prepareRequests + HqInteropGetClient.prepareRequests
both did `conn.lock.withLock { ... openBidiStreamLocked() }`. Post the
lock-split refactor `conn.lock` is the deprecated alias for lifecycleLock.
The writer's drainOutbound takes streamsLock — not lifecycleLock — so the
send loop interleaved between every two openBidiStreamLocked calls,
draining one stream's data per pass.
Fix:
1. Both prepareRequests impls now use conn.streamsLock.withLock.
2. openBidiStreamLocked now `check`s streamsLock.isLocked at entry
so this can never silently regress again — calling it without the
lock (or with the wrong lock) throws IllegalStateException with
a message naming streamsLock as the lock to acquire.
3. New BatchedOpenLockContractTest pins the contract:
- calling openBidiStreamLocked WITHOUT any lock throws
- calling openBidiStreamLocked while holding lifecycleLock throws
(the exact regression shape)
- calling openBidiStreamLocked while holding streamsLock works
(happy path)
The runtime check is the regression-proof part: future callers physically
cannot hold the wrong lock without the test (and prod) blowing up at the
first call site.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Runner persists:
<case>/output.txt — runner stdout/stderr (+ client logs)
<case>/client/qlog/*.sqlog — qlog under client/qlog/, not client/
<case>/server/stderr.log — server stderr (CONNECTION_CLOSE reason)
Plus targeted grep for the events we actually need to localize a
multiplexing failure:
- last 5 packet_received / packet_sent (where did the flow stall)
- connection_closed (peer error code + reason)
- packet_dropped (sign of decrypt fails / unknown CID / etc.)
Layout varies by runner version; print the tree so we can see what
the runner actually wrote (qlog/pcap/log filenames, sizes) before
guessing at paths.
Pulls the diagnostics needed to localize a multiplexing failure:
- tail client/log.txt (per-stream errors, final outcome)
- tail server/log.txt (peer's CONNECTION_CLOSE reason)
- tail client qlog (frame-level event sequence)
- count downloaded files (how many of N actually finished)
- qlog event-type histogram (e.g. "lots of packet_dropped",
"no stream_state_updated past t=30s", etc.)
Resolves the most recent run-* dir under ../quic-interop-runner/logs
automatically — no need to copy-paste paths after every run.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Diagnosis from yet another qlog round: streams/packet still ~1 even
with the prepareRequest/awaitResponse split. Root cause: openBidiStream
is suspend due to lock.withLock, and each call releases the lock between
iterations. The send loop is queued on the lock; it grabs it the moment
we release, drains the one stream of data we just enqueued, and the
next prepareRequest call has to re-acquire after the send loop releases.
Net: one stream per drain per packet, same useless coalescing as before.
Fix is structural:
- QuicConnection.openBidiStreamLocked() — public, lock-not-acquired
version of openBidiStream. Caller MUST hold conn.lock.
- GetClient.prepareRequests(authority, paths) — batch API that
holds conn.lock once, opens + enqueues all N streams in a single
critical section, releases. Send loop can't interject; when it
next drains it sees ALL N streams' data ready and packs them
into coalesced packets.
- Http3GetClient + HqInteropGetClient: implement prepareRequests
using openBidiStreamLocked under conn.lock.withLock { ... }.
- InteropClient's chunked-multiplex loop: uses prepareRequests
(batch) instead of N x prepareRequest.
Single-stream paths still use prepareRequest / get(); behavior unchanged.
The fundamental architectural improvement (per-stream / per-level lock
split, or actor-model dispatch) is a follow-up; this commit gets us
the throughput we need from the existing single-mutex shape by holding
the lock for the full chunk's worth of work.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Diagnosis from qlog timeline pattern: send packets clustered ~37ms
apart (sim RTT) but each cluster contained only ONE stream's data
(80-byte packets despite 1452-byte capacity). 1457 GETs in 58s, ~25
streams/sec.
Root cause: race between client.get()'s per-call driver.wakeup() and
the dispatcher scheduling the OTHER 63 coroutines. Sequence:
1. c1 acquires conn lock, enqueues request, wakes send loop, releases
2. Send loop wakes, queues for lock — other 63 coroutines haven't
started yet (dispatcher hasn't picked them up)
3. Send loop acquires lock alone, drains c1's data into one tiny
packet, releases
4. c2 finally starts, acquires, enqueues, wakes...
→ one stream per packet, no coalescing
Fix: split GetClient.get() into prepareRequest (open + enqueue + FIN,
synchronous, no wake) and awaitResponse (collect, async). Multiplex
chunk loop now:
Phase 1: serial prepareRequest for every URL in the chunk (64 in
sequence, each adding to send buffers)
Phase 2: SINGLE driver.wakeup() — by now all 64 streams have data
queued; send loop drains them all in coalesced packets
Phase 3: parallel awaitResponse with per-stream timeout
Predicted throughput jump: 25 streams/sec → ~1000+/sec (sim RTT-bound
at ~30ms per round trip = 64 streams per RTT = 2100/sec ceiling).
Single-request paths (transfer / chacha20 / etc) keep using the
default GetClient.get() which still wraps prepare+await; no behavioral
change there.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Diagnosis (qlog): 1361 GETs in 58s = 23/sec, but only 2618 packets sent
in that window — 0.5 GETs per packet. We were sending nearly empty
packets one at a time, not coalescing requests.
Root cause: stream.send.enqueue + stream.send.finish() don't wake the
send loop. The send loop suspends on sendWakeup until either an
inbound packet arrives or the PTO timer fires (~1s). For our chunked
parallel multiplexing path:
1. enqueue 64 GETs into 64 streams
2. send loop is asleep (last drain happened on previous chunk)
3. wait ~1s for PTO before any of them go on the wire
4. server processes, replies, our read loop wakes the send loop
5. send loop drains ACKs (no new requests yet)
Each chunk wasted ~1s of PTO wait. With ~21 chunks at 1s each plus
RTTs and server processing, throughput floored at ~23 streams/sec.
Fix: pass QuicConnectionDriver to Http3GetClient + HqInteropGetClient
constructors. After stream.send.finish(), call driver.wakeup() to
nudge the send loop. The first request of each chunk now leaves
within microseconds instead of waiting for PTO.
Predicted throughput: 600+ streams/sec (RTT-bound at 30ms per chunk
of 64 = 2100/sec ceiling; CPU and lock contention drop it to ~600).
1999 streams in 3-5s instead of timing out at 60s.
The architectural fix would be having stream.send.enqueue auto-wake
via a callback set during stream creation. That's the cleaner shape;
this commit takes the minimal path: explicit driver-passed wakeup
from interop client code where the throughput matters.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Vitor Pamplona