square
HTTP/2 Write Timeouts Aren’t Immediate
- OkHttp 3.12.0
- Android asynctask that sends a set of little file (about 1.3mb each file) via HTTP2 POST to a cloud service, one by one
- Android device with Android 5.1.1. (API LEVEL 22)
- HttpClient build as following:
val client = OkHttpClient.Builder()
.addInterceptor(logging)
.connectTimeout(120, TimeUnit.SECONDS)
.readTimeout(5000, TimeUnit.MILLISECONDS)
.writeTimeout(5000, TimeUnit.MILLISECONDS)
.callTimeout(10000, TimeUnit.MILLISECONDS)
.build()
- this is the async task code
fun uploadFile(fileName: String, fileInputStream: InputStream, totalNumber: Int, index: Int) {
val client = OkHttpClient.Builder()
.connectTimeout(120, TimeUnit.SECONDS)
.readTimeout(5000, TimeUnit.MILLISECONDS)
.writeTimeout(5000, TimeUnit.MILLISECONDS)
.callTimeout(10000, TimeUnit.MILLISECONDS)
.build()
val data = fileInputStream.readBytes()
Timber.i("Start uploading $fileName (${data.size} bytes)")
val digest = md5(data)
val body = RequestBody.create(null, data)
val request = Request.Builder()
.addHeader(HEADER_CHECKSUM, digest)
.url(url)
.post(body)
.build()
try {
val call = client.newCall(request)
call.execute().use { response ->
/* do nothing */
}
} catch (e : Exception) {
Timber.i(e)
}
}
- At my offiche I have a very bad network condition with a lot of TCP retransmission
EXPECTED:
- The maximum expected time for each file (callTimeout) should be 10 seconds ACTUAL:
- these are for example the timing for 10 file:
- 85622ms - UPLOAD ERROR
- 8539ms - UPLOAD ERROR
- 18381ms - UPLOAD ERROR
- 8564ms - UPLOAD ERROR
- 10100ms - UPLOAD ERROR
- 6810ms
- 61457ms - UPLOAD ERROR
- 9088ms
- 8040ms
- 22351ms - UPLOAD ERROR
Seven uploads exceeded the callTimeout and goes in error. I can reproduce this behaviour easily but this happens only here at my office, so an example code could be useless
@swankjesse no, because this happens only at my office. If I try the same application on the same device at home, the upload is super fast without any timeout or delay (about 500ms each file)
Another info: the same code with a post to a standard HTTP 1.1 server works as expected
Example code at https://gist.github.com/sarbyn/2940cb5a5f4c6c144410f3dd7569fdfe You need to use an HTTP2 server and a large file (for example 40mb) Tie call timeout is set to 10 seconds. In the header comment you can find an output
@sarbyn, can you set this on OkHttpClient.Builder() and provide the output from a problematic run?
.eventListenerFactory(new LoggingEventListener.Factory()).build();
Also, does this reproduce with http://www.nghttp2.org/httpbin/post?
This is the output with LoggingEventListener enabled
2018-12-27 10:12:05.159 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [0 ms] callStart: Request{method=POST, url=https://MY_SERVER_NAME:8082/upload, tags={}}
2018-12-27 10:12:05.160 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: --> POST https://MY_SERVER_NAME:8082/upload
2018-12-27 10:12:05.160 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: Content-Length: 1332109
2018-12-27 10:12:05.160 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: MY_CUSTOM_HEADER_1: cecf15f862a82c9bcebfb2f19661fdf2
2018-12-27 10:12:05.160 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: MY_CUSTOM_HEADER_2: 5
2018-12-27 10:12:05.160 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: MY_CUSTOM_HEADER_3: 4
2018-12-27 10:12:05.160 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: MY_CUSTOM_HEADER_4: 7edb2819-36ab-4bb2-b80e-85050f23734f
2018-12-27 10:12:05.160 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: MY_CUSTOM_HEADER_5: 2
2018-12-27 10:12:05.160 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: --> END POST
2018-12-27 10:12:05.160 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [0 ms] dnsStart: MY_SERVER_NAME
2018-12-27 10:12:05.194 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [34 ms] dnsEnd: [MY_SERVER_NAME/MY_SERVER_IP]
2018-12-27 10:12:05.194 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [35 ms] connectStart: MY_SERVER_NAME/MY_SERVER_IP:8082 DIRECT
2018-12-27 10:12:05.216 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [56 ms] secureConnectStart
2018-12-27 10:12:05.246 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [86 ms] secureConnectEnd
2018-12-27 10:12:05.248 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [88 ms] connectEnd: h2
2018-12-27 10:12:05.248 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [88 ms] connectionAcquired: Connection{MY_SERVER_NAME:8082, proxy=DIRECT hostAddress=MY_SERVER_NAME/MY_SERVER_IP:8082 cipherSuite=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 protocol=h2}
2018-12-27 10:12:05.248 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [88 ms] requestHeadersStart
2018-12-27 10:12:05.249 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [89 ms] requestHeadersEnd
2018-12-27 10:12:05.249 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [89 ms] requestBodyStart
2018-12-27 10:12:17.714 15856-16590/com.sarbyn.androidsessionupload W/zygote: Long monitor contention with owner AsyncTask #8 (16569) at void com.android.org.conscrypt.NativeCrypto.SSL_write(long, java.io.FileDescriptor, com.android.org.conscrypt.NativeCrypto$SSLHandshakeCallbacks, byte[], int, int, int)(NativeCrypto.java:-2) waiters=0 in void okhttp3.internal.http2.Http2Writer.rstStream(int, okhttp3.internal.http2.ErrorCode) for 7.440s
2018-12-27 10:12:17.714 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [12554 ms] connectionReleased
2018-12-27 10:12:17.714 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [12554 ms] callEnd
2018-12-27 10:12:17.714 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: <-- HTTP FAILED: java.net.SocketTimeoutException: timeout
2018-12-27 10:12:17.715 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [12555 ms] callFailed: java.net.SocketTimeoutException: timeout
2018-12-27 10:12:17.717 15856-16569/com.sarbyn.androidsessionupload I/Uploader$Companion: java.net.SocketTimeoutException: timeout
at okhttp3.internal.http2.Http2Stream$StreamTimeout.newTimeoutException(Http2Stream.java:656)
at okhttp3.internal.http2.Http2Stream$StreamTimeout.exitAndThrowIfTimedOut(Http2Stream.java:664)
at okhttp3.internal.http2.Http2Stream$FramingSink.emitFrame(Http2Stream.java:572)
at okhttp3.internal.http2.Http2Stream$FramingSink.write(Http2Stream.java:543)
at okio.ForwardingSink.write(ForwardingSink.java:35)
at okhttp3.internal.http.CallServerInterceptor$CountingSink.write(CallServerInterceptor.java:149)
at okio.RealBufferedSink.emitCompleteSegments(RealBufferedSink.java:179)
at okio.RealBufferedSink.write(RealBufferedSink.java:92)
at okhttp3.RequestBody$2.writeTo(RequestBody.java:98)
at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:72)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:126)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
at okhttp3.logging.HttpLoggingInterceptor.intercept(HttpLoggingInterceptor.java:225)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:254)
at okhttp3.RealCall.execute(RealCall.java:92)
at com.sarbyn.androidsessionupload.Uploader$Companion.uploadFile(Uploader.kt:184)
at com.sarbyn.androidsessionupload.UploaderAsyncTask.doInBackground(UploaderAsyncTask.kt:23)
at com.sarbyn.androidsessionupload.UploaderAsyncTask.doInBackground(UploaderAsyncTask.kt:10)
at android.os.AsyncTask$2.call(AsyncTask.java:333)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:245)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
at java.lang.Thread.run(Thread.java:764)
2018-12-27 10:12:17.717 15856-16569/com.sarbyn.androidsessionupload I/Uploader$Companion: TimeElapsed 12558
2018-12-27 10:12:05.249 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [89 ms] requestBodyStart
2018-12-27 10:12:17.714 15856-16590/com.sarbyn.androidsessionupload W/zygote: Long monitor contention with owner AsyncTask #8 (16569) at void com.android.org.conscrypt.NativeCrypto.SSL_write(long, java.io.FileDescriptor, com.android.org.conscrypt.NativeCrypto$SSLHandshakeCallbacks, byte[], int, int, int)(NativeCrypto.java:-2) waiters=0 in void okhttp3.internal.http2.Http2Writer.rstStream(int, okhttp3.internal.http2.ErrorCode) for 7.440s
2018-12-27 10:12:17.714 15856-16569/com.sarbyn.androidsessionupload D/OkHttp: [12554 ms] connectionReleased
looks suspicious. The fact that at 10:12:17.714, the monitor was held by SSL_write() for 7.440s, means that it was taken at 10:12:10.274, which is 5.025s after starting to write the request body. Both this and the stack trace of the SocketTimeoutException indicate that the 5s write timeout kicked in and blocked on writing the RST_STREAM frame. Even if there was no write timeout, it would have been the call timeout blocked on writing the RST_STREAM frame, preventing the call from ending after exactly 10 seconds as you expect.
This can also explain why it happens only with HTTP/2, as with HTTP/1.1 the socket is simply closed when the timeout fires and there is no attempt to write anything, which may block.
I'm not sure if this is an actual issue. I expect that if you remove the write timeout and add some logging, you'll see that the call timeout in fact kicks in after 10 seconds, but just takes a few extra seconds to completely end the call.
The last log is from an android application with AsyncTask but happens also with the Gist provided in the link above.
For example look at the log below (Read/write timeout 5 seconds - callTimeout 10 seconds). The socket timeout is fired afted 17 seconds:
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: [0 ms] callStart: Request{method=POST, url=https://blablabla.sarbyn.com:8443/upload, tags={}}
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: --> POST https://blablabla.sarbyn.com:8443/upload
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: Content-Length: 1930048
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: HEADER-1: bbcf35da1f80fd90483b990df7dacf52
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: HEADER-2: 10
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: HEADER-3: 3
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: HEADER-4: cf2d6535-cd3a-4f2b-bbd7-ae6d03d70e00
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: HEADER-5: 2
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: --> END POST
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: [2 ms] dnsStart: blablabla.sarbyn.com
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: [2 ms] dnsEnd: [blablabla.sarbyn.com/MY_IP_ADDRESS]
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: [2 ms] connectStart: blablabla.sarbyn.com/MY_IP_ADDRESS:8443 DIRECT
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: [14 ms] secureConnectStart
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: [96 ms] secureConnectEnd
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: [97 ms] connectEnd: h2
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: [98 ms] connectionAcquired: Connection{blablabla.sarbyn.com:8443, proxy=DIRECT hostAddress=blablabla.sarbyn.com/MY_IP_ADDRESS:8443 cipherSuite=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 protocol=h2}
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: [98 ms] requestHeadersStart
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: [99 ms] requestHeadersEnd
dic 28, 2018 9:11:44 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: [99 ms] requestBodyStart
dic 28, 2018 9:12:01 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: [17336 ms] connectionReleased
dic 28, 2018 9:12:01 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: [17336 ms] callEnd
dic 28, 2018 9:12:01 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: <-- HTTP FAILED: java.net.SocketTimeoutException: timeout
dic 28, 2018 9:12:01 AM okhttp3.internal.platform.Platform log
INFORMAZIONI: [17337 ms] callFailed: java.net.SocketTimeoutException: timeout
Another strange things: this is the upload result, (same laptop, same network, same server, same list of file), of a python script:
fileName, time
1, 11938
2, 3273
3, 2723
4, 6597
5, 4929
6, 514
7, 3511
8, 2682
9, 6398
10, 3106
Done, total time is 45671 ms. goodbye
This is the result with OkHTTP (Read/write timeout 5 seconds - callTimeout 10 seconds)
fileName,time,success
1, 14187, Timeout
2, 2462, 1
3, 20640, Timeout
4, 4871, 1
5, 19881, Timeout
6, 8096, Timeout
7, 18926, Timeout
8, 16175, Timeout
9, 4174, 1
10, 7609, Timeout
Total time is 117021ms. Goodbye
45 seconds vs 117 😞
I think the core problem is that our HTTP/2 write timeouts don’t have teeth. On HTTP/1 we close the underlying socket which takes effect immediately. On HTTP/2 we cancel the stream, but if it’s currently blocked on a write it won’t cancel until that write returns.
I think the core problem is that our HTTP/2 write timeouts don’t have teeth. On HTTP/1 we close the underlying socket which takes effect immediately. On HTTP/2 we cancel the stream, but if it’s currently blocked on a write it won’t cancel until that write returns.
Related to https://github.com/square/okhttp/issues/1902, should we be interrupting ourselves?
Related to issue #3278 because timeouts were supposed to save us from the hang if they really were effective.
Are there any updates? I have the exact same issue in an app in case of really bad network quality. The stream seems to be blocked in NativeCrypto.SSL_write and it doesn't time out properly. Is there a way to solve this other than switching to HTTP/1?
@gorogaron no updates right now. We might have to do something awkward, like failing the entire connection if any write times out.
Is there any plan to fix this? Here is my scenario
- 50 threads making connections
- all get affected because of the lock at java.lang.Thread.State: BLOCKED okhttp3.internal.http2.Http2Connection.newStream
- Lock is held by Http2Writer.flush
@Synchronized @Throws(IOException::class) fun flush() { if (closed) throw IOException("closed") sink.flush() }
4. Writes gets stuck for 15minutes (which is the OS timeout https://blog.cloudflare.com/when-tcp-sockets-refuse-to-die/)
(of course call timeout or write timeout are not handled).
Whats the best way to workaround this situation?
- change the protocol to http1? that might affect the throughput
- Create multiple httpclients if running calls exceeds a threshold ?
49 blocked BLOCKED threads java.lang.Thread.State: BLOCKED at okhttp3.internal.http2.Http2Connection.newStream(Http2Connection.kt:240) at okhttp3.internal.http2.Http2Connection.newStream(Http2Connection.kt:225) at okhttp3.internal.http2.Http2ExchangeCodec.writeRequestHeaders(Http2ExchangeCodec.kt:76) at okhttp3.internal.connection.Exchange.writeRequestHeaders(Exchange.kt:59) at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:36) at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) at com.foo.bar.httpclient.interceptor.LoggingInterceptor.intercept(LoggingInterceptor.java:58) 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 datadog.trace.instrumentation.okhttp3.TracingInterceptor.intercept(TracingInterceptor.java:38) at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201) at okhttp3.internal.connection.RealCall.execute(RealCall.kt:154) at com.foo.bar.httpclient.HttpExecutor.call(HttpExecutor.java:43) …….. at java.lang.Thread.run(Thread.java:750)
Runnable thread that gets timed out after 15 minutes at java.net.SocketOutputStream.socketWrite0(Native Method) at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111) at java.net.SocketOutputStream.write(SocketOutputStream.java:155) at sun.security.ssl.SSLSocketOutputRecord.deliver(SSLSocketOutputRecord.java:346) at sun.security.ssl.SSLSocketImpl$AppOutputStream.write(SSLSocketImpl.java:1146) at okio.OutputStreamSink.write(JvmOkio.kt:53) at okio.AsyncTimeout$sink$1.write(AsyncTimeout.kt:103) at okio.RealBufferedSink.flush(RealBufferedSink.kt:267) at okhttp3.internal.http2.Http2Writer.flush(Http2Writer.kt:120) at okhttp3.internal.http2.Http2Connection.flush(Http2Connection.kt:408) at okhttp3.internal.http2.Http2Stream$FramingSink.close(Http2Stream.kt:626) at okio.ForwardingSink.close(ForwardingSink.kt:37) at okhttp3.internal.connection.Exchange$RequestBodySink.close(Exchange.kt:242) at okio.RealBufferedSink.close(RealBufferedSink.kt:286) at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:60) at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 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 datadog.trace.instrumentation.okhttp3.TracingInterceptor.intercept(TracingInterceptor.java:38) at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201) at okhttp3.internal.connection.RealCall.execute(RealCall.kt:154) ...... at java.lang.Thread.run(Thread.java:750)
- OkHttp 3.12.0
- Android asynctask that sends a set of little file (about 1.3mb each file) via HTTP2 POST to a cloud service, one by one
- Android device with Android 5.1.1. (API LEVEL 22)
- HttpClient build as following:
val client = OkHttpClient.Builder() .addInterceptor(logging) .connectTimeout(120, TimeUnit.SECONDS) .readTimeout(5000, TimeUnit.MILLISECONDS) .writeTimeout(5000, TimeUnit.MILLISECONDS) .callTimeout(10000, TimeUnit.MILLISECONDS) .build()
- this is the async task code
fun uploadFile(fileName: String, fileInputStream: InputStream, totalNumber: Int, index: Int) { val client = OkHttpClient.Builder() .connectTimeout(120, TimeUnit.SECONDS) .readTimeout(5000, TimeUnit.MILLISECONDS) .writeTimeout(5000, TimeUnit.MILLISECONDS) .callTimeout(10000, TimeUnit.MILLISECONDS) .build() val data = fileInputStream.readBytes() Timber.i("Start uploading $fileName (${data.size} bytes)") val digest = md5(data) val body = RequestBody.create(null, data) val request = Request.Builder() .addHeader(HEADER_CHECKSUM, digest) .url(url) .post(body) .build() try { val call = client.newCall(request) call.execute().use { response -> /* do nothing */ } } catch (e : Exception) { Timber.i(e) } }
- At my offiche I have a very bad network condition with a lot of TCP retransmission
EXPECTED:
The maximum expected time for each file (callTimeout) should be 10 seconds ACTUAL:
these are for example the timing for 10 file:
85622ms - UPLOAD ERROR
8539ms - UPLOAD ERROR
18381ms - UPLOAD ERROR
8564ms - UPLOAD ERROR
10100ms - UPLOAD ERROR
6810ms
61457ms - UPLOAD ERROR
9088ms
8040ms
22351ms - UPLOAD ERROR
Seven uploads exceeded the callTimeout and goes in error. I can reproduce this behaviour easily but this happens only here at my office, so an example code could be useless
Viadao
- OkHttp 3.12.0
- Android asynctask that sends a set of little file (about 1.3mb each file) via HTTP2 POST to a cloud service, one by one
- Android device with Android 5.1.1. (API LEVEL 22)
- HttpClient build as following:
val client = OkHttpClient.Builder() .addInterceptor(logging) .connectTimeout(120, TimeUnit.SECONDS) .readTimeout(5000, TimeUnit.MILLISECONDS) .writeTimeout(5000, TimeUnit.MILLISECONDS) .callTimeout(10000, TimeUnit.MILLISECONDS) .build()
- this is the async task code
fun uploadFile(fileName: String, fileInputStream: InputStream, totalNumber: Int, index: Int) { val client = OkHttpClient.Builder() .connectTimeout(120, TimeUnit.SECONDS) .readTimeout(5000, TimeUnit.MILLISECONDS) .writeTimeout(5000, TimeUnit.MILLISECONDS) .callTimeout(10000, TimeUnit.MILLISECONDS) .build() val data = fileInputStream.readBytes() Timber.i("Start uploading $fileName (${data.size} bytes)") val digest = md5(data) val body = RequestBody.create(null, data) val request = Request.Builder() .addHeader(HEADER_CHECKSUM, digest) .url(url) .post(body) .build() try { val call = client.newCall(request) call.execute().use { response -> /* do nothing */ } } catch (e : Exception) { Timber.i(e) } }
- At my offiche I have a very bad network condition with a lot of TCP retransmission
EXPECTED:
- The maximum expected time for each file (callTimeout) should be 10 seconds ACTUAL:
- these are for example the timing for 10 file:
- 85622ms - UPLOAD ERROR
- 8539ms - UPLOAD ERROR
- 18381ms - UPLOAD ERROR
- 8564ms - UPLOAD ERROR
- 10100ms - UPLOAD ERROR
- 6810ms
- 61457ms - UPLOAD ERROR
- 9088ms
- 8040ms
- 22351ms - UPLOAD ERROR
Seven uploads exceeded the callTimeout and goes in error. I can reproduce this behaviour easily but this happens only here at my office, so an example code could be useless
Viadao
@yschimke Could you please tell me which pull request solved this issue? I have encountered the same problem while using 3.x and I want to learn about how the issue has been fixed. Thanks a lot!
It's a bug raised against 3.x. There is no action to take without a reproduction using 4.x. Do you get it still with 4.12?
@yschimke No, I got it with 3.x. I just want to know what code changes have been made in order to solve this issue