okhttp: 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

About this issue

  • Original URL
  • State: closed
  • Created 6 years ago
  • Comments: 26 (5 by maintainers)

Most upvoted comments

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.

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