search

square / okhttp

Square’s meticulous HTTP client for the JVM, Android, and GraalVM.
https://square.github.io/okhttp/
Apache License 2.0
45.9k stars 9.16k forks source link

Incorrect retries on connection that still succeeded #8587

Open speekha opened 3 days ago

speekha commented 3 days ago

We've wanted to upgrade OkHttp v4.x for quite a while now, but we can't because of some change regarding the connection pool and its impact on the retry policy. In some cases, we can see a connection going to a server and being answered (we use proxyman to track network flows, and we can see both request and response going through), but for some reason, OkHttp decides to silently drop that connection even though it was successful and retry it (not sure if the connection was deemed stale and thus closed). So we see a second request going through in proxyman (which ends up with an error from the server in some cases because it was already processed the first time, authentication for instance), and in our code, the only result that we receive is that second one (the server error).

We've encountered the problem with all v 4.x versions that we've tested so far, but never had the problem with v3.x (currently 3.14.9). The exact conditions are hard to reproduce, but if you disable the retryOnConnectionFailure, you end up with an IOException. This means that for some reason, the socket was closed by OkHttp v4.x, in a way that did not happen in OkHttp v3.x, leading to this exception:

Error response java.io.IOException: unexpected end of stream on https://www.xxxxxxxxxx.fr/... at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:210) at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:110) at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:93) 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) at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201) at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637) at java.lang.Thread.run(Thread.java:1012) Caused by: java.io.EOFException: \n not found: limit=0 content=… at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:335) at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:29) at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:180) at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:110) at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:93) 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) at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201) at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637) at java.lang.Thread.run(Thread.java:1012) at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:525) at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:210) at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:110) at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:93) 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) at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201) at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517) at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:29) at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:180)

Every time that we've tried to upgrade and faced the issue, reverting to OkHttp 3 solved the problem.

PS : I opened that issue a few month ago, but it got closed erroneously (the bug that was fixed had nothing to do with the original problem.

speekha commented 3 days ago

Here's some additional logs leading up to the exception.

2024-07-11 16:01:30.624 11418-14990 System.err W OkHttp Extra [2024-07-11 16:01:30] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:01:30.630 11418-14990 System.err W OkHttp Extra [2024-07-11 16:01:30] Q10000 run again after 0 µs: OkHttp ConnectionPool 2024-07-11 16:01:30.630 11418-14990 System.err W OkHttp Extra [2024-07-11 16:01:30] Q10000 finished run in 9 ms: OkHttp ConnectionPool 2024-07-11 16:01:30.630 11418-14990 System.err W OkHttp Extra [2024-07-11 16:01:30] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:01:30.630 11418-14990 System.err W OkHttp Extra [2024-07-11 16:01:30] Q10000 run again after 938 ms: OkHttp ConnectionPool 2024-07-11 16:01:30.630 11418-14990 System.err W OkHttp Extra [2024-07-11 16:01:30] Q10000 finished run in 212 µs: OkHttp ConnectionPool 2024-07-11 16:01:31.571 11418-14990 System.err W OkHttp Extra [2024-07-11 16:01:31] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:01:31.572 11418-14990 System.err W OkHttp Extra [2024-07-11 16:01:31] Q10000 run again after 0 µs: OkHttp ConnectionPool 2024-07-11 16:01:31.573 11418-14990 System.err W OkHttp Extra [2024-07-11 16:01:31] Q10000 finished run in 2 ms: OkHttp ConnectionPool 2024-07-11 16:01:31.573 11418-14990 System.err W OkHttp Extra [2024-07-11 16:01:31] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:01:31.573 11418-14990 System.err W OkHttp Extra [2024-07-11 16:01:31] Q10000 run again after 4 s : OkHttp ConnectionPool 2024-07-11 16:01:31.573 11418-14990 System.err W OkHttp Extra [2024-07-11 16:01:31] Q10000 finished run in 191 µs: OkHttp ConnectionPool 2024-07-11 16:01:35.109 11418-14990 System.err W OkHttp Extra [2024-07-11 16:01:35] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:01:35.110 11418-14990 System.err W OkHttp Extra [2024-07-11 16:01:35] Q10000 finished run in 2 ms: OkHttp ConnectionPool 2024-07-11 16:23:58.278 11418-15506 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:23:58.278 11418-15507 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 already scheduled : OkHttp ConnectionPool 2024-07-11 16:23:58.280 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:23:58.280 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 run again after 300 s : OkHttp ConnectionPool 2024-07-11 16:23:58.281 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 finished run in 430 µs: OkHttp ConnectionPool 2024-07-11 16:23:58.440 11418-15511 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:23:58.440 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:23:58.440 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 run again after 300 s : OkHttp ConnectionPool 2024-07-11 16:23:58.440 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 finished run in 285 µs: OkHttp ConnectionPool 2024-07-11 16:23:58.592 11418-15506 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:23:58.593 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:23:58.593 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 run again after 300 s : OkHttp ConnectionPool 2024-07-11 16:23:58.594 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 finished run in 841 µs: OkHttp ConnectionPool 2024-07-11 16:23:58.716 11418-15511 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:23:58.716 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:23:58.716 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 run again after 300 s : OkHttp ConnectionPool 2024-07-11 16:23:58.717 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 finished run in 316 µs: OkHttp ConnectionPool 2024-07-11 16:23:58.783 11418-15506 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:23:58.783 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:23:58.783 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 run again after 300 s : OkHttp ConnectionPool 2024-07-11 16:23:58.783 11418-15510 System.err W OkHttp Extra [2024-07-11 16:23:58] Q10000 finished run in 295 µs: OkHttp ConnectionPool 2024-07-11 16:28:58.602 11418-15510 System.err W OkHttp Extra [2024-07-11 16:28:58] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:28:58.624 11418-15510 System.err W OkHttp Extra [2024-07-11 16:28:58] Q10000 run again after 0 µs: OkHttp ConnectionPool 2024-07-11 16:28:58.624 11418-15510 System.err W OkHttp Extra [2024-07-11 16:28:58] Q10000 finished run in 30 ms: OkHttp ConnectionPool 2024-07-11 16:28:58.625 11418-15510 System.err W OkHttp Extra [2024-07-11 16:28:58] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:28:58.627 11418-15510 System.err W OkHttp Extra [2024-07-11 16:28:58] Q10000 run again after 157 ms: OkHttp ConnectionPool 2024-07-11 16:28:58.628 11418-15510 System.err W OkHttp Extra [2024-07-11 16:28:58] Q10000 finished run in 2 ms: OkHttp ConnectionPool 2024-07-11 16:28:58.785 11418-15510 System.err W OkHttp Extra [2024-07-11 16:28:58] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:28:58.787 11418-15510 System.err W OkHttp Extra [2024-07-11 16:28:58] Q10000 finished run in 2 ms: OkHttp ConnectionPool 2024-07-11 16:53:47.000 11418-15715 System.err W OkHttp Extra [2024-07-11 16:53:47] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:53:47.001 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:47] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:53:47.001 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:47] Q10000 run again after 300 s : OkHttp ConnectionPool 2024-07-11 16:53:47.001 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:47] Q10000 finished run in 620 µs: OkHttp ConnectionPool 2024-07-11 16:53:47.253 11418-15715 System.err W OkHttp Extra [2024-07-11 16:53:47] Q10000 canceled : OkHttp ConnectionPool 2024-07-11 16:53:56.493 11418-15756 System.err W OkHttp Extra [2024-07-11 16:53:56] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:53:56.493 11418-15715 System.err W OkHttp Extra [2024-07-11 16:53:56] Q10000 already scheduled : OkHttp ConnectionPool 2024-07-11 16:53:56.494 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:56] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:53:56.494 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:56] Q10000 run again after 300 s : OkHttp ConnectionPool 2024-07-11 16:53:56.495 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:56] Q10000 finished run in 539 µs: OkHttp ConnectionPool 2024-07-11 16:53:56.705 11418-15757 System.err W OkHttp Extra [2024-07-11 16:53:56] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:53:56.706 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:56] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:53:56.706 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:56] Q10000 run again after 300 s : OkHttp ConnectionPool 2024-07-11 16:53:56.706 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:56] Q10000 finished run in 1 ms: OkHttp ConnectionPool 2024-07-11 16:53:56.828 11418-15715 System.err W OkHttp Extra [2024-07-11 16:53:56] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:53:56.828 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:56] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:53:56.829 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:56] Q10000 run again after 300 s : OkHttp ConnectionPool 2024-07-11 16:53:56.829 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:56] Q10000 finished run in 822 µs: OkHttp ConnectionPool 2024-07-11 16:53:57.050 11418-15757 System.err W OkHttp Extra [2024-07-11 16:53:57] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:53:57.050 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:57] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:53:57.050 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:57] Q10000 run again after 300 s : OkHttp ConnectionPool 2024-07-11 16:53:57.050 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:57] Q10000 finished run in 454 µs: OkHttp ConnectionPool 2024-07-11 16:53:57.123 11418-15715 System.err W OkHttp Extra [2024-07-11 16:53:57] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:53:57.123 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:57] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:53:57.123 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:57] Q10000 run again after 300 s : OkHttp ConnectionPool 2024-07-11 16:53:57.123 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:57] Q10000 finished run in 226 µs: OkHttp ConnectionPool 2024-07-11 16:53:58.423 11418-15715 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:53:58.423 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:53:58.423 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 run again after 298 s : OkHttp ConnectionPool 2024-07-11 16:53:58.424 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 finished run in 294 µs: OkHttp ConnectionPool 2024-07-11 16:53:58.443 11418-15757 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:53:58.446 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:53:58.446 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 run again after 298 s : OkHttp ConnectionPool 2024-07-11 16:53:58.446 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 finished run in 3 ms: OkHttp ConnectionPool 2024-07-11 16:53:58.608 11418-15757 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:53:58.608 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:53:58.609 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 run again after 298 s : OkHttp ConnectionPool 2024-07-11 16:53:58.609 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 finished run in 317 µs: OkHttp ConnectionPool 2024-07-11 16:53:58.642 11418-15757 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:53:58.642 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:53:58.643 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 run again after 298 s : OkHttp ConnectionPool 2024-07-11 16:53:58.643 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 finished run in 790 µs: OkHttp ConnectionPool 2024-07-11 16:53:58.690 11418-15715 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:53:58.691 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:53:58.691 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 run again after 298 s : OkHttp ConnectionPool 2024-07-11 16:53:58.692 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 finished run in 1 ms: OkHttp ConnectionPool 2024-07-11 16:53:58.751 11418-15756 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-11 16:53:58.752 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 starting : OkHttp ConnectionPool 2024-07-11 16:53:58.753 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 run again after 298 s : OkHttp ConnectionPool 2024-07-11 16:53:58.753 11418-15721 System.err W OkHttp Extra [2024-07-11 16:53:58] Q10000 finished run in 1 ms: OkHttp ConnectionPool

speekha commented 3 days ago

Here's the events log:

2024-07-12 17:00:16.543 26646-27016 System.err W OkHttp Extra [2024-07-12 17:00:16] Q10000 scheduled after 0 µs: OkHttp ConnectionPool 2024-07-12 17:00:16.543 26646-26912 System.err W OkHttp Extra [2024-07-12 17:00:16] Q10000 starting : OkHttp ConnectionPool 2024-07-12 17:00:16.548 26646-26912 System.err W OkHttp Extra [2024-07-12 17:00:16] Q10000 run again after 294 s : OkHttp ConnectionPool 2024-07-12 17:00:16.549 26646-26912 System.err W OkHttp Extra [2024-07-12 17:00:16] Q10000 finished run in 5 ms: OkHttp ConnectionPool 2024-07-12 17:00:16.549 26646-27016 System.out I 0063 0.037 connectionAcquired 2024-07-12 17:00:16.549 26646-27016 System.out I 0063 0.037 requestHeadersStart 2024-07-12 17:00:16.549 26646-27016 System.out I 0063 0.037 requestHeadersEnd 2024-07-12 17:00:16.549 26646-27016 System.out I 0063 0.037 requestBodyStart 2024-07-12 17:00:16.549 26646-27016 System.out I 0063 0.037 requestBodyEnd 2024-07-12 17:00:18.022 26646-27016 System.out I 0063 1.510 responseHeadersStart 2024-07-12 17:00:18.023 26646-27016 System.out I 0063 1.511 responseHeadersEnd 2024-07-12 17:00:18.025 26646-27016 System.out I 0063 1.513 responseBodyStart 2024-07-12 17:00:18.026 26646-27016 System.out I 0063 1.514 responseBodyEnd 2024-07-12 17:00:18.026 26646-27016 System.out I 0063 1.514 connectionReleased 2024-07-12 17:00:18.026 26646-27016 System.out I 0063 1.515 callEnd 2024-07-12 17:00:18.032 26646-27016 System.out I 0063 1.520 canceled 2024-07-12 17:00:20.659 26646-27115 System.out I 0064 https://www…. 2024-07-12 17:00:20.660 26646-27115 System.out I 0064 0.000 callStart 2024-07-12 17:00:20.665 26646-27016 System.out I 0064 0.005 connectionAcquired 2024-07-12 17:00:20.665 26646-27016 System.out I 0064 0.005 requestHeadersStart 2024-07-12 17:00:20.665 26646-27016 System.out I 0064 0.006 requestHeadersEnd 2024-07-12 17:00:20.666 26646-27016 System.out I 0064 0.006 requestBodyStart 2024-07-12 17:00:20.666 26646-27016 System.out I 0064 0.006 requestBodyEnd 2024-07-12 17:00:20.668 26646-27016 System.out I 0064 0.008 responseFailed 2024-07-12 17:00:20.670 26646-27016 System.out I 0064 0.011 connectionReleased 2024-07-12 17:00:20.670 26646-27016 System.out I 0064 0.011 callFailed 2024-07-12 17:05:10.697 26646-26912 System.err W OkHttp Extra [2024-07-12 17:05:10] Q10000 starting : OkHttp ConnectionPool 2024-07-12 17:05:10.713 26646-26912 System.err W OkHttp Extra [2024-07-12 17:05:10] Q10000 run again after 0 µs: OkHttp ConnectionPool 2024-07-12 17:05:10.714 26646-26912 System.err W OkHttp Extra [2024-07-12 17:05:10] Q10000 finished run in 57 ms: OkHttp ConnectionPool 2024-07-12 17:05:10.718 26646-26912 System.err W OkHttp Extra [2024-07-12 17:05:10] Q10000 starting : OkHttp ConnectionPool 2024-07-12 17:05:10.720 26646-26912 System.err W OkHttp Extra [2024-07-12 17:05:10] Q10000 run again after 2 s : OkHttp ConnectionPool 2024-07-12 17:05:10.721 26646-26912 System.err W OkHttp Extra [2024-07-12 17:05:10] Q10000 finished run in 3 ms: OkHttp ConnectionPool 2024-07-12 17:05:12.638 26646-26912 System.err W OkHttp Extra [2024-07-12 17:05:12] Q10000 starting : OkHttp ConnectionPool 2024-07-12 17:05:12.641 26646-26912 System.err W OkHttp Extra [2024-07-12 17:05:12] Q10000 finished run in 4 ms: OkHttp ConnectionPool

The log says response failed at 17:00:20.668, even though the request was received and the server answered.

speekha commented 3 days ago

Just confirmed that the failure has nothing to do with header sizes by checking an erroneous response:

swankjesse commented 3 days ago

That’s surprising. There’s gonna be a bug in our code that enforces the 256 KiB limit on headers. The root cause exception is here:

Caused by: java.io.EOFException: \n not found: limit=0 content=…
at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:335)
at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:29)
at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:180)

The limit is supposed to start at (256 * 1024) and shrink as headers are processed.

Either way we should improve the error messaging here.

swankjesse commented 3 days ago

Do you have a URL that consistently triggers this? If you’d like to share it with me privately, my email address is posted at the bottom of publicobject.com.

speekha commented 2 days ago

@swankjesse No, I don't have a specific URL : it can happen on any URL we call. As far as I can tell, it's more of a time issue. The problem never happens during the first few minutes after launching the app, just after a few minutes. Thus my conclusion that it is probably more of a thread pool handling problem. As if a thread was reused, but when the response is received, the connection would be considered stale and discarded, even though it is clearly still working (the server received the request and answered it).

swankjesse commented 2 days ago

Interesting! I wonder if we could reproduce this with a single URL and a loop.

If you have any URL that I can use to attempt to reproduce this, that’ll help me to fix it.

swankjesse commented 2 days ago

(Or a test that uses MockWebServer and a loop!)

speekha commented 1 day ago

I don't have anything available, but I think you could use anything: as I mention, it can happen on pretty much any URL that we call.

I'll try and see if I can come up with a way to reproduce, but no guarantees.