OkHttp call timeout is ignored

Question

I have a Spring Boot app that receives messages from Kafka and sends them to other REST web services using OkHttp. Messages are XML, requests are POST, communication is over HTTP (no HTTPS) and receiving web services are always addressed by IP addresses. I've configured RestTemplate to use OkHttpClient the following way:

@Bean
public RestTemplate restTemplate() {
    OkHttpClient httpClient = new OkHttpClient.Builder()
        .connectTimeout(ofMillis(2000))
        .readTimeout(ofMillis(11000))
        .writeTimeout(ofMillis(5000))
        .callTimeout(ofMillis(30000))
        .connectionPool(new ConnectionPool(250, 5000, TimeUnit.MILLISECONDS))
        .retryOnConnectionFailure(false)
        .build();
    return new RestTemplate(new OkHttp3ClientHttpRequestFactory(httpClient));
}

However, in some specific situations the call timeout is ignored, and with the config above I see some of my POST requests taking 50+ seconds to execute. It happens on production and I can't figure out the case to reproduce it. I've checked RestTemplate instance in debug mode locally just prior to sending and I can see my timeouts configured properly. Also tested call timeout locally by sending to httpbin.org and requests are terminated after timeout as expected. In production logs I see my read timeout in effect, so I believe my configuration is applied, but problematic case still persists. Can anyone help me in figuring out the problem?

Java 8, Spring Boot 2.1.10, OkHttp tried 3.14.9 and 4.2.2 (can't go newer)

One thing I noticed is that when my request takes 50+ seconds to execute, the exception thrown is

I/O error on POST request for "http://x:y/z": timeout; nested exception is java.net.SocketTimeoutException: timeout

but when I tested call timeout using httpbin.org, the exception was

I/O error on POST request for "http://httpbin.org/delay/10": timeout; nested exception is java.io.InterruptedIOException: timeout

so I think call timeout is ignored and either read or write timeout occurs in the first case, but why?

Edit: stack dump for the case when call timeout is ignored using OkHttp 3.14.9:

I/O error on POST request for "http://x:y/z": timeout; nested exception is java.net.SocketTimeoutException: timeout
org.springframework.web.client.ResourceAccessException: I/O error on POST request for "http://x:y/z": timeout; nested exception is java.net.SocketTimeoutException: timeout
    at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:744)
    at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:670)
    at org.springframework.web.client.RestTemplate.postForEntity(RestTemplate.java:445)
    ...
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeOnMessage(KafkaMessageListenerContainer.java:1325)
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeOnMessage(KafkaMessageListenerContainer.java:1293)
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeRecordListener(KafkaMessageListenerContainer.java:1253)
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.doInvokeWithRecords(KafkaMessageListenerContainer.java:1234)
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeRecordListener(KafkaMessageListenerContainer.java:1149)
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.invokeListener(KafkaMessageListenerContainer.java:959)
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.pollAndInvoke(KafkaMessageListenerContainer.java:766)
    at org.springframework.kafka.listener.KafkaMessageListenerContainer$ListenerConsumer.run(KafkaMessageListenerContainer.java:704)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.net.SocketTimeoutException: timeout
    at okio.Okio$4.newTimeoutException(Okio.java:232)
    at okio.AsyncTimeout.exit(AsyncTimeout.java:286)
    at okio.AsyncTimeout$2.read(AsyncTimeout.java:241)
    at okio.RealBufferedSource.indexOf(RealBufferedSource.java:358)
    at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:230)
    at okhttp3.internal.http1.Http1ExchangeCodec.readHeaderLine(Http1ExchangeCodec.java:242)
    at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.java:213)
    at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.java:115)
    at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:94)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142)
    at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:43)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117)
    at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:94)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117)
    at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142)
    at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:88)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:142)
    at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:117)
    at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:229)
    at okhttp3.RealCall.execute(RealCall.java:81)
    at org.springframework.http.client.OkHttp3ClientHttpRequest.executeInternal(OkHttp3ClientHttpRequest.java:73)
    at org.springframework.http.client.AbstractBufferingClientHttpRequest.executeInternal(AbstractBufferingClientHttpRequest.java:48)
    at org.springframework.http.client.AbstractClientHttpRequest.execute(AbstractClientHttpRequest.java:53)
    at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:735)
    ... 18 common frames omitted
Caused by: java.net.SocketException: Socket closed
    at java.net.SocketInputStream.read(SocketInputStream.java:204)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at okio.Okio$2.read(Okio.java:140)
    at okio.AsyncTimeout$2.read(AsyncTimeout.java:237)
    ... 42 common frames omitted

Edit: event listener logs when using OkHttp 3.14.9:

GAP AFTER callStart
10-04-2021 10:57:47,502 INFO  (Platform.java:135) - [0 ms] 1099137-callStart: Request{method=POST, url=http://x:y/z, tags={}}
10-04-2021 10:58:32,690 INFO  (Platform.java:135) - [45187 ms] 1099137-callFailed: java.io.InterruptedIOException: timeout

GAP AFTER connectionAcquired
10-04-2021 10:57:47,502 INFO  (Platform.java:135) - [0 ms] 1099136-callStart: Request{method=POST, url=http://x:y/z, tags={}}
10-04-2021 10:57:47,502 INFO  (Platform.java:135) - [0 ms] 1099136-connectionAcquired: Connection{x:y, proxy=DIRECT hostAddress=/x:y cipherSuite=none protocol=http/1.1}
10-04-2021 10:58:32,098 INFO  (Platform.java:135) - [44595 ms] 1099136-connectionReleased
10-04-2021 10:58:32,697 INFO  (Platform.java:135) - [45195 ms] 1099136-callFailed: java.io.InterruptedIOException: timeout

GAP AFTER requestHeadersStart
10-04-2021 10:57:47,501 INFO  (Platform.java:135) - [0 ms] 1099134-callStart: Request{method=POST, url=http://x:y/z, tags={}}
10-04-2021 10:57:47,502 INFO  (Platform.java:135) - [0 ms] 1099134-connectionAcquired: Connection{x:y, proxy=DIRECT hostAddress=/x:y cipherSuite=none protocol=http/1.1}
10-04-2021 10:57:47,554 INFO  (Platform.java:135) - [52 ms] 1099134-requestHeadersStart
10-04-2021 10:58:32,694 INFO  (Platform.java:135) - [45192 ms] 1099134-requestHeadersEnd
10-04-2021 10:58:32,740 INFO  (Platform.java:135) - [45238 ms] 1099134-requestBodyStart
10-04-2021 10:58:32,740 INFO  (Platform.java:135) - [45238 ms] 1099134-requestBodyEnd: byteCount=1476
10-04-2021 10:58:32,740 INFO  (Platform.java:135) - [45238 ms] 1099134-requestFailed: java.net.SocketException: Socket closed
10-04-2021 10:58:32,740 INFO  (Platform.java:135) - [45238 ms] 1099134-connectionReleased
10-04-2021 10:58:32,741 INFO  (Platform.java:135) - [45239 ms] 1099134-callFailed: java.io.InterruptedIOException: timeout

GAP AFTER requestBodyEnd
10-04-2021 14:07:14,969 INFO  (Platform.java:135) - [0 ms] 1427963-callStart: Request{method=POST, url=http://x:y/z, tags={}}
10-04-2021 14:07:14,969 INFO  (Platform.java:135) - [0 ms] 1427963-dnsStart: x
10-04-2021 14:07:14,970 INFO  (Platform.java:135) - [0 ms] 1427963-dnsEnd: [/x]
10-04-2021 14:07:14,970 INFO  (Platform.java:135) - [0 ms] 1427963-connectStart: /x:y DIRECT
10-04-2021 14:07:14,993 INFO  (Platform.java:135) - [24 ms] 1427963-connectEnd: http/1.1
10-04-2021 14:07:14,994 INFO  (Platform.java:135) - [24 ms] 1427963-connectionAcquired: Connection{x:y, proxy=DIRECT hostAddress=/x:y cipherSuite=none protocol=http/1.1}
10-04-2021 14:07:14,994 INFO  (Platform.java:135) - [24 ms] 1427963-requestHeadersStart
10-04-2021 14:07:14,994 INFO  (Platform.java:135) - [24 ms] 1427963-requestHeadersEnd
10-04-2021 14:07:14,994 INFO  (Platform.java:135) - [24 ms] 1427963-requestBodyStart
10-04-2021 14:07:15,050 INFO  (Platform.java:135) - [80 ms] 1427963-requestBodyEnd: byteCount=87191
10-04-2021 14:08:02,949 INFO  (Platform.java:135) - [47979 ms] 1427963-requestFailed: java.net.SocketException: Socket closed
10-04-2021 14:08:03,396 INFO  (Platform.java:135) - [48426 ms] 1427963-connectionReleased
10-04-2021 14:08:03,400 INFO  (Platform.java:135) - [48430 ms] 1427963-callFailed: java.io.InterruptedIOException: timeout

GAP AFTER responseFailed
10-04-2021 10:19:07,289 INFO  (Platform.java:135) - [0 ms] 1037242-callStart: Request{method=POST, url=http://x:y/z, tags={}}
10-04-2021 10:19:07,290 INFO  (Platform.java:135) - [0 ms] 1037242-dnsStart: x
10-04-2021 10:19:07,290 INFO  (Platform.java:135) - [0 ms] 1037242-dnsEnd: [/x]
10-04-2021 10:19:07,290 INFO  (Platform.java:135) - [0 ms] 1037242-connectStart: /x:y DIRECT
10-04-2021 10:19:07,313 INFO  (Platform.java:135) - [23 ms] 1037242-connectEnd: http/1.1
10-04-2021 10:19:07,313 INFO  (Platform.java:135) - [23 ms] 1037242-connectionAcquired: Connection{x:y, proxy=DIRECT hostAddress=/x:y cipherSuite=none protocol=http/1.1}
10-04-2021 10:19:07,314 INFO  (Platform.java:135) - [24 ms] 1037242-requestHeadersStart
10-04-2021 10:19:07,314 INFO  (Platform.java:135) - [24 ms] 1037242-requestHeadersEnd
10-04-2021 10:19:07,314 INFO  (Platform.java:135) - [24 ms] 1037242-requestBodyStart
10-04-2021 10:19:07,314 INFO  (Platform.java:135) - [24 ms] 1037242-requestBodyEnd: byteCount=1476
10-04-2021 10:19:07,314 INFO  (Platform.java:135) - [24 ms] 1037242-responseHeadersStart
10-04-2021 10:19:18,315 INFO  (Platform.java:135) - [11025 ms] 1037242-responseFailed: java.net.SocketTimeoutException: timeout
10-04-2021 10:20:04,043 INFO  (Platform.java:135) - [56753 ms] 1037242-connectionReleased
10-04-2021 10:20:04,413 INFO  (Platform.java:135) - [57123 ms] 1037242-callFailed: java.io.InterruptedIOException: timeout

GAP AFTER responseHeadersEnd
10-04-2021 14:07:14,990 INFO  (Platform.java:135) - [0 ms] 1427964-callStart: Request{method=POST, url=http://x:y/z, tags={}}
10-04-2021 14:07:14,991 INFO  (Platform.java:135) - [0 ms] 1427964-connectionAcquired: Connection{x:y, proxy=DIRECT hostAddress=/x:y cipherSuite=none protocol=http/1.1}
10-04-2021 14:07:14,992 INFO  (Platform.java:135) - [1 ms] 1427964-requestHeadersStart
10-04-2021 14:07:14,992 INFO  (Platform.java:135) - [1 ms] 1427964-requestHeadersEnd
10-04-2021 14:07:14,992 INFO  (Platform.java:135) - [1 ms] 1427964-requestBodyStart
10-04-2021 14:07:14,992 INFO  (Platform.java:135) - [2 ms] 1427964-requestBodyEnd: byteCount=1520
10-04-2021 14:07:14,993 INFO  (Platform.java:135) - [2 ms] 1427964-responseHeadersStart
10-04-2021 14:07:15,022 INFO  (Platform.java:135) - [31 ms] 1427964-responseHeadersEnd: Response{protocol=http/1.1, code=200, message=OK, url=http://x:y/z}
10-04-2021 14:08:02,949 INFO  (Platform.java:135) - [47958 ms] 1427964-responseBodyStart
10-04-2021 14:08:03,393 INFO  (Platform.java:135) - [48403 ms] 1427964-responseBodyEnd: byteCount=0
10-04-2021 14:08:03,397 INFO  (Platform.java:135) - [48407 ms] 1427964-connectionReleased
10-04-2021 14:08:03,444 INFO  (Platform.java:135) - [48454 ms] 1427964-callFailed: java.io.InterruptedIOException: timeout

Can you get a stack dump? it sounds like the socket isn't failing a read or similar when the interrupt is happening. Maybe a different JDK, or JSSE provider? — Yuri Schimke, Apr 09 '21 at 07:12
@YuriSchimke I've added a stack dump for the exception, if I understood you correctly. The JDK versions between production server and my local machine are indeed different, but I'm not sure I can find that version to try reproducing the problem and OS is different too. Thanks for giving me ideas to research. — chewse, Apr 09 '21 at 09:46
That looks reasonable - next is probably adding an event listener https://stackoverflow.com/a/66398516/1542667, which is one line in the build file, and one line in code. — Yuri Schimke, Apr 09 '21 at 10:57
I'd love to know if the AsyncTimeout is being triggered after 30s (and the socket close takes 20s to fail) or if it's being triggered after 50s. Not sure how to tell this without a reproduction. Maybe a log line in a custom build? — Jesse Wilson, Apr 09 '21 at 11:11
@YuriSchimke when using versions newer than 4.2.2 I get some Kotlin exception, I think it's because of my Spring Boot version, which I cannot upgrade easily. — chewse, Apr 09 '21 at 11:54
@JesseWilson Idk what AsyncTimeout signifies, but I'm pretty sure no timeout is getting triggered after 30s, because by investigating the log I see multiple cases when my requests are successful after taking 50+s to execute, i.e., after such period result is not always an exception. — chewse, Apr 09 '21 at 11:58
@JesseWilson think this is missing from eventlistener. We only show the result. Not the trigger. — Yuri Schimke, Apr 09 '21 at 11:58
@YuriSchimke I've added event listener logs for different cases of the exception and I'm even more confused now. Maybe I misunderstood the use case of a call timeout, but I thought it will hide me from all lower level stuff. I just set the timeout and make a call. Whatever happens during the call is handled by HttpClient and if the call timeout is exceeded exception would be thrown immediately without me needing to change any OS-specific configs. Is the intended use case of the call timeout as such? — chewse, Apr 10 '21 at 11:10

OkHttp call timeout is ignored

0 Answers0