From 31d192582e0cc4134981073a209dd2a3329789ae Mon Sep 17 00:00:00 2001
From: Vitor Pamplona <vitor@vitorpamplona.com>
Date: Thu, 7 May 2026 15:55:09 -0400
Subject: [PATCH] diag(quic-interop): periodic 250ms qlog flush so SIGKILL
 doesn't strand traces
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

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>
---
 .../quic/interop/runner/QlogWriter.kt         | 39 ++++++++++++++-----
 1 file changed, 29 insertions(+), 10 deletions(-)

diff --git a/quic/interop/src/main/kotlin/com/vitorpamplona/quic/interop/runner/QlogWriter.kt b/quic/interop/src/main/kotlin/com/vitorpamplona/quic/interop/runner/QlogWriter.kt
index 59f4f5afc1..b711c4d97b 100644
--- a/quic/interop/src/main/kotlin/com/vitorpamplona/quic/interop/runner/QlogWriter.kt
+++ b/quic/interop/src/main/kotlin/com/vitorpamplona/quic/interop/runner/QlogWriter.kt
@@ -69,6 +69,17 @@ class QlogWriter(
     private val lock = ReentrantLock()
     private val startMillis: Long = nowMillis()
 
+    /** Last wall-clock millis we flushed at. Periodic flushing avoids the
+     *  "qlog truncates at exactly the BufferedWriter buffer size when the
+     *  JVM is hard-killed at runner timeout" trap that hides the test's
+     *  late behavior. The interval is generous enough to keep the macOS
+     *  Docker filesystem virtualization overhead off the hot send path
+     *  (per-event flush there was multi-ms and broke handshakes — see
+     *  commit 99a1a91de). 250 ms keeps us within ~one cwnd of the
+     *  failure under loss while still being far cheaper than per-event. */
+    @Volatile
+    private var lastFlushMillis: Long = startMillis
+
     init {
         // qlog 0.3 JSON-SEQ header. qvis tolerates both `qlog_format`
         // values "JSON-SEQ" and "NDJSON"; we use JSON-SEQ to match the
@@ -301,16 +312,22 @@ class QlogWriter(
             try {
                 writer.write(line)
                 writer.write("\n")
-                // Deliberately NOT flushing per event: this method runs
-                // inside conn.lock.withLock { drainOutbound(...) } on the
-                // hot send path. On macOS Docker Desktop the filesystem
-                // is virtualized and per-event flush is multi-millisecond.
-                // Every flush stalls the connection lock, blocks the
-                // receive loop, and the connection silently dies
-                // mid-handshake. close() does the only flush we need
-                // for normal completion. A hard-killed JVM loses recent
-                // events but that's an acceptable trade — the alternative
-                // is the connection never completing in the first place.
+                // Periodic flush so a runner-timeout SIGKILL doesn't leave
+                // the last seconds of the trace stranded in the JVM buffer.
+                // Pre-fix this method never flushed (relied on close()), and
+                // a 60 s test ended at exactly 32768 bytes = 4 × 8 KB
+                // BufferedWriter blocks — masking 50 s of late-connection
+                // behavior and turning every interop debug session into
+                // "did the connection wedge or did the qlog?". Per-event
+                // flush was the prior shape and was multi-ms on macOS
+                // Docker virtualized filesystems (commit 99a1a91de). 250 ms
+                // is the compromise: cheap enough to not stall the send
+                // path, fine-grained enough to capture per-PTO behavior.
+                val now = nowMillis()
+                if (now - lastFlushMillis >= FLUSH_INTERVAL_MILLIS) {
+                    writer.flush()
+                    lastFlushMillis = now
+                }
             } catch (_: java.io.IOException) {
                 // Stream closed under us. Latch closed so subsequent emits
                 // skip the lock and return immediately.
@@ -320,6 +337,8 @@ class QlogWriter(
     }
 
     companion object {
+        private const val FLUSH_INTERVAL_MILLIS: Long = 250L
+
         private val DEFAULT_MAPPER: ObjectMapper = jacksonObjectMapper()
 
         private fun packetTypeFor(level: EncryptionLevel): String =