From 9cd8d0a6ee29dd5a44dadf7e1b5c6fc0f9bd8ece Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 7 May 2026 13:08:14 +0000 Subject: [PATCH] diag(quic): writer-side per-drain stats behind DEBUG=1 build flag MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- quic/interop/Dockerfile | 7 ++++ quic/interop/Makefile | 7 +++- .../quic/interop/runner/InteropClient.kt | 6 ++++ .../quic/connection/QuicConnectionWriter.kt | 19 +++++++++++ .../quic/connection/WriterDebug.kt | 34 +++++++++++++++++++ .../connection/MultiplexingAioquicTpsTest.kt | 1 - 6 files changed, 72 insertions(+), 2 deletions(-) create mode 100644 quic/src/commonMain/kotlin/com/vitorpamplona/quic/connection/WriterDebug.kt diff --git a/quic/interop/Dockerfile b/quic/interop/Dockerfile index 21b225c86..d556b2d54 100644 --- a/quic/interop/Dockerfile +++ b/quic/interop/Dockerfile @@ -14,3 +14,10 @@ RUN apt-get update \ COPY quic/interop/build/install/quic-interop /opt/quic-interop COPY quic/interop/run_endpoint.sh /run_endpoint.sh RUN chmod +x /run_endpoint.sh /opt/quic-interop/bin/quic-interop + +# Build-time toggle for verbose tracing. Pass --build-arg DEBUG=1 (or +# `make build DEBUG=1` via the Makefile) to bake QUIC_INTEROP_DEBUG into +# the image so the InteropClient + writer emit per-drain stats to stderr. +# Off by default — production matrix runs stay quiet. +ARG DEBUG=0 +ENV QUIC_INTEROP_DEBUG=${DEBUG} diff --git a/quic/interop/Makefile b/quic/interop/Makefile index a93b4dd2c..c49c90169 100644 --- a/quic/interop/Makefile +++ b/quic/interop/Makefile @@ -10,6 +10,11 @@ IMAGE ?= amethyst-quic-interop:latest REPO_ROOT := $(shell git rev-parse --show-toplevel) DIST_DIR := build/install/quic-interop +# Build-time toggle: `make build DEBUG=1` bakes QUIC_INTEROP_DEBUG=1 into +# the image so the InteropClient + writer emit per-drain diagnostics to +# stderr. Off by default — production matrix runs stay silent. +DEBUG ?= 0 + .PHONY: build dist docker image-name clean build: docker @@ -18,7 +23,7 @@ dist: cd $(REPO_ROOT) && ./gradlew :quic-interop:installDist docker: dist - cd $(REPO_ROOT) && docker build -t $(IMAGE) -f quic/interop/Dockerfile . + cd $(REPO_ROOT) && docker build -t $(IMAGE) --build-arg DEBUG=$(DEBUG) -f quic/interop/Dockerfile . image-name: @echo $(IMAGE) diff --git a/quic/interop/src/main/kotlin/com/vitorpamplona/quic/interop/runner/InteropClient.kt b/quic/interop/src/main/kotlin/com/vitorpamplona/quic/interop/runner/InteropClient.kt index 2e59fd32d..449269e84 100644 --- a/quic/interop/src/main/kotlin/com/vitorpamplona/quic/interop/runner/InteropClient.kt +++ b/quic/interop/src/main/kotlin/com/vitorpamplona/quic/interop/runner/InteropClient.kt @@ -83,6 +83,12 @@ private const val PER_STREAM_TIMEOUT_SEC = 20L private const val MULTIPLEX_PARALLELISM = 64 fun main() { + // Single env-var check, propagated to library code that opts into + // verbose tracing only when this is set. + if (System.getenv("QUIC_INTEROP_DEBUG") == "1") { + com.vitorpamplona.quic.connection.writerDebugEnabled = true + } + val role = System.getenv("ROLE") ?: "client" if (role != "client") { System.err.println("server role not implemented") diff --git a/quic/src/commonMain/kotlin/com/vitorpamplona/quic/connection/QuicConnectionWriter.kt b/quic/src/commonMain/kotlin/com/vitorpamplona/quic/connection/QuicConnectionWriter.kt index e60635170..88792a4e3 100644 --- a/quic/src/commonMain/kotlin/com/vitorpamplona/quic/connection/QuicConnectionWriter.kt +++ b/quic/src/commonMain/kotlin/com/vitorpamplona/quic/connection/QuicConnectionWriter.kt @@ -705,6 +705,25 @@ private fun buildApplicationPacket( } if (frames.isEmpty()) return null + + // Diagnostic: gated by QUIC_INTEROP_DEBUG=1 so prod is silent. Tells + // us exactly what state the writer was in when it built this packet. + // Hunting the multiplexing-on-the-wire bug where MultiplexingCoalescing + // Test passes (~9 streams/packet) but the live driver emits 1 STREAM + // per packet against aioquic. + if (com.vitorpamplona.quic.connection.writerDebugEnabled) { + val streamFrameCount = frames.count { it is StreamFrame } + val totalFrames = frames.size + val streamsViewSize = conn.streamsListLocked().size + val activeSize = conn.streamsListLocked().count { !it.isClosed } + System.err.println( + "[writer.app] frames=$totalFrames stream_frames=$streamFrameCount " + + "streamsView=$streamsViewSize active=$activeSize " + + "packetBudget_remaining=${1100 - (frames.filterIsInstance().sumOf { it.data.size + 32 })} " + + "connBudget_initial=${(conn.sendConnectionFlowCredit - conn.sendConnectionFlowConsumed).coerceAtLeast(0L)}", + ) + } + val payload = encodeFrames(frames) val pn = state.pnSpace.allocateOutbound() // Retain the packet for RFC 9002 loss detection BEFORE the encrypt diff --git a/quic/src/commonMain/kotlin/com/vitorpamplona/quic/connection/WriterDebug.kt b/quic/src/commonMain/kotlin/com/vitorpamplona/quic/connection/WriterDebug.kt new file mode 100644 index 000000000..6955974aa --- /dev/null +++ b/quic/src/commonMain/kotlin/com/vitorpamplona/quic/connection/WriterDebug.kt @@ -0,0 +1,34 @@ +/* + * Copyright (c) 2025 Vitor Pamplona + * + * Permission is hereby granted, free of charge, to any person obtaining a copy of + * this software and associated documentation files (the "Software"), to deal in + * the Software without restriction, including without limitation the rights to use, + * copy, modify, merge, publish, distribute, sublicense, and/or sell copies of the + * Software, and to permit persons to whom the Software is furnished to do so, + * subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in all + * copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS + * FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR + * COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN + * AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION + * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. + */ +package com.vitorpamplona.quic.connection + +/** + * Opt-in writer-side debug logging. Toggled by external code (the + * interop endpoint sets it from the QUIC_INTEROP_DEBUG env var at + * startup). Off by default — production must be silent. + * + * Cost when off: a single volatile read in the writer hot path, + * negligible against the encode + AEAD seal cost. Worth keeping + * inert in shipped code so the next interop investigation can flip + * it on without code changes. + */ +@Volatile +var writerDebugEnabled: Boolean = false diff --git a/quic/src/commonTest/kotlin/com/vitorpamplona/quic/connection/MultiplexingAioquicTpsTest.kt b/quic/src/commonTest/kotlin/com/vitorpamplona/quic/connection/MultiplexingAioquicTpsTest.kt index 4fa330b34..cec71658f 100644 --- a/quic/src/commonTest/kotlin/com/vitorpamplona/quic/connection/MultiplexingAioquicTpsTest.kt +++ b/quic/src/commonTest/kotlin/com/vitorpamplona/quic/connection/MultiplexingAioquicTpsTest.kt @@ -20,7 +20,6 @@ */ package com.vitorpamplona.quic.connection -import com.vitorpamplona.quic.frame.StreamFrame import com.vitorpamplona.quic.tls.InProcessTlsServer import kotlinx.coroutines.runBlocking import kotlin.test.Test