okhttp icon indicating copy to clipboard operation
okhttp copied to clipboard
verified publisher icon square

Incorrect retries on connection that still succeeded

Open speekha opened this issue 1 year ago • 18 comments

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)

speekha avatar Jul 11 '24 15:07 speekha

Can you turn on logging with https://square.github.io/okhttp/features/events/

And provide that output?

yschimke avatar Jul 12 '24 06:07 yschimke

Here's the logs leading up to the exception. Hope it helps.

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 avatar Jul 12 '24 07:07 speekha

Need the event logging that I linked to. Or a logging network interceptor

yschimke avatar Jul 12 '24 10:07 yschimke

Sorry. Misundestood the logs you wanted. Here's the extra logs :

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 avatar Jul 12 '24 15:07 speekha

Has this problem been solved? I have also reproduced it。thanks image

yx-Yaoxaing avatar Aug 02 '24 05:08 yx-Yaoxaing

I haven't had any news since I posted the logs.

speekha avatar Aug 02 '24 09:08 speekha

自从我发布日志以来，还没有收到任何消息。

thanks!!!

yx-Yaoxaing avatar Aug 03 '24 09:08 yx-Yaoxaing

und: limit=0 content=

自从我发布日志以来，还没有收到任何消息。

thanks!!!

Has this problem been solved? I have also reproduced it。thanks image

Excuse me, can you reproduce the issue consistently?

Endeavour233 avatar Aug 04 '24 10:08 Endeavour233

Actually, I found the issue, and was able to reproduce it consistently (see below for server and client code).

The problem is that okhttp3.internal.http1.HeadersReader sets a headerLimit of 256KB (as you can see below, the server adds a random very long header).

According to RFC 2616, there is no limitation on the header size, however, a lot of softwares add limitations (the provided response will provide an error in cURL, while it will work like a charm on Firefox).

Can you confirm that this was due to an "oversized" header ?

I would be more than happy to solve this issue, but we should agree on what we want to do here :

  • Do not provide any error but ignore everything which is over the limit (with a workaround code to detect Content-Length).
  • Do not provide any error, and just treat the header regardless its size (by far my least favourite as it would cause MemoryError). This would be fully RFC complient.
  • Keep things as they are, after all, even cURL is having troubles. This would imply to update the documentation of the project, to let the user know about this limitation which is not stated in HTTP RFC.
  • Let the user choose a limit (or even unlimited) for the header size by adding a Builder method. (my favourite option)

I will start from now on to work on that last option.

Python3 Server code

import socket
import random
import string

def generate_random_string(length):
    return ''.join(random.choices(string.ascii_letters + string.digits, k=length))

random_string = ''.join(random.choices(string.ascii_letters + string.digits, k=256 * 1024 - 48))

# Création d'un socket TCP
with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as server_socket:
    server_socket.bind(('127.0.0.1', 8080))
    server_socket.listen()

    while True:
        conn, addr = server_socket.accept()
        with conn:
            response = (
                "HTTP/1.1 200 OK\n"
                "Content-Type: text/plain\n"
                f"MyHeader:{random_string}\n"
                "Content-Length: 14\n"
                "\n"
                "Erreur de requête"
            )
            conn.sendall(response.encode('utf-8'))

Kotlin client code with OkHttp

import okhttp3.OkHttpClient;
import okhttp3.Request;
import okhttp3.Response;
import okhttp3.ResponseBody;

public class OkHttpTest {
  private static final String ENDPOINT = "http://127.0.0.1:8080";

  public static void main(String... args) {
    OkHttpClient client = new OkHttpClient();

    try {
      Request request = new Request.Builder()
        .url(ENDPOINT)
        .build();
      try (Response response = client.newCall(request).execute()) {
        ResponseBody body = response.body();
        System.out.println(body.string());
      }
    } catch(Exception e) {
      e.printStackTrace();
    }
  }
}

Error stacktrace

java.io.IOException: unexpected end of stream on http://127.0.0.1:8080/...
	at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:220)
	at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:114)
	at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:93)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:126)
	at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:126)
	at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:126)
	at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:126)
	at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:72)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:126)
	at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:208)
	at okhttp3.internal.connection.RealCall.execute(RealCall.kt:160)
	at okhttp3.sample.OkHttpContributors.main(OkHttpContributors.java:50)
Caused by: java.io.EOFException: \n not found: limit=0 content=436f6e74656e742d4c656e6774683a2031340a0a457272657572206465207265…
	at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:339)
	at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:29)
	at okhttp3.internal.http1.HeadersReader.readHeaders(HeadersReader.kt:38)
	at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:195)
	... 14 more

gahfy avatar Aug 10 '24 11:08 gahfy

Anyone with the error, could you try with #8504 and tell me if it is working now?

gahfy avatar Aug 10 '24 11:08 gahfy

Actually, I found the issue, and was able to reproduce it consistently (see below for server and client code).

The problem is that okhttp3.internal.http1.HeadersReader sets a headerLimit of 256KB (as you can see below, the server adds a random very long header).

According to RFC 2616, there is no limitation on the header size, however, a lot of softwares add limitations (the provided response will provide an error in cURL, while it will work like a charm on Firefox).

Can you confirm that this was due to an "oversized" header ?

I would be more than happy to solve this issue, but we should agree on what we want to do here :

  • Do not provide any error but ignore everything which is over the limit (with a workaround code to detect Content-Length).
  • Do not provide any error, and just treat the header regardless its size (by far my least favourite as it would cause MemoryError). This would be fully RFC complient.
  • Keep things as they are, after all, even cURL is having troubles. This would imply to update the documentation of the project, to let the user know about this limitation which is not stated in HTTP RFC.
  • Let the user choose a limit (or even unlimited) for the header size by adding a Builder method. (my favourite option)

I will start from now on to work on that last option.

Python3 Server code

import socket
import random
import string

def generate_random_string(length):
    return ''.join(random.choices(string.ascii_letters + string.digits, k=length))

random_string = ''.join(random.choices(string.ascii_letters + string.digits, k=256 * 1024 - 48))

# Création d'un socket TCP
with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as server_socket:
    server_socket.bind(('127.0.0.1', 8080))
    server_socket.listen()

    while True:
        conn, addr = server_socket.accept()
        with conn:
            response = (
                "HTTP/1.1 200 OK\n"
                "Content-Type: text/plain\n"
                f"MyHeader:{random_string}\n"
                "Content-Length: 14\n"
                "\n"
                "Erreur de requête"
            )
            conn.sendall(response.encode('utf-8'))

Kotlin client code with OkHttp

import okhttp3.OkHttpClient;
import okhttp3.Request;
import okhttp3.Response;
import okhttp3.ResponseBody;

public class OkHttpTest {
  private static final String ENDPOINT = "http://127.0.0.1:8080";

  public static void main(String... args) {
    OkHttpClient client = new OkHttpClient();

    try {
      Request request = new Request.Builder()
        .url(ENDPOINT)
        .build();
      try (Response response = client.newCall(request).execute()) {
        ResponseBody body = response.body();
        System.out.println(body.string());
      }
    } catch(Exception e) {
      e.printStackTrace();
    }
  }
}

Error stacktrace

java.io.IOException: unexpected end of stream on http://127.0.0.1:8080/...
	at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:220)
	at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:114)
	at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:93)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:126)
	at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:126)
	at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:126)
	at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:126)
	at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:72)
	at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:126)
	at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:208)
	at okhttp3.internal.connection.RealCall.execute(RealCall.kt:160)
	at okhttp3.sample.OkHttpContributors.main(OkHttpContributors.java:50)
Caused by: java.io.EOFException: \n not found: limit=0 content=436f6e74656e742d4c656e6774683a2031340a0a457272657572206465207265…
	at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.kt:339)
	at okhttp3.internal.http1.HeadersReader.readLine(HeadersReader.kt:29)
	at okhttp3.internal.http1.HeadersReader.readHeaders(HeadersReader.kt:38)
	at okhttp3.internal.http1.Http1ExchangeCodec.readResponseHeaders(Http1ExchangeCodec.kt:195)
	... 14 more

Cool! However, I still have one question. Why did the issue not happen with okhttp v3.x as mentioned in the second paragraph of issue description.

Endeavour233 avatar Aug 10 '24 23:08 Endeavour233

Has this problem been solved? I have also reproduced it。thanks image

@gahfy And I think the last third line of this log, which prints "\n not found, limit = 0, content=...", indicated a header of length 0.

Endeavour233 avatar Aug 10 '24 23:08 Endeavour233

@Endeavour233 I don't know why v3 worked, as I don't know the release date of v3. It is actually like this (this kind of error) since 2017 in the git history. Also, limit represents the number left allowed in the header. For example, the limit of the size of the header is 256KB, if you have 2048 characters, then the limit will become 254 KB. And the limit is decreasing line after line. So if you have a line which reach the limit size of the header, then the limit will become 0.

gahfy avatar Aug 11 '24 10:08 gahfy

@Endeavour233 I don't know why v3 worked, as I don't know the release date of v3. It is actually like this (this kind of error) since 2017 in the git history. Also, limit represents the number left allowed in the header. For example, the limit of the size of the header is 256KB, if you have 2048 characters, then the limit will become 254 KB. And the limit is decreasing line after line. So if you have a line which reach the limit size of the header, then the limit will become 0.

Got it, thank you. One more question, though I've understood how limit = 0 happens, I think content=... in the log showed that we can't read anything from the source (network response). However, we'll try to read at least 1 byte from the source according to the code snippet pasted below(3.9.0 okio). If there was any bytes remaining in the response, I think the content should be of at least one byte length. 截屏2024-08-11 19 57 22

Endeavour233 avatar Aug 11 '24 11:08 Endeavour233

@Endeavour233 This limit + 1 in the code will allow scanning limit + 1 characters as you suggested. But this is in order to have the \n character, which will be removed. But in your scenario, that character not being found means that buffer.read will never get called, and so you get this error without any character.

This is more "guess" than certainty, but if you have any reproductible scenario, I can investigate more on this. I understand that it might be complicated to share private results, but maybe you can try to compile with the code in #8504 and see if the error still occurs in your scenario (setting headerSizeLimit to -1)

gahfy avatar Aug 11 '24 12:08 gahfy

@Endeavour233 This limit + 1 in the code will allow scanning limit + 1 characters as you suggested. But this is in order to have the \n character, which will be removed. But in your scenario, that character not being found means that buffer.read will never get called, and so you get this error without any character.

This is more "guess" than certainty, but if you have any reproductible scenario, I can investigate more on this. I understand that it might be complicated to share private results, but maybe you can try to compile with the code in #8504 and see if the error still occurs in your scenario (setting headerSizeLimit to -1)

Sorry, I can't reproduce the issue(I am just another one who is interested in this issue). Could you please explain what you mean by saying buffer.read will never get called? I think, compared to the stacktrace of your consistently reproduced issue caused by oversized header, of which the exception thrown is EOFException: \n not found: limit=0 content=436f6e74656e742d4c656e6774683a2031340a0a457272657572206465207265…, where limie is 0 while content(436f6e....) is not empy, the stacktrace of this issue(limit=0, content=...) showed that we can't copy any bytes from buffer to data, which means the buffer can't read anything from the underlying source(network response)

Endeavour233 avatar Aug 18 '24 12:08 Endeavour233

@gahfy Sorry for the delay, I was on holidays and just got back. In my case, failures were a bit random, and only happened after a little while (thus my suspicion that it was due to thread reuse). What's more, in my case, retrying the exact same request immediately generally succeeded, provided that the server accepted to process it a second time: in case of authentication, you often got booted out because the authentication factor had already been processed and could not be used a second time. In some other case, you ended up with a request processed twice, thus corrupting data. So the fix I'm expecting would be one that would match what was happening in OkHttp 3.x: reading the response properly the first time.

speekha avatar Aug 26 '24 09:08 speekha

Hi. Any news on the subject?

speekha avatar Oct 11 '24 07:10 speekha

I’ve got a PR here to confirm our behavior: https://github.com/square/okhttp/pull/8584

It looks like our limit is consistent with Chrome: https://source.chromium.org/chromium/chromium/src/+/main:net/http/http_stream_parser.h;l=169?q=ERR_RESPONSE_HEADERS_TOO_BIG&ss=chromium

If you need headers larger than 256 KiB, the stock OkHttp is the wrong HTTP client for you.

swankjesse avatar Nov 20 '24 01:11 swankjesse

I don't know why the title of this issue was changed but my request never had anything to do with long headers. Looks like it got hijacked by another bug that has nothing to do with it.

speekha avatar Nov 20 '24 14:11 speekha

Ok can you chat me whatsapp

On Wed, Nov 20, 2024 at 09:46 David Blanc @.***> wrote:

I don't know why the title of this issue was changed but my request never had anything to do with long headers. Looks like it got hijacked by another bug that has nothing to do with it.

— Reply to this email directly, view it on GitHub https://github.com/square/okhttp/issues/8472#issuecomment-2488774134, or unsubscribe https://github.com/notifications/unsubscribe-auth/A3NXVZID35UE3DGQGSQQZA32BSOFJAVCNFSM6AAAAABKXGZPYSVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDIOBYG43TIMJTGQ . You are receiving this because you are subscribed to this thread.Message ID: @.***>

Sniffentrevon1 avatar Nov 20 '24 14:11 Sniffentrevon1