S3 TransferUtility onStateChanged not called although onProgressChanged indicates completed upload

[kwatra]

Every once in a while when I upload a file to S3 via TransferUtility, the TransferObserver's onStateChanged is not called at all, even though onProgressChanged indicates that the upload has been completed. This is usually accompanied by an error log indicating a time out, which looking at the code suggests should just trigger a retry.

Example of last few logs:

• onProgressChanged() gets called with params: id: 7, bytesCurrent: 15220736, bytesTotal: 15244198
• This is followed after a few seconds with the following log:

I/AmazonHttpClient: Unable to execute HTTP request: Read timed out
  java.net.SocketTimeoutException: Read timed out
  at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
  at com.android.org.conscrypt.OpenSSLSocketImpl$SSLInputStream.read(OpenSSLSocketImpl.java:705)
  at com.android.okhttp.okio.Okio$2.read(Okio.java:135)
  at com.android.okhttp.okio.AsyncTimeout$2.read(AsyncTimeout.java:211)
  at com.android.okhttp.okio.RealBufferedSource.indexOf(RealBufferedSource.java:306)
  at com.android.okhttp.okio.RealBufferedSource.indexOf(RealBufferedSource.java:300)
  at com.android.okhttp.okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:196)
  at com.android.okhttp.internal.http.HttpConnection.readResponse(HttpConnection.java:191)
  at com.android.okhttp.internal.http.HttpTransport.readResponseHeaders(HttpTransport.java:80)
  at com.android.okhttp.internal.http.HttpEngine.readNetworkResponse(HttpEngine.java:904)
  at com.android.okhttp.internal.http.HttpEngine.readResponse(HttpEngine.java:788)
  at com.android.okhttp.internal.huc.HttpURLConnectionImpl.execute(HttpURLConnectionImpl.java:443)
  at com.android.okhttp.internal.huc.HttpURLConnectionImpl.getResponse(HttpURLConnectionImpl.java:388)
  at com.android.okhttp.internal.huc.HttpURLConnectionImpl.getResponseMessage(HttpURLConnectionImpl.java:497)
  at com.android.okhttp.internal.huc.DelegatingHttpsURLConnection.getResponseMessage(DelegatingHttpsURLConnection.java:109)
  at com.android.okhttp.internal.huc.HttpsURLConnectionImpl.getResponseMessage(HttpsURLConnectionImpl.java)
  at com.amazonaws.http.UrlHttpClient.createHttpResponse(UrlHttpClient.java:72)
  at com.amazonaws.http.UrlHttpClient.execute(UrlHttpClient.java:66)
  at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:360)
  at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:199)
  at com.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:4221)
  at com.amazonaws.services.s3.AmazonS3Client.uploadPart(AmazonS3Client.java:3312)
  at com.amazonaws.mobileconnectors.s3.transferutility.UploadPartTask.call(UploadPartTask.java:48)
  at com.amazonaws.mobileconnectors.s3.transferutility.UploadPartTask.call(UploadPartTask.java:28)
  at java.util.concurrent.FutureTask.run(FutureTask.java:237)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
at java.lang.Thread.run(Thread.java:818)

• This is almost instantaneously (few ms) followed by
  onProgressChanged call with params: id: 7, bytesCurrent: 15244198, bytesTotal: 15244198
• After that there is complete silence and onStateChanged is never called.

Few notes:

• This usually happens the first time I do an upload after a fresh start of TransferService. This suggests something similar to issue Upload files to S3 fails #94.
• I am on sdk version 2.2.14 on Nexus 5X running 6.0.1.

[fosterzhang]

@kwatra What's the state of the transfer? Is the upload successful? Would you please increase socket timeout via ClientConfiguration?

[kwatra]

@fosterzhang Thanks for the quick response.

No the upload is not successful -- I confirmed via the S3 console that the file was not uploaded.

Sure, I will try increasing the socket timeout. However I am worried that it may just decrease the frequency of this error, but the underlying problem will still exist. The main problem is that since the TransferObserver doesn't fire any error in this case, I have no way of knowing when to trigger a retry.

Thanks.

[fosterzhang]

@kwatra Thanks for the information. SocketTimeoutException is incorrectly handled as manual interruption, and thus the exception isn't propagated to user. Stay tuned for the fix.

[kwatra]

@fosterzhang Thanks for the update. Will look forward to the fix.

By any chance is this bug specific to 2.2.14, and would reverting to 2.2.13 help for the time being?

Thanks.

[fosterzhang]

@kwatra it's a general bug that exists in all versions. It's somehow tricky to fix. I have a fix in mind, but it causes unwanted behaviors. For now, I suggest you increase the socket timeout if it happens often.

[kwatra]

Thanks @fosterzhang. Will look forward to the fix.

[jsarabia]

@fosterzhang I've been having the same issue trying to test a large (500MB) upload over a relatively slow connection (2Mb down/1Mb up). I see several SocketTimeOut exceptions but the transfer does continue. I'm using onProgressChanged to report the percent completed to a progress dialog, and on reaching 100% I notice in the Android Monitor that TransferService calls stopSelf, however when I examined the TransferObserver in a debugger, getTransferState returns IN_PROGRESS. As such onStateChanged never fires (and thus I'm unable to report to the user that the transfer was unsuccessful and close the progress dialog). When I look at the bucket, the file has not been uploaded.

I've set the socket timeout to 0 (infinity) just as a test, and the upload is sometimes able to complete (though sometimes it fails but at least it does change the state to fail).

Hope this information is useful, please let me know if you'd like any more details!

[fosterzhang]

@jsarabia1247 Thanks for the information. I'll address this ASAP.

[tosulc]

Yep, this is directly connected to my problem also -> #119

I've solved it by increasing that timeout, for now.

ps. Thanks for responding so quickly :)

[prakashkgm]

@fosterzhang and all, Thanks for these discussion, we are also facing the same problem.

Here are some more details, these may help you to figure out the exact problem I believe,

Uploading file bytesCurrent exceeded from bytesTotal.
         total: 17914286, current: 16300462
         total: 17914286, current: 16447918
         total: 17914286, current: 16562606
         total: 17914286, current: 16808366
         total: 17914286, current: 16931246
         total: 17914286, current: 17283502
         total: 17914286, current: 17430958
         total: 17914286, current: 17545646
         total: 17914286, current: 17914286 - Reached the max size
         total: 17914286, current: 18028974
         total: 17914286, current: 18258350
         total: 17914286, current: 18479534
         total: 17914286, current: 18725294
         total: 17914286, current: 18749870

This is the reason still IN_PROGRESS state is notified by the TransferObserver.

[fosterzhang]

@kwatra @jsarabia1247 This is fixed in v2.2.16. For detailed changes, please refer to the change log.

[kwatra]

Great. Thanks!

[vinkrish]

still facing this issues with aws sdk 2.4.1

[maliknaseer]

still facing the issue in sdk 2.6.6