OAuthEndToEndTest is flaky in CI — SocketTimeoutException, passes on re-run of the identical commit

[monkopedia-coder]

core/tunnel/src/jvmTest/.../OAuthEndToEndTest.kt fails nondeterministically in CI with a socket timeout, and a re-run of the identical commit passes.

Evidence

Same commit 172dea6d, same job, no code change between runs:

run 1   test  FAILED   OAuthEndToEndTest > full OAuth authorization code flow
                       with PKCE through relay()[jvm] FAILED
                       java.net.SocketTimeoutException at OAuthEndToEndTest.kt:604
                       50 tests completed, 1 failed

run 2   test  SUCCESS  22m58s   (re-run of failed jobs, identical SHA)

Line 604 is IntegrationHttpSupport.exchange(input, output, sb.toString(), bodyBytes) — a real socket exchange against the locally spawned rouse-relay binary, so a timeout here is timing, not logic.

Why this is worth an issue rather than a shrug

A nondeterministic red is worse than a consistently red test, because it destroys the ability to tell a real regression from noise at exactly the moment that distinction matters.

Concretely, this cost a full diagnostic cycle: the failure landed on a PR whose diff was two files in app/src/foss/, a module with no dependency path to :core:tunnel (core/tunnel/build.gradle.kts depends on :core:testfixtures, :core:mcp, :core:bridge — not :app), and the failing test references nothing from com.rousecontext.app. The structural argument said "not mine"; the branch history said "previous head green, this head red, only your files changed." Those pointed opposite ways and neither settled it — only re-running the identical commit did.

That is a tax on every future PR that happens to land while this test is unlucky. The next person may not re-run; they may push a speculative fix, or worse, learn to disregard a red test job.

What would settle the cause

Not investigated here — this issue records the flake with evidence rather than guessing at it. Candidates worth checking:

• the timeout constant used by IntegrationHttpSupport.exchange versus how long relay startup actually takes on a cold GitHub runner
• whether the test waits for the relay to be listening or merely for the process to have been spawned
• whether the OAuth flow's multi-leg exchange has a per-leg timeout that is tight relative to runner variance

Prior occurrence

android-ci.yml on main shows a failure on 2026-07-08 among otherwise-green runs. I have not confirmed that was this same test — the logs may have aged out — so treat it as a lead rather than a second data point.

[monkopedia-coder]

Triage: labelling under-investigation — and adding prior art this issue does not have, which changes what the investigation should start from.

This is the fourth filing of this flake on this test, and the desync theory has already been fixed twice. The issue's "Prior occurrence" section reaches for a 2026-07-08 android-ci.yml failure it could not confirm; the real history is much more specific and is all in this tracker:

#	what it was	outcome
#377 (Apr 25)	Same test, SocketTimeoutException at OAuthEndToEndTest.kt:596 — the reader.readLine() in httpRequest, 30s soTimeout	Investigated, no speculative fix shipped. Notably it also found the issue's own "two observations" were one: the second run's failure was an unrelated DataStoreUnknownClientLabelerTest failure.
#518 (Jun 25)	Same test, same exception, at :603. 2 of 6 runs in a stability sweep	Closed by #522
#522	Root cause: lost-bytes desync. IntegrationHttpSupport.readResponse built a fresh BufferedReader per call, so bytes buffered ahead from a coalesced TCP segment were discarded and the next read blocked until the timeout fired. Fix: one reader per stream, identity-keyed	30/30 clean locally
#523 (Jun 25)	Residual — ClaudeFullFlowEndToEndTest, same signature, post-#522	Closed by #524
#524	Second root cause: Content-Length counts BYTES, BufferedReader counts CHARS. Fix: byte-exact HTTP framing over BufferedInputStream, body read as exactly N bytes	—

What that means for this investigation. The three candidate causes listed in the issue are worth checking, but two of them are already closed off on origin/main (fbde32e6):

• The timeout is not tight. IntegrationHttpSupport.SOCKET_READ_TIMEOUT_MS = 60_000, applied via applyReadTimeout(socket). Flaky: OAuthEndToEndTest full PKCE flow through relay (observed twice on main CI) #377's failure was against a 30s local soTimeout; that is no longer the code being run.
• Relay readiness is waited on, not assumed. TestRelayFixture.startRelay polls java.net.Socket("127.0.0.1", port) until it connects, so the test waits for the relay to be listening, not merely spawned.
• The reader-level desync is fixed twice over and IntegrationHttpSupport carries a long KDoc block (lines 48-65) explaining both fixes.

So the two obvious theories are spent. Please do not re-derive them. A 60s read timeout expiring means either something upstream of the helper (relay-side stall, or the multi-leg OAuth flow genuinely taking >60s under runner contention) or a third framing bug the byte-exact rewrite did not reach.

One datum in this issue's own evidence points at contention and is worth pulling on first: the passing re-run took 22m58s. #377 recorded its failure landing after ~3.5 min of task execution while a typical local run of this test is ~13s. If CI job duration correlates with the failures, the cause is the runner, not the test — and that is a different fix (isolate/serialize the integration suite) than anything in the candidate list.

Do not ship a speculative timeout bump. Two prior rounds found real, specific bugs by reproducing rather than guessing; a third round that raises a constant would hide whatever is left.

[monkopedia-coder]

Investigation — the residual is not in the HTTP helper, and I have two reproduced bugs in the tunnel

Short version: the triage comment's two "already closed off" claims both hold. The live lead (contention) is real but is a modifier, not the cause. Following the evidence away from IntegrationHttpSupport turned up two independently reproducible defects in core/tunnel product code, either of which produces exactly this signature — a peer sitting on a socket that never speaks again until its 60 s read timeout fires. One is fixed in #563; the other is filed as #562.

---

1. Re-verified, not re-derived

• IntegrationHttpSupport.SOCKET_READ_TIMEOUT_MS = 60_000, applied via applyReadTimeout(socket). Confirmed on origin/main (fbde32e6). This is the third round in which "the timeout is tight" has been proposed, and it is still not it.
• TestRelayFixture.startRelay polls java.net.Socket("127.0.0.1", port) in a loop with a 10 s deadline and fail()s if the process dies. It genuinely waits for listening, not spawned.

Also ruled out along the way:

• A stalled MCP handler. HttpTransport.REQUEST_TIMEOUT_MS = 30_000, i.e. below the 60 s socket timeout — a wedged handler surfaces as a 500, never as a client-side socket timeout.
• A regression since test(fixtures): byte-exact integration HTTP framing to close socket-read desync (#523) #524. No commit has touched core/bridge/src, core/tunnel/src/jvmMain, relay/src/passthrough.rs, relay/src/main.rs or relay/src/mux since 2026-06-20. Whatever is left has been there the whole time.

---

2. Two traps in the evidence, for whoever reads this next

(a) The uploaded test report from the failing run shows the test PASSING. Run 31295452985, attempt 1, job 93199702863:

05:03:14  > Task :core:tunnel:integrationTest
05:07:03  OAuthEndToEndTest > full OAuth ... FAILED
          java.net.SocketTimeoutException at OAuthEndToEndTest.kt:604
05:09:35  50 tests completed, 1 failed        BUILD FAILED
05:09:35  ##[group]Run ./gradlew koverHtmlReport koverXmlReport -Pgoogle
05:10:10  > Task :core:tunnel:integrationTest     <-- re-ran it
05:15:36  (passed)

The Coverage report (Kover) step runs with if: success() || failure(), so after the red it re-ran :core:tunnel:integrationTest — which passed — and that is what the test-reports artifact contains. Download it and OAuthEndToEndTest shows passed, 12.816 s. Anyone reaching for the artifact as primary evidence will conclude nothing happened.

(b) The failure fires ~3m49s into the task, not at the start. Consistent with #377's "~3.5 min" note. The 60 s timer starts around 05:06:03, so the test is well into the suite, not racing relay startup.

---

3. Contention is real, and quantified — but it is not sufficient

Because of trap (a) I can compare the same 50 tests on the two runners:

	tests compared	total	median per-test ratio
attempt 1 runner (the one that failed)	42	333.6 s	1.29×
attempt 2 runner (the re-run that passed)	42	258.4 s	1.00×

(min 0.83×, max 2.32×.) The failing job's runner was ~29 % slower at identical work. That is a genuine contention signal and it supports the lead in the triage comment.

But it is not the whole story: that same slow runner then passed the same 50 tests on its second execution. Slowness widens a window; it does not by itself create a hang.

I could not reproduce by contention alone. Four full :core:tunnel:integrationTest runs under 24 CPU hogs on 16 cores (load avg ~30), relay built with --features test-mode, test-results deleted before each run and the count taken from the JUnit XML rather than from "BUILD SUCCESSFUL":

iter 1 rc=0 dur=714s tests/fail/err/skip=50 0 0 0
iter 2 rc=0 dur=672s tests/fail/err/skip=50 0 0 0
iter 3 rc=0 dur=673s tests/fail/err/skip=50 0 0 0
iter 4 rc=0 dur=676s tests/fail/err/skip=50 0 0 0
DONE: 0 failures out of 4

50 executed, 0 skipped every time (so the relay binary was found and nothing was silently assumeTrue-d away), at ~11 min per suite against ~35 s for a single unloaded OAuth run — roughly a 20× slowdown, and still green. Contention is a modifier, not the mechanism. Which is the right answer: the mechanisms below are what it modifies.

---

4. The decisive clue: the other post-#524 failure is in the TLS handshake, not an HTTP read

android-ci.yml on main, run 28953639588 (2026-07-08, 9bde5017) — the "lead rather than a second data point" this issue mentions. It is a real data point, and it is post-#524:

15:25:31  > Task :core:tunnel:integrationTest
15:26:35  ClaudeFullFlowEndToEndTest > initializationError FAILED
          java.net.SocketTimeoutException at ClaudeFullFlowEndToEndTest.kt:712

At 9bde5017, line 712 is socket.startHandshake() inside connectAiClient() — not an HTTP exchange. IntegrationHttpSupport is not on that code path at all. (Timing corroborates: 64 s after the task started, i.e. the 60 s soTimeout applied to the socket just before the handshake.)

So the two surviving failures are:

	site	what was waiting
2026-07-08	ClaudeFullFlowEndToEndTest.kt:712 → startHandshake()	ServerHello
#558	OAuthEndToEndTest.kt:604 → IntegrationHttpSupport.exchange()	HTTP response

Different call sites, one shared condition: the device side of the tunnel goes silent. #522 and #524 fixed real bugs; what is left is upstream of the helper entirely. Please do not send a fourth round at IntegrationHttpSupport.

---

5. Root cause A (reproduced, fixed in #563): TlsAcceptor spins forever on a TLS record split across two mux DATA frames

core/tunnel/src/jvmMain/kotlin/com/rousecontext/tunnel/TlsAcceptor.kt gates its stream read, in both the handshake pump (accept) and the data path (SuspendTlsSession.read), on:

if (netIn.position() == 0) {
    val tlsData = stream.read()
    netIn = ensureCapacity(netIn, tlsData.size)
    netIn.put(tlsData)
}
netIn.flip()
val result = engine.unwrap(netIn, appIn)
netIn.compact()

That guard was added on 2026-04-06 (da28a140, d8c4b645 — "handle multi-record mux DATA frames") to fix the case where several TLS records arrive in one frame. It creates the exact inverse defect: when one record is split across two frames, netIn holds a partial record, so position() != 0, so the code never reads the remainder. unwrap returns BUFFER_UNDERFLOW consuming zero bytes, compact() restores the same bytes, and the loop runs again — forever, at 100 % CPU, in a coroutine with no suspension point, so it is not even cancellable.

Reproduced with a test that splits every client→server delivery in half. jstack of the hung worker:

"DefaultDispatcher-worker-1 @coroutine#3" ... cpu=45158.97ms elapsed=79.65s ... RUNNABLE
   at sun.security.ssl.SSLEngineImpl.readRecord(java.base@21.0.12/SSLEngineImpl.java:598)
   at javax.net.ssl.SSLEngine.unwrap(java.base@21.0.12/SSLEngine.java:679)
   at com.rousecontext.tunnel.TlsAcceptor$accept$2.invokeSuspend(TlsAcceptor.kt:100)

45 s of CPU in 80 s of wall on one thread, parked on the same unwrap. runBlocking could not return — cancelChildren() cannot stop a loop that never suspends.

Symptom match is exact, at both observed sites:

• spin in accept() → the AI client's startHandshake() never sees a ServerHello → 60 s → SocketTimeoutException at ClaudeFullFlowEndToEndTest.kt:712.
• spin in SuspendTlsSession.read() → the client's request is never forwarded to the Ktor MCP server → no response → 60 s → SocketTimeoutException at OAuthEndToEndTest.kt:604.

Timeline match: the guard landed 2026-04-06; the first filing (#377) is 2026-04-23. And a pegged vCPU on a 4-vCPU runner is consistent with the slow tail after the failure.

Honest limit on this one. I proved the spin exists and that it produces this signature; I have not proved CI is reaching it. The relay forwards client.read() verbatim with a 16 KiB buffer (relay/src/passthrough.rs:433) while a TLS record can be ~16.4 KiB on the wire, so any client burst over 16 KiB splits a record deterministically — but the OAuth flow's payloads are all well under that, so it would need an unlucky short read on loopback, which I could not force. Fixing it is still unambiguously correct: today a >16 KiB MCP request wedges a real device's tunnel at 100 % CPU.

---

6. Root cause B (reproduced, filed as #562): mux DATA frames can arrive out of order

This is my leading candidate for #558 specifically, because it needs only two adjacent frames — no size threshold.

TunnelClientImpl.onBinaryMessage launches a new coroutine per inbound WebSocket message:

override fun onBinaryMessage(data: ByteArray) {
    val muxFrame = MuxCodec.decode(data)
    scope.launch { demux.handleFrame(muxFrame) }
}

Nothing serialises those launches. Fails on origin/main, first try, no contention needed:

MuxFrameOrderingProbeTest > mux DATA frames reach the stream in wire order() FAILED
    expected: <null> but was: <index 2: expected 2, got 4>

A reordered TLS record fails unwrap with bad_record_mac; SessionHandler.copyTlsToStream swallows that (catch (_: Exception)) and tears the bridge down without closing the TLS session, so the peer is left on a socket that will never produce another byte — no error anywhere points at the cause. Same 60 s signature, and it lands at whichever call site happened to be in flight, which is why the two failures look unrelated.

Why it only ever bites CI: production passes RouseApplication.appScope = CoroutineScope(SupervisorJob() + Dispatchers.Main), single-threaded, so launches run FIFO by accident. The integration tests pass CoroutineScope(Dispatchers.IO) — OAuthEndToEndTest.connectTunnelClient() does exactly this — which is multi-threaded.

Why it is intermittent rather than constant: two DATA frames must be in flight close enough together to race. IntegrationHttpSupport.exchange writes the header block and the body as two separate SSLSocket writes, so a POST with a body routinely produces two back-to-back records → two DATA frames → one dice roll. OAuthEndToEndTest makes ~6 such POSTs. On an idle machine the first coroutine almost always wins; on a 4-vCPU runner at 1.29× load it sometimes does not. That is how contention enters the picture without being the cause — which is exactly the shape the triage comment predicted.

I did not ship this fix: it is a design change to the tunnel's frame dispatch (single consumer coroutine over a Channel, plus lifecycle handling), not a one-liner, and it deserves its own review. See #562 for the reproducer and a suggested shape.

---

7. Also worth fixing while someone is in here

The fixtures throw away the evidence that would have settled this three filings ago:

• TestRelayManager.capturedOutput() exists and captures the relay's RUST_LOG=debug output, but OAuthEndToEndTest and ClaudeFullFlowEndToEndTest never print it on failure (only RelayApiClientIntegrationTest, CertRotationIntegrationTest and the :app harness do).
• OAuthEndToEndTest.httpRequest is one call site for ~12 requests, so at OAuthEndToEndTest.kt:604 does not say which request timed out. Threading the method/path into the failure message costs nothing.

---

Status

• fix(tunnel): read more when a TLS record spans two mux DATA frames (#558 investigation) #563 — fixes root cause A (TlsAcceptor split-record spin) + regression tests. Deliberately does not say Closes #558.
• Mux DATA frames can be delivered out of wire order (TunnelClientImpl launches one coroutine per frame) #562 — root cause B (mux frame ordering), with a failing reproducer.
• I would keep OAuthEndToEndTest is flaky in CI — SocketTimeoutException, passes on re-run of the identical commit #558 open until a fix for Mux DATA frames can be delivered out of wire order (TunnelClientImpl launches one coroutine per frame) #562 has had several green main runs behind it.

[monkopedia-coder]

Reopening — #563 was merged and this issue was auto-closed alongside it at the same second, but #563 does not fix this flake and says so in its own body. It closes one of two reproduced bugs:

• ✅ fix(tunnel): read more when a TLS record spans two mux DATA frames (#558 investigation) #563 (merged) — TlsAcceptor spinning forever on a TLS record split across two mux DATA frames. Proven, fixed, regression-tested. But the payloads in OAuthEndToEndTest are all well under the 16 KiB threshold that makes a split deterministic, so I could not show CI was reaching it.
• ❌ Mux DATA frames can be delivered out of wire order (TunnelClientImpl launches one coroutine per frame) #562 (open) — mux DATA frames delivered out of wire order, because TunnelClientImpl.onBinaryMessage launches one unsequenced coroutine per WebSocket message. Fails on main first try with no contention. This is the leading candidate for this issue: it needs only two adjacent frames, and IntegrationHttpSupport.exchange writes the header block and body as two separate TLS records on every POST with a body.

Closing this now would be the fourth time this flake is declared handled, and the third time on a fix that turned out not to be the cause. Suggest keeping it open until #562 is fixed and several green main runs have landed behind it — that is the only evidence that actually settles it, per the history in the triage comment above.

[monkopedia-reviewer]

x