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
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 still 0/7 after the close-race fix because there's a deeper
issue. QlogWriter.writeLineLocked() called writer.flush() on every
event. On macOS Docker Desktop the filesystem is virtualized and
per-event flush is multi-millisecond. The qlog hooks fire from
QuicConnectionWriter.drainOutbound() which runs INSIDE
conn.lock.withLock { ... } on the send loop. Every flush stalls
that lock; the receive loop blocks indefinitely trying to acquire
it for feedDatagram().
Symptom matched: client.sqlog showed our ClientHello packet_sent
at t=400ms, then NOTHING for the rest of the test — no
packet_received (server's response never decoded), no PTO probe
(send loop stuck behind disk IO).
Fix: remove per-event flush. close() flushes once at the end of
the run, which gives us the trace for everything except a hard
JVM kill mid-test (acceptable trade). BufferedWriter still buffers
in-memory; we don't lose events, just don't sync them to disk
synchronously.
Should restore aioquic to 5/7. picoquic was already 5/7 because
its server-response timing apparently let our send loop drain
between flushes; aioquic's faster turnaround tripped the lock more
reliably.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
aioquic full-matrix run came back 0/7 with stack traces:
java.io.IOException: Stream closed
at QlogWriter.writeLineLocked(QlogWriter.kt:289)
at QlogWriter.onPacketSent(QlogWriter.kt:126)
at QuicConnectionWriter.emitQlogSent(...)
The send loop runs concurrently with InteropClient's teardown sequence:
1. driver.close() — launches CLOSING → CLOSED async
2. qlogWriter?.close() — closes the file
3. delay(50)
4. scope.cancel() — kills coroutines
Between (2) and (4), the send loop is still alive and emits
packet_sent for the CONNECTION_CLOSE Initial. QlogWriter.writeLineLocked
threw IOException into the send loop, propagated up, took down the
connection — including connections that had completed transfer
successfully.
Fix: QlogWriter swallows post-close IOExceptions silently. An observer
must NOT break the connection it's observing — that's the whole NoOp
contract. Adds @Volatile closed flag, latches it both on explicit
close() and on the first IOException; subsequent emits short-circuit.
picoquic was 5/7 (predictable: M + S still open) so the regression was
specifically aioquic-timing-sensitive. With this fix aioquic should
return to 5/7 too.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Documents:
- Three overnight agents merged (VN defense in :quic, qlog observer
+ JSON-NDJSON writer wired into the prod endpoint, peer-uni-stream
drainer fixing the multiplexing tear-down).
- The agent-A versionnegotiation testcase mismatch — runner doesn't
have that name; v2 is the closest, tests QUIC v2 which we don't
speak. VN code stays as defensive support.
- Open issues for tomorrow: retry test failure (qlog now available
for diagnosis), v2 (deferred), re-runs against all three peers
with the new fixes.
- Documented run-matrix.sh's concurrency limit.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Agent B's QlogWriter previously lived only in :quic's jvmTest scope,
hooked into the standalone InteropRunner. Brings it into :quic-interop
proper:
- QlogWriter.kt + QlogWriterTest.kt copied into :quic-interop with
package com.vitorpamplona.quic.interop.runner.
- Jackson dep added to :quic-interop's build.gradle.kts.
- InteropClient reads $QLOGDIR (the runner sets it inside the
container per docker-compose.yml). When set, opens a QlogWriter
at <QLOGDIR>/client.sqlog, passes as QuicConnection.qlogObserver,
closes on every exit path (handshake_failed / udp_failed /
transfer_timeout / ok).
- QUIC_INTEROP_DEBUG=1 now prints qlogdir alongside the other env
fields.
Net effect: any future runner-driven test failure dumps a structured
qlog file the user can drag straight into qvis (qvis.quictools.info)
to see frame-by-frame what the client decided to do. The retry test
failure on aioquic + picoquic that we still need to debug now produces
a usable artifact.
NOTE: the QlogWriter copy in :quic's jvmTest stays in place as the
helper for the standalone InteropRunner main(). Slight duplication;
acceptable while :quic-interop is its own module.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Two corrections from the user's just-completed run:
1. The runner does not have a 'versionnegotiation' testcase. Available
list output: handshake, transfer, longrtt, chacha20, multiplexing,
retry, resumption, zerortt, http3, blackhole, keyupdate, ecn,
amplificationlimit, handshakeloss, transferloss, handshakecorruption,
transfercorruption, ipv6, v2, rebind-port, rebind-addr,
connectionmigration. (`v2` exists but tests QUIC v2 protocol
support — we're v1-only, so it would correctly fail.)
The :quic-side VN code from agent A stays as defensive support for
any future server that throws a VN at us; just no testcase wires
it up.
2. run-matrix.sh is NOT safe to run concurrently. The runner's
docker-compose.yml hardcodes container_name: sim/server/client —
Docker enforces those globally regardless of COMPOSE_PROJECT_NAME.
Documented the limitation + the recommended sequential loop in
the script's comments.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Two integrations from overnight agents:
1. agent C — peer-uni-stream drainer for the H3 multiplexing fix.
Http3GetClient.init() now takes a CoroutineScope and calls
conn.drainPeerInitiatedUniStreamsIntoBlackHole(scope) to consume +
discard the server's three uni streams (control, qpack-encoder,
qpack-decoder). RFC 9114 §6.2 mandates the client read these;
pre-fix their bytes accumulated in 64-chunk per-stream channels
until parser overflow tore down the connection with INTERNAL_ERROR
~4.5s into a multiplexing run.
2. agent A — versionnegotiation testcase wired into dispatch.
Adds the testcase to the runTransferTest route and threads
QuicVersion.FORCE_VERSION_NEGOTIATION as the initial version when
testcase=='versionnegotiation'. The QuicConnection's RFC 9000 §6
VN flow (applyVersionNegotiation) takes over from there, retrying
with v1 once the server replies with its supported list.
https://claude.ai/code/session_01HcvfQq1ttPV9PkRoJb4nyT
Vitor Pamplona