The calltimeout setting sometimes does not take effect

[hkj-07]

The calltimeout setting sometimes does not take effect. For example, a 10s calltimeout is set, but sometimes it does not close after 10s, and finally closes around 1000s.

[swankjesse]

Yikes; that’s severe. I wonder if this is related to full write buffers on the outbound TCP socket. I believe that can be a problem!

[yschimke]

@swankjesse What's the theory or observable way to reproduce or fake? A delegating Socket that blocks writes?

[swankjesse]

Yeah, a server that doesn’t read anything should do it.

[swankjesse]

(That’ll only catch a broken write timeout. A broken call timeout should still work fine.)

[yschimke]

closing as not reproducible, although possible relates to duplex requests

[alex859]

Hello, we are currently investigating a similar issue using OkHttp 4.12.0.

Call timeout set to 3s on the OkHttp instance:

val okHttp = OkHttpClient.Builder().callTimeout(timeout).build()

It did not trigger for ~10 minutes. Eventually a InterruptedIOException("timeout") was thrown.

From the OpenTelemetry trace there is sign of a okhttp3.internal.http2.ConnectionShutdownException thrown with the following stack trace:

okhttp3.internal.http2.Http2Connection.newStream (Http2Connection.kt:246)
okhttp3.internal.http2.Http2Connection.newStream (Http2Connection.kt:225)
okhttp3.internal.http2.Http2ExchangeCodec.writeRequestHeaders (Http2ExchangeCodec.kt:76)
okhttp3.internal.connection.Exchange.writeRequestHeaders (Exchange.kt:63)
okhttp3.internal.http.CallServerInterceptor.intercept (CallServerInterceptor.kt:41)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:109)
io.opentelemetry.javaagent.shaded.instrumentation.okhttp.v3_0.internal.TracingInterceptor.intercept (TracingInterceptor.java:47)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:109)
okhttp3.internal.connection.ConnectInterceptor.intercept (ConnectInterceptor.kt:34)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:109)
okhttp3.internal.cache.CacheInterceptor.intercept (CacheInterceptor.kt:95)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:109)
okhttp3.internal.http.BridgeInterceptor.intercept (BridgeInterceptor.kt:83)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:109)
okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept (RetryAndFollowUpInterceptor.kt:76)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:109)
io.opentelemetry.javaagent.shaded.instrumentation.okhttp.v3_0.internal.ConnectionErrorSpanInterceptor.intercept (ConnectionErrorSpanInterceptor.java:38)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:109)
io.opentelemetry.javaagent.instrumentation.okhttp.v3_0.OkHttp3Singletons.lambda$static$2 (OkHttp3Singletons.java:46)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:109)
okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp (RealCall.kt:201)
okhttp3.internal.connection.RealCall.execute (RealCall.kt:154)

The issue lasted 7 minutes only on 1 out of 3 instances of our app, then it started behaving as expected.

Did you guys had another chance to look into this?

What's your advice to make sure that the timeout is applied?

Thanks.

[swankjesse]

Reopening to consider @alex859’s crash.

[alex859]

Thank you @swankjesse for looking into this.

Since the last message we've updated to OkHttp 5.1.0 and the issue is still happening.

We now have a workaround that uses a coroutine managed timeout slightly higher than the call timeout set in OkHttp:

private fun Call.executeWithTimeout(killTimeout: Duration): Response =
    runBlocking(Dispatchers.IO) {
        withTimeout(killTimeout) {
            executeAsync()
        }
    }

This avoids having a thread stuck waiting for minutes.

The exception we can see in AWS X-Ray is now different:

• type: okhttp3.internal.http2.StreamResetException
• message: stream was reset: CANCEL
• stack trace:

okhttp3.internal.http2.Http2Stream.takeHeaders (Http2Stream.kt:166)
okhttp3.internal.http2.Http2ExchangeCodec.readResponseHeaders (Http2ExchangeCodec.kt:105)
okhttp3.internal.connection.Exchange.readResponseHeaders (Exchange.kt:117)
okhttp3.internal.http.CallServerInterceptor.intercept (CallServerInterceptor.kt:97)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
io.opentelemetry.javaagent.shaded.instrumentation.okhttp.v3_0.internal.TracingInterceptor.intercept (TracingInterceptor.java:47)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
okhttp3.internal.connection.ConnectInterceptor.intercept (ConnectInterceptor.kt:34)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
okhttp3.internal.cache.CacheInterceptor.intercept (CacheInterceptor.kt:101)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
okhttp3.internal.http.BridgeInterceptor.intercept (BridgeInterceptor.kt:85)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept (RetryAndFollowUpInterceptor.kt:74)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
io.opentelemetry.javaagent.shaded.instrumentation.okhttp.v3_0.internal.ConnectionErrorSpanInterceptor.intercept (ConnectionErrorSpanInterceptor.java:38)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
io.opentelemetry.javaagent.instrumentation.okhttp.v3_0.OkHttp3Singletons.lambda$static$2 (OkHttp3Singletons.java:46)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp (RealCall.kt:226)
okhttp3.internal.connection.RealCall$AsyncCall.run (RealCall.kt:574)
java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1144)
java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:642)
java.lang.Thread.run (Thread.java:1583)

Our next guess will be to force the connection to be over HTTP/1.1.

Is there anything we could do to help with the investigation?

[alex859]

We've tried enforcing HTTP/1.1 and we still get the same behaviour, but with a different excepion in X-Ray:

• type: java.net.SocketException
• message: Socket closed
• stack trace:

sun.nio.ch.NioSocketImpl.endRead (NioSocketImpl.java:243)
sun.nio.ch.NioSocketImpl.implRead (NioSocketImpl.java:323)
sun.nio.ch.NioSocketImpl.read (NioSocketImpl.java:346)
sun.nio.ch.NioSocketImpl$1.read (NioSocketImpl.java:796)
java.net.Socket$SocketInputStream.read (Socket.java:1099)
sun.security.ssl.SSLSocketInputRecord.read (SSLSocketInputRecord.java:489)
sun.security.ssl.SSLSocketInputRecord.readHeader (SSLSocketInputRecord.java:483)
sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket (SSLSocketInputRecord.java:70)
sun.security.ssl.SSLSocketImpl.readApplicationRecord (SSLSocketImpl.java:1461)
sun.security.ssl.SSLSocketImpl$AppInputStream.read (SSLSocketImpl.java:1066)
okio.internal.DefaultSocket$SocketSource.read (DefaultSocket.kt:124)
okio.RealBufferedSource.indexOf (RealBufferedSource.kt:457)
okio.RealBufferedSource.readUtf8LineStrict (RealBufferedSource.kt:350)
okhttp3.internal.http1.HeadersReader.readLine (HeadersReader.kt:31)
okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders (Http1ExchangeCodec.kt:196)
okhttp3.internal.connection.Exchange.readResponseHeaders (Exchange.kt:117)
okhttp3.internal.http.CallServerInterceptor.intercept (CallServerInterceptor.kt:97)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
io.opentelemetry.javaagent.shaded.instrumentation.okhttp.v3_0.internal.TracingInterceptor.intercept (TracingInterceptor.java:47)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
okhttp3.internal.connection.ConnectInterceptor.intercept (ConnectInterceptor.kt:34)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
okhttp3.internal.cache.CacheInterceptor.intercept (CacheInterceptor.kt:101)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
okhttp3.internal.http.BridgeInterceptor.intercept (BridgeInterceptor.kt:85)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept (RetryAndFollowUpInterceptor.kt:74)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
io.opentelemetry.javaagent.shaded.instrumentation.okhttp.v3_0.internal.ConnectionErrorSpanInterceptor.intercept (ConnectionErrorSpanInterceptor.java:38)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
io.opentelemetry.javaagent.instrumentation.okhttp.v3_0.OkHttp3Singletons.lambda$static$2 (OkHttp3Singletons.java:46)
okhttp3.internal.http.RealInterceptorChain.proceed (RealInterceptorChain.kt:126)
okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp (RealCall.kt:226)
okhttp3.internal.connection.RealCall$AsyncCall.run (RealCall.kt:574)
java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1144)
java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:642)
java.lang.Thread.run (Thread.java:1583)

We've found that the issue happens more often after upgrading to OkHttp 5.2.0.

[yschimke]

I'm assuming the type of exception is the server closing your connection, because it notices a stall. While OkHttp isn't.

If so, we are still with trying to work out why OkHttp isn't honouring the call timeout.

[jozzas]

I've been working on a chaos test which introduces 100% packet loss and this is causing all threads to become stuck - I think this is the same issue?

The scenario spins up the service, throws normal traffic at it and then introduces 100% packet loss - so there will be HTTP2 connections established and ready to be re-used.

17 Nov 2025 02:07:15,652 [WARN] Thread 11 is detected as stuck as it has been blocked for 943918 ms. 
StuckThreadDetector$StuckThreadException: Thread is in [BLOCKED] state because it's blocked by OkHttp external-api-endpoint.com[1777] writeSynReset.	
at okhttp3.internal.http2.Http2Connection.newStream(Http2Connection.kt:240)	
at okhttp3.internal.http2.Http2Connection.newStream(Http2Connection.kt:225)	
at okhttp3.internal.http2.Http2ExchangeCodec.writeRequestHeaders(Http2ExchangeCodec.kt:76)	
at okhttp3.internal.connection.Exchange.writeRequestHeaders(Exchange.kt:63)	
at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:41)	
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)	
at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34)	
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95) 
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)

Looking at the implementation, the thread could be blocked in writer.headers() or writer.flush() while holding the writer.withLock mutex?

My understanding is the thread is stuck in kernel space and not interruptible by Java timeouts - my callTimeout can't interrupt this thread since it's blocked in native I/O.