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.
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.
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
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
Claude