Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Infinite Retry happening (No cap on Okhttp retry count) #7530

Open
Yogesh-1206 opened this issue Nov 29, 2022 · 15 comments
Open

Infinite Retry happening (No cap on Okhttp retry count) #7530

Yogesh-1206 opened this issue Nov 29, 2022 · 15 comments
Labels
bug Bug in existing code needs info More information needed from reporter
Milestone

Comments

@Yogesh-1206
Copy link

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)

Screenshot 2022-11-24 at 2 32 09 PM

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.

@Yogesh-1206 Yogesh-1206 added the bug Bug in existing code label Nov 29, 2022
@yschimke
Copy link
Collaborator

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.

@Yogesh-1206
Copy link
Author

@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)]

@yschimke
Copy link
Collaborator

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.

@Yogesh-1206
Copy link
Author

Yogesh-1206 commented Dec 6, 2022

@yschimke please check these logs
OkHttp Issue.txt

@Yogesh-1206
Copy link
Author

In RetryAndFollowUpInterceptor, we are getting this error response in 2nd catch block catch(e: IOException) and here it is recovering.

@yschimke
Copy link
Collaborator

yschimke commented Dec 11, 2022

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&params2=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.

@sterien7
Copy link

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?

@sterien7
Copy link

@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

@yschimke
Copy link
Collaborator

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?

@Yogesh-1206
Copy link
Author

OkHttp Version: 4.9.3

@yschimke
Copy link
Collaborator

yschimke commented Dec 21, 2022

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.

@yschimke yschimke added the needs info More information needed from reporter label Dec 22, 2022
@yschimke
Copy link
Collaborator

yschimke commented Dec 22, 2022

OK, my test with 5.x, is also using happy eyeballs (fastFallback(true)) so I should disable that.

@yschimke
Copy link
Collaborator

I confirmed this case, I don't think RealConnection.trackFailure will avoid this.

I'm going to continue this in #7588

@sterien7
Copy link

sterien7 commented Jan 4, 2023

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?

@swankjesse swankjesse added this to the 5.0 milestone Jan 4, 2023
@yschimke
Copy link
Collaborator

yschimke commented Jan 4, 2023

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Bug in existing code needs info More information needed from reporter
Projects
None yet
Development

No branches or pull requests

4 participants