square
Infinite Retry happening (No cap on Okhttp retry count)
We are seeing infinite retries in OkHttp client (RetryAndFollowUpInterceptor).
I performed a Post Api request with connect, write and read timeout of 70 seconds. I used Charles to block the request so that it will not able to hit the server. I am expecting a SocketTimeoutException if I am blocking a request for greater than 70 sec, but I am getting Stream Reset Exception even before 70 sec (around 60 sec).
I am getting this error for the request: at Charles I am seeing: Socket: Connection or outbound has closed and at App Side: okhttp3.internal.http2.StreamResetException: stream was reset: REFUSED_STREAM
After getting this error at RetryAndFollowUpInterceptor, it again retries and this will continue infinitely (request is blocked at Charles)
Note: I tried many Api’s for finding this behaviour, but I found only one API.
Is there any solution to this problem?, if not then there should be some retryCount at OkHttp level where this kind of behaviour can be eliminated.
Can you attach a printing event listener and record the output. Its should show what's happening with connections?
It's hard to investigate from bug report without a repro test cade to run.
@yschimke, We are using OkHttp Version: 4.9.3 (I checked the latest version as well, I found the same behaviour).
These are Logs of EventListeners:
2022-11-30 12:56:37.410 29666-29717 NetworkE...istener net...m.networkmoduleapp I callStart 2022-11-30 12:56:37.414 29666-29717 NetworkE...istener net...m.networkmoduleapp I dnsStart 2022-11-30 12:56:37.416 29666-29717 NetworkE...istener net...m.networkmoduleapp I dnsEnd 2022-11-30 12:56:37.418 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectStart 2022-11-30 12:56:37.554 29666-29717 NetworkE...istener net...m.networkmoduleapp I secureConnectStart 2022-11-30 12:56:38.011 29666-29717 NetworkE...istener net...m.networkmoduleapp I secureConnectEnd 2022-11-30 12:56:38.033 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectEnd 2022-11-30 12:56:38.038 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectionAcquired 2022-11-30 12:56:38.039 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestHeadersStart 2022-11-30 12:56:38.047 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestHeadersEnd 2022-11-30 12:56:38.047 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestBodyStart 2022-11-30 12:56:38.048 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestBodyEnd 2022-11-30 12:57:38.252 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectionReleased 2022-11-30 12:57:38.256 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectStart 2022-11-30 12:57:38.385 29666-29717 NetworkE...istener net...m.networkmoduleapp I secureConnectStart 2022-11-30 12:57:38.820 29666-29717 NetworkE...istener net...m.networkmoduleapp I secureConnectEnd 2022-11-30 12:57:38.828 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectEnd 2022-11-30 12:57:38.831 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectionAcquired 2022-11-30 12:57:38.832 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestHeadersStart 2022-11-30 12:57:38.844 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestHeadersEnd 2022-11-30 12:57:38.844 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestBodyStart 2022-11-30 12:57:38.847 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestBodyEnd 2022-11-30 12:58:39.094 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectionReleased 2022-11-30 12:58:39.100 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectStart 2022-11-30 12:58:39.227 29666-29717 NetworkE...istener net...m.networkmoduleapp I secureConnectStart 2022-11-30 12:58:39.642 29666-29717 NetworkE...istener net...m.networkmoduleapp I secureConnectEnd 2022-11-30 12:58:39.649 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectEnd 2022-11-30 12:58:39.652 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectionAcquired 2022-11-30 12:58:39.653 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestHeadersStart 2022-11-30 12:58:39.665 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestHeadersEnd 2022-11-30 12:58:39.666 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestBodyStart 2022-11-30 12:58:39.667 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestBodyEnd 2022-11-30 12:59:39.918 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectionReleased 2022-11-30 12:59:39.921 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectStart 2022-11-30 12:59:39.992 29666-29717 NetworkE...istener net...m.networkmoduleapp I secureConnectStart 2022-11-30 12:59:40.363 29666-29717 NetworkE...istener net...m.networkmoduleapp I secureConnectEnd 2022-11-30 12:59:40.371 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectEnd 2022-11-30 12:59:40.372 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectionAcquired 2022-11-30 12:59:40.373 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestHeadersStart 2022-11-30 12:59:40.386 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestHeadersEnd 2022-11-30 12:59:40.386 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestBodyStart 2022-11-30 12:59:40.389 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestBodyEnd 2022-11-30 13:00:40.542 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectionReleased 2022-11-30 13:00:40.544 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectStart 2022-11-30 13:00:40.613 29666-29717 NetworkE...istener net...m.networkmoduleapp I secureConnectStart 2022-11-30 13:00:41.094 29666-29717 NetworkE...istener net...m.networkmoduleapp I secureConnectEnd 2022-11-30 13:00:41.106 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectEnd 2022-11-30 13:00:41.109 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectionAcquired 2022-11-30 13:00:41.109 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestHeadersStart 2022-11-30 13:00:41.124 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestHeadersEnd 2022-11-30 13:00:41.124 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestBodyStart 2022-11-30 13:00:41.127 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestBodyEnd 2022-11-30 13:01:41.262 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectionReleased 2022-11-30 13:01:41.264 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectStart 2022-11-30 13:01:41.341 29666-29717 NetworkE...istener net...m.networkmoduleapp I secureConnectStart 2022-11-30 13:01:41.711 29666-29717 NetworkE...istener net...m.networkmoduleapp I secureConnectEnd 2022-11-30 13:01:41.727 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectEnd 2022-11-30 13:01:41.729 29666-29717 NetworkE...istener net...m.networkmoduleapp I connectionAcquired 2022-11-30 13:01:41.732 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestHeadersStart 2022-11-30 13:01:41.752 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestHeadersEnd 2022-11-30 13:01:41.752 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestBodyStart 2022-11-30 13:01:41.758 29666-29717 NetworkE...istener net...m.networkmoduleapp I requestBodyEnd
These are the logs we receive at NetworkInterceptor (We are receiving exception so all the details of exception is here):
2022-11-30 12:57:38.239 29666-29717 ResponseData net...m.networkmoduleapp D Message: stream was reset: REFUSED_STREAM Cause: null StackTrace: [okhttp3.internal.http2.Http2Stream.takeHeaders(Http2Stream.kt:148), okhttp3.internal.http2.Http2ExchangeCodec.readResponseHeaders(Http2ExchangeCodec.kt:96), okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106), okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79), okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109), com.paytm.network.OkHttpStack.lambda$new$1(OkHttpStack.java:89), com.paytm.network.OkHttpStack$$ExternalSyntheticLambda1.intercept(Unknown Source:0), 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), okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201), okhttp3.internal.connection.RealCall.execute(RealCall.kt:154), com.paytm.network.OkHttpStack.executeRequest(OkHttpStack.java:195), com.paytm.network.CJRBasicNetwork.performRequest(CJRBasicNetwork.java:112), com.android.volley.NetworkDispatcher.processRequest(NetworkDispatcher.java:132), com.android.volley.NetworkDispatcher.processRequest(NetworkDispatcher.java:111), com.android.volley.NetworkDispatcher.run(NetworkDispatcher.java:90)] 2022-11-30 12:58:39.068 29666-29717 ResponseData net...m.networkmoduleapp D Message: stream was reset: REFUSED_STREAM Cause: null StackTrace: [okhttp3.internal.http2.Http2Stream.takeHeaders(Http2Stream.kt:148), okhttp3.internal.http2.Http2ExchangeCodec.readResponseHeaders(Http2ExchangeCodec.kt:96), okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106), okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79), okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109), com.paytm.network.OkHttpStack.lambda$new$1(OkHttpStack.java:89), com.paytm.network.OkHttpStack$$ExternalSyntheticLambda1.intercept(Unknown Source:0), 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), okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201), okhttp3.internal.connection.RealCall.execute(RealCall.kt:154), com.paytm.network.OkHttpStack.executeRequest(OkHttpStack.java:195), com.paytm.network.CJRBasicNetwork.performRequest(CJRBasicNetwork.java:112), com.android.volley.NetworkDispatcher.processRequest(NetworkDispatcher.java:132), com.android.volley.NetworkDispatcher.processRequest(NetworkDispatcher.java:111), com.android.volley.NetworkDispatcher.run(NetworkDispatcher.java:90)]
2022-11-30 12:59:39.894 29666-29717 ResponseData net...m.networkmoduleapp D Message: stream was reset: REFUSED_STREAM Cause: null StackTrace: [okhttp3.internal.http2.Http2Stream.takeHeaders(Http2Stream.kt:148), okhttp3.internal.http2.Http2ExchangeCodec.readResponseHeaders(Http2ExchangeCodec.kt:96), okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106), okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79), okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109), com.paytm.network.OkHttpStack.lambda$new$1(OkHttpStack.java:89), com.paytm.network.OkHttpStack$$ExternalSyntheticLambda1.intercept(Unknown Source:0), 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), okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201), okhttp3.internal.connection.RealCall.execute(RealCall.kt:154), com.paytm.network.OkHttpStack.executeRequest(OkHttpStack.java:195), com.paytm.network.CJRBasicNetwork.performRequest(CJRBasicNetwork.java:112), com.android.volley.NetworkDispatcher.processRequest(NetworkDispatcher.java:132), com.android.volley.NetworkDispatcher.processRequest(NetworkDispatcher.java:111), com.android.volley.NetworkDispatcher.run(NetworkDispatcher.java:90)]
2022-11-30 13:00:40.516 29666-29717 ResponseData net...m.networkmoduleapp D Message: stream was reset: REFUSED_STREAM Cause: null StackTrace: [okhttp3.internal.http2.Http2Stream.takeHeaders(Http2Stream.kt:148), okhttp3.internal.http2.Http2ExchangeCodec.readResponseHeaders(Http2ExchangeCodec.kt:96), okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106), okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79), okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109), com.paytm.network.OkHttpStack.lambda$new$1(OkHttpStack.java:89), com.paytm.network.OkHttpStack$$ExternalSyntheticLambda1.intercept(Unknown Source:0), 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), okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201), okhttp3.internal.connection.RealCall.execute(RealCall.kt:154), com.paytm.network.OkHttpStack.executeRequest(OkHttpStack.java:195), com.paytm.network.CJRBasicNetwork.performRequest(CJRBasicNetwork.java:112), com.android.volley.NetworkDispatcher.processRequest(NetworkDispatcher.java:132), com.android.volley.NetworkDispatcher.processRequest(NetworkDispatcher.java:111), com.android.volley.NetworkDispatcher.run(NetworkDispatcher.java:90)]
2022-11-30 13:01:41.239 29666-29717 ResponseData net...m.networkmoduleapp D Message: stream was reset: REFUSED_STREAM Cause: null StackTrace: [okhttp3.internal.http2.Http2Stream.takeHeaders(Http2Stream.kt:148), okhttp3.internal.http2.Http2ExchangeCodec.readResponseHeaders(Http2ExchangeCodec.kt:96), okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106), okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79), okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109), com.paytm.network.OkHttpStack.lambda$new$1(OkHttpStack.java:89), com.paytm.network.OkHttpStack$$ExternalSyntheticLambda1.intercept(Unknown Source:0), 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), okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201), okhttp3.internal.connection.RealCall.execute(RealCall.kt:154), com.paytm.network.OkHttpStack.executeRequest(OkHttpStack.java:195), com.paytm.network.CJRBasicNetwork.performRequest(CJRBasicNetwork.java:112), com.android.volley.NetworkDispatcher.processRequest(NetworkDispatcher.java:132), com.android.volley.NetworkDispatcher.processRequest(NetworkDispatcher.java:111), com.android.volley.NetworkDispatcher.run(NetworkDispatcher.java:90)]
That log isn't much help without details like the dns results.
See https://github.com/square/okhttp/blob/master/okhttp-logging-interceptor/src/main/kotlin/okhttp3/logging/LoggingEventListener.kt
It's probably retrying on multiple hosts returned by dns. You can disable retry on connection failures on the client if so.
But its hard to guess from the big report.
In RetryAndFollowUpInterceptor, we are getting this error response in 2nd catch block catch(e: IOException) and here it is recovering.
It definitely shouldn't be retrying infinitely, it clearly is because of callStart without callEnd or callFailed. I'll need to try to reproduce that locally. I'm not too worried about it, because it's with a contrived example. If we can manage to reproduce it with a real server, then it's quite serious.
Separately from that, while testing with Charles, you can set a callTimeout of 80 seconds that should stop the request, or retryOnConnectionFailure = false.
[0 ms] callStart: Request{method=POST, url=https://xyz.com//path/somePath/somMorePath?params1=par1¶ms2=par2, headers=[x-app-rid:51930544-f213-4be9-acc4-2a1cdb3636b0:1669801488129:1:2, Accept-Encoding:gzip, If-None-Match:W/"2-nOO9QiTIwXgNtWtBJezz8kv3SLc"]}
[7 ms] proxySelectStart: https://xyz.com/
[8 ms] proxySelectEnd: [HTTP @ x9x.1x8.xx.4x:xxx8]
[9 ms] dnsStart: x9x.1x8.xx.4x
[10 ms] dnsEnd: [/x9x.1x8.xx.4x]
[14 ms] connectStart: /x9x.1x8.xx.4x:xxx8 HTTP @ x9x.1x8.xx.4x:xxx8
[97 ms] secureConnectStart
[561 ms] secureConnectEnd: Handshake{tlsVersion=TLS_1_2 cipherSuite=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 peerCertificates=[CN=*.abc.com, O=abc ltd, L=dummyCity, ST=dummyState, C=IN, C=NZ, ST=Auckland, L=Auckland, O=XK72 Ltd, OU=https://charlesproxy.com/ssl, CN="Charles Proxy CA (11 Jul 2022, 197BLRMB40706.local)"] localCertificates=[]}
[584 ms] connectEnd: h2
[586 ms] connectionAcquired: Connection{xyz.com:443, proxy=HTTP @ x9x.1x8.xx.4x:xxx8 hostAddress=/x9x.1x8.xx.4x:xxx8 cipherSuite=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 protocol=h2}
[588 ms] requestHeadersStart
[595 ms] requestHeadersEnd
[596 ms] requestBodyStart
[597 ms] requestBodyEnd: byteCount=0
[60745 ms] responseFailed: okhttp3.internal.http2.StreamResetException: stream was reset: REFUSED_STREAM
[60753 ms] connectionReleased
[60755 ms] connectStart: /x9x.1x8.xx.4x:xxx8 HTTP @ x9x.1x8.xx.4x:xxx8
[60877 ms] secureConnectStart
[61368 ms] secureConnectEnd: Handshake{tlsVersion=TLS_1_2 cipherSuite=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 peerCertificates=[CN=*.abc.com, O=abc ltd, L=dummyCity, ST=dummyState, C=IN, C=NZ, ST=Auckland, L=Auckland, O=XK72 Ltd, OU=https://charlesproxy.com/ssl, CN="Charles Proxy CA (11 Jul 2022, 197BLRMB40706.local)"] localCertificates=[]}
[61375 ms] connectEnd: h2
[61377 ms] connectionAcquired: Connection{xyz.com:443, proxy=HTTP @ x9x.1x8.xx.4x:xxx8 hostAddress=/x9x.1x8.xx.4x:xxx8 cipherSuite=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 protocol=h2}
[61380 ms] requestHeadersStart
[61382 ms] requestHeadersEnd
[61383 ms] requestBodyStart
[61384 ms] requestBodyEnd: byteCount=0
[121469 ms] responseFailed: okhttp3.internal.http2.StreamResetException: stream was reset: REFUSED_STREAM
[121492 ms] connectionReleased
[121498 ms] connectStart: /x9x.1x8.xx.4x:xxx8 HTTP @ x9x.1x8.xx.4x:xxx8
I'll take a look at why that is.
Yeap this happens to me as well, I have multiple instances of my backend server running so dnsEnd returns 4 addresses and the endpoint times out but the client keeps trying all the different IPs even if I have set .retryOnConnectionFailure(false)
Any ideas? Any older version that was working to downgrade?
@Yogesh-1206 also I am noticing that even if all 4 retries are getting timed out one or two of them actually reaching the backend so I am assuming the TCP connection to the current target is not properly terminated when you go and try the next server in the list
I tried to make a repro on 5.x without any luck. The charles server and the proxy are different though. Before I start manually testing, can you provide additional information such as the exact OkHttp you are using?
OK, can reproduce something sort of like this on 4.10.
/**
* Return the route from the current connection if it should be retried, even if the connection
* itself is unhealthy. The biggest gotcha here is that we shouldn't reuse routes from coalesced
* connections.
*/
private fun retryRoute(): Route? {
But my repro only causes a second follow up, but it's definitely possible that the proxy plus other traffic is causing the connection to stay healthy and get retried continually.
It might be worth trying to 5.0.0-alpha.10, while I continue to investigate.
I'd like to confirm against 5.0.0-alpha.10, before deciding any changes.
OK, my test with 5.x, is also using happy eyeballs (fastFallback(true)) so I should disable that.
I confirmed this case, I don't think RealConnection.trackFailure will avoid this.
I'm going to continue this in https://github.com/square/okhttp/pull/7588
thanks @yschimke for reaching back.
So in order to get this right does it make sense to try using 5.0.0-alpha.10 or not?
Please try against 5.0.0-alpha11, it should have fast fallback enabled and I hope it solves this. But there is still an underlying issue I'm working through from the bottom up, putting tests in place first.
If we can eventually reproduce your exact situation in https://github.com/square/okhttp/blob/ebb6e92d93f1725eacfd12b6b1afec95b4f704e9/okhttp/src/jvmTest/java/okhttp3/RouteFailureTest.kt we can make sure it's fixed. But I'm not sure if it will be easy to backport.