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
Round-2 audit of the openBidiStreamsBatch / openUniStreamsBatch landing.
(1) Tests overpromised. The previous "holds streamsLock for the whole
batch" test only verified the API didn't crash and stream ids were
unique. A future regression that released the lock between opens
(the 2026-05-06 bug shape) would not break it.
Added `assertTrue(client.streamsLock.isLocked)` inside both batch
init lambdas. Now the test name matches what's verified.
(2) `*Batch` docstrings didn't warn that `init` runs under
streamsLock. A naive caller might do encoding / IO inside, defeating
the lock-hold-time goal that motivated pre-encoding outside. Added
the warning + the canonical caller shape (encode outside, enqueue
inside) to both function docs.
(3) Empty-batch corner: an empty `items` list was still acquiring the
lock and entering withLock. Added an `if (items.isEmpty()) return
emptyList()` short-circuit. New test pins the contract — `init`
must not run for an empty batch.
Test count: 6 → 7. All green; no production-API change.
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
The runner's `multiplexing` testcase opens N parallel bidi streams,
each downloading one file, and asserts every file's content lands
on the right stream. Existing tests cover pieces of that:
- MultiplexingThroughputTest: opens 1000 streams in <2s — measures
lock contention but never moves bytes server-side.
- MultiplexingCoalescingTest: pins that 64 streams coalesce into ≤6
packets — encoder contract, no end-to-end.
- MultiStreamFinDeliveryTest: server pushes responses to 50 streams,
client surfaces every FIN — but the CLIENT never sends a STREAM
frame in that test, so any regression in the writer's request-
side multiplex path is invisible.
This test runs the full request → response loop:
1. Open 64 parallel bidi streams
2. Each enqueues a tiny request + FIN
3. Drain client outbound → decrypt → assert all 64 STREAM frames
made it across, with their request bytes intact
4. Server sends one response per stream + FIN
5. Per-stream incoming.toList() must yield the expected response
Failures call out the specific stream id, so a regression points
at "stream X dropped its FIN" instead of a generic timeout.
64 streams keeps wall-clock under a second; the bug class the test
guards against (per-stream loss / mis-routing) fires identically at
64 and 1999.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
The existing PtoCryptoRetransmitTest simulated the driver inline:
it set pendingPing=true and called requeueAllInflightCrypto by hand,
then asserted the next drain emitted CRYPTO. That checked the helpers
worked but never noticed when the DRIVER stopped calling
requeueAllInflightCrypto — which is exactly the regression that bit
us in commits c0d7b6031 (qlog merge) and again in cf2303a38
(lock-split refactor).
Extract the PTO-fired logic from QuicConnectionDriver.sendLoop into
a top-level internal helper handlePtoFired(conn). Driver and test now
both call the same function — if anyone unwires the requeue from
that helper or rewrites sendLoop to do volatile-only updates, the
test breaks.
Verified the regression-catch by stripping the requeue from
handlePtoFired and re-running the test: it fails with an
AssertionError on the PTO retransmit packet check, as expected.
Restored the helper, test green again.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
aioquic interop multiplexing qlog (the smoking gun):
packet_sent PN=0 Initial frames=[crypto] (ClientHello)
packet_sent PN=1 Initial frames=[ping] (PTO probe — bare PING)
packet_received connection_close 0x0
"Packet contains no CRYPTO frame"
This is the SAME bug commit c0d7b6031 fixed; the lock-split refactor
(ef4bb9998) re-wrote the driver's PTO branch to use streamsLock and
inlined the @Volatile pendingPing/consecutivePtoCount writes — but
dropped the requeueAllInflightCrypto call that c0d7b6031 had wired
under the (now-renamed) connection.lock.
Restored under levelLock for the appropriate level. SendBuffer's
internal synchronized covers correctness, but the level lock keeps
us from racing the writer's takeChunk mid-build.
The writer's comment at QuicConnectionWriter.kt:421-431 already
documented this contract — it was just unwired on the driver side.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Tier 1 lock-split agent's worktree was based on main and didn't carry
the Retry-handling work (fields retryToken / retryConsumed, applyRetry
method's references to them). Merge with -X theirs nuked those.
Restored:
- retryToken + retryConsumed @Volatile fields on QuicConnection,
re-attached to applyRetry in the lock-split-merged file.
- LevelState.resetForVersionNegotiation now uses pnSpace.resetForRetry()
to reset the PN counter in place — pnSpace is `val` post-refactor,
direct re-assignment doesn't compile. The naming is historical;
the underlying semantics (zero PN counter + clear received side)
are correct for both VN and Retry-with-fresh-PN cases.
- openBidiStream split into the public suspend wrapper +
openBidiStreamLocked() (caller holds streamsLock). Restores the
batched prepareRequests path's ability to open N streams under one
lock hold.
- close() — local var firedQlog hoisted out of withLock block.
Test suite runs clean. Three deprecation warnings remain on
PtoCryptoRetransmitTest + QlogObserverTest still using the
backward-compat conn.lock alias; left for follow-up cleanup.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
The single connection-wide `QuicConnection.lock` mutex serialised every
critical path: the read loop's `feedDatagram`, the send loop's
`drainOutbound`, and every public mutator (`openBidiStream`,
`streamById`, `flowControlSnapshot`, ...). The multiplexing testcase
opens hundreds of bidi streams in parallel and was capped at ~25
streams/sec by lock contention against the I/O loops.
Phase 1 of the lock split (see
`quic/plans/2026-05-08-lock-split-design.md`) introduces three
domain-specific mutexes:
- `streamsLock` — streams registry, datagram queues, stream-id
counters, connection-level flow-control bookkeeping, pending-
retransmit maps for control frames
- `LevelState.levelLock` (one per encryption level) — per-level
pnSpace / sentPackets / ackTracker / CRYPTO buffers
- `lifecycleLock` — status transitions, close reason/error code
Acquisition order: `lifecycleLock < streamsLock < levelLock`.
Per-stream `synchronized(this)` blocks inside SendBuffer/ReceiveBuffer
remain at the leaf — never acquire any QuicConnection mutex while
holding a per-stream lock.
The legacy `lock: Mutex` field is preserved as a deprecated alias of
`lifecycleLock` for source-compatibility with external test harnesses;
new code MUST use the appropriate domain lock.
Highlights:
- `feedDatagram` / `drainOutbound` now require the caller to hold
`streamsLock`; the driver wraps each call. Phase 1 keeps the whole
feed/drain inside `streamsLock` for safety; phase 2 (deferred) will
split frame-collection from encrypt + sentPackets-record so app
coroutines can intersperse during the encrypt window.
- `pendingPing`, `peerTransportParameters`, `status`,
`handshakeComplete` are now @Volatile so observers read them
without a lock.
- `markClosedExternally` no longer needs any lock (status is
@Volatile, signals are channel-thread-safe).
- Driver's PTO bookkeeping uses the volatile fields directly — no
lock needed.
- Tests that manually acquired `conn.lock` to call
`getOrCreatePeerStreamLocked` / `onTokensAcked` / `onTokensLost`
now acquire `streamsLock` (the domain those routines mutate).
- New `MultiplexingThroughputTest` locks in the contract: 1000
parallel `openBidiStream` calls must complete in <2 s.
Test plan:
- `:quic:jvmTest` — 294 tests pass (293 prior + 1 new throughput).
- `MultiplexingThroughputTest`: 1000 bidi streams in 52 ms
(~19,000 streams/sec on the in-memory pipe), well above the
250+/sec target.
- `:nestsClient:compileKotlinJvm` — clean, no API breaks.
- `./gradlew :quic:spotlessApply` — clean.
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
Two unit tests for the multiplexing throughput problem we just fixed
in the InteropClient (commit bc19e90c1):
1. `64 streams enqueued before drain coalesce into a small fixed
number of packets` — opens 64 bidi streams, enqueues 50 bytes +
FIN on each (no drain between), drains everything, asserts
≤6 packets and ≥10 streams/packet. Pre-fix shape (each enqueue
followed by an immediate single-stream drain) would emit 64 packets.
2. `1000 streams enqueued in batches of 64 produce a tractable packet
count` — stress version mirroring the runner's 1999-file
multiplexing test. Asserts ≤150 packets total for 1000 streams.
Both tests run in <300ms on the in-memory pipe — fast iteration for
debugging the multiplexing-throughput regression cycle without
spinning up Docker.
These pin the contract that ZERO drains between enqueues = packets
batch many streams' frames. The runner-side fix (split GetClient.get
into prepareRequest + awaitResponse, batch prepareRequests serially,
wake once) ensures we hit this shape in real interop.
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
Multiplexing-throughput investigation (qlog against aioquic):
~25 streams/sec with 1453 GETs in 58s. The bottleneck under high
stream count was drainOutbound's per-call O(N log N) sort over the
ENTIRE stream list (including streams that have already FIN'd both
ways and have nothing to send).
Two cheap optimizations to drainOutbound's stream iteration:
1. Filter to !isClosed streams BEFORE sort. Most streams under
bursty multiplexing loads are done; iterating them is wasted.
2. Skip sortedByDescending entirely when every stream is at
default priority (priority == 0). The pre-priority round-robin
shape (insertion order) is preserved, satisfying the moq-lite
newer-sequence-stream priority contract by happenstance for
uniform-priority loads.
Drops drainOutbound's per-call cost from O(N log N) where N = total
streams to roughly O(active) under realistic loads. Multiplexing's
~2000 streams accumulated over a run drop down to maybe 64 active at
any moment (the chunk in flight).
Doesn't affect the moq-lite audio path's behavior (small N, default
priorities → both paths reduce to the same round-robin walk).
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
Multiplexing matters — MoQ audio rooms run hundreds of concurrent streams
(one per Opus frame). Earlier diagnosis showed our endpoint was
hard-capped at ~23 streams/sec because spawning 1999 simultaneous
coroutines all racing :quic's single conn.lock cratered throughput.
Diagnosis from the qlog/output.txt: 1359 GETs processed in 58s. Lock
contention scales superlinearly with suspended coroutines:
- every drainOutbound walks streamsList O(N)
- every openBidiStream queues behind every other waiter
- the dispatcher thrashes context-switching across 1999 channels
Fix: process the multiplexing testcase's URLs in chunks of 64. Each
chunk is fully parallel on the wire (what the runner's tshark
multiplexing check verifies — streams overlap in time WITHIN a chunk),
and conn.lock only ever has ~64 live waiters instead of ~1999.
Predicted throughput jump from 23 to ~600+ streams/sec. 1999 files in
~3 seconds instead of timing out at 60.
Per-stream timeout still wraps each get() — a single hung stream
surfaces as status=0 instead of stalling its chunk's await.
This is the right answer for the throughput angle. The conn-lock split
remains a follow-up for genuinely-stratospheric stream counts (10k+),
but 64-wide concurrency comfortably handles the runner's 1999 and
real MoQ audio-room load shapes (hundreds of concurrent streams).
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
The QPACK_MAX_TABLE_CAPACITY=0 advertisement worsened the result
(1 file → 0 files written). Empirical: empty SETTINGS = spec defaults
(both 0) and aioquic was already sending literal-encoded responses
under that condition.
Real bug isn't QPACK — diagnostic showed 1359 GETs processed in 58s
(~23 streams/sec). Throughput is hard-bottlenecked by :quic's single
conn.lock serializing send loop + read loop + openBidiStream across
1999 waiting coroutines. Even at maximum throughput we'd only complete
~1400 of 1999 in 60s. The 1 file we managed previously was just the
first response landing before lock contention spiked.
Filed multiplexing as a known-throughput-limit follow-up. Possible
fixes (per-level lock split / Semaphore-bounded concurrency / QPACK
dynamic-table support) are all non-trivial and the testcase is a
stress test, not a real-world load shape.
For now: revert to empty SETTINGS, accept multiplexing as the lone
deferred testcase. Aioquic + picoquic stay at 6/7.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
aioquic multiplexing diagnosis: runner asked for 1999 files, aioquic
processed 1371 GET requests, our endpoint wrote ONLY 1 file to
/downloads. The connection stayed healthy throughout (qlog shows
STREAM frames flowing both ways at t=58s). Server response volume
indicates each request got a 200 response.
The bug: our QpackDecoder is literal-only (no dynamic table). When
aioquic primes its dynamic table after a few requests and switches
to dynamic-table references in subsequent response HEADERS, our
decoder silently mis-parses — status comes back 0, file not written.
Empty-SETTINGS gives aioquic the spec default (also 0) but it apparently
doesn't strictly enforce: it still emits dynamic-refs anyway.
Fix: explicitly advertise QPACK_MAX_TABLE_CAPACITY=0 +
QPACK_BLOCKED_STREAMS=0 in our SETTINGS. Forces aioquic onto the
literal-only QPACK path that our decoder handles correctly.
A proper fix would be to implement QPACK dynamic-table support in our
decoder + read the server's encoder stream; that's its own project.
For now this gets multiplexing past the QPACK barrier so we can see
whether anything else is broken downstream.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
The previous coroutineScope { urls.map { async { ... } }.map { it.await() } }
pattern was vulnerable to a single hung stream blocking the whole await
chain — even though the others completed, sequential .await() iteration
would hang on the slowest forever. With multiplexing's hundreds of
streams, the probability of at least one having an issue (lost FIN,
slow consumer hitting channel-saturation thresholds, etc.) is high.
Wrap each get() in withTimeoutOrNull(PER_STREAM_TIMEOUT_SEC). A timed-out
stream surfaces as GetResponse(status=0); the caller's status != 200
check counts it as a failure but doesn't block the loop.
Doesn't fix throughput — that needs separate work on per-stream
backpressure and parser fairness. Just makes the failure mode visible
(status=0 → "failed file") rather than hidden (whole test times out
because of one bad stream).
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
aioquic multiplexing qlog showed:
t=31424: still receiving STREAM frames
t=31493: PTO timer expired
t=31507: connection_closed (owner: local)
We were still actively transferring when our 30s timeout fired. The
multiplexing testcase generates many small files (3431 sim packets
captured for the run) and download throughput on Mac+Rosetta is
dominated by per-write filesystem overhead in the Docker volume mount.
60s gives enough headroom without making fast-completing tests slower.
Doesn't fix any real protocol issue — just lets the test budget match
the workload.
If multiplexing still fails after this, the next investigation is the
sequential `.map { it.await() }` pattern in runTransferTest: a single
hung stream blocks the await chain even though others completed.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
aioquic's retry test result, surfaced via qlog:
Check of downloaded files succeeded.
Client reset the packet number. Check failed for PN 0
Our applyRetry called LevelState.resetForVersionNegotiation, which
creates a fresh PacketNumberSpaceState() — resetting PN to 0. The
qlog confirmed: PN=0 sent at t=388 (pre-Retry ClientHello), then PN=0
again at t=1468 (post-Retry retried ClientHello). Same PN reused
across the boundary.
RFC 9001 §5.7 + RFC 9000 §17.2.5: the Initial PN namespace CONTINUES
across the Retry boundary. The new Initial keys are derived from the
new DCID, but PN doesn't reset. Reusing a PN under different keys
makes the runner's pcap-decryption check fail (it's also a security
concern in the general case, hence the strict spec rule).
Fix: new LevelState.resetForRetry that's identical to
resetForVersionNegotiation EXCEPT it preserves pnSpace. applyRetry
calls resetForRetry. Two regression tests updated to assert the
post-Retry Initial uses PN=1 (continues from PN=0 of the pre-Retry
attempt) rather than PN=0 (the buggy reset behavior).
For Version Negotiation the original semantics still apply (RFC 9000
§6.2: client treats VN as if the original Initial was never sent;
PN reset to 0 is correct).
This should bring the retry testcase from ✕(S) to ✓(S) against
servers that exercise the Retry path. The handshake / transfer
already succeeded over the Retry per the qlog (the server's check
"Check of downloaded files succeeded." passed); only the PN-reuse
flag was failing the test.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Claude