Aws-sdk-android: S3 transferUtility progress tracking issue

[FilenkovMaxim]

To help us solve your problem better, please answer the following list of questions.

• What service are you using?
  TransferUtility (download)

• In what version of SDK are you facing the problem?
  com.amazonaws:aws-android-sdk-s3:2.4.7

• Is the issue limited to Simulators / Actual Devices?
  Actual Device (Xiaomi)

• Can your problem be resolved if you bump to a higher version of SDK?
  no

• Is this problem related to specific Android/OS version?
  no

• Can you give us steps to reproduce with a minimal, complete, and verifiable example? Please include any specific network conditions that might be required to reproduce the problem.

I received not smoothy and not realistic data at onProgressChanged from TransferUtility. It finished downloading in one time after reached half size. Just jumped to 100% from 60%
It looks like this (look at the last line):
`21:58:41.0830 [main] D onProgressChanged(5, 56288708 / 111444303)

21:58:42.0750 [main] D onProgressChanged(5, 57845212 / 111444303)
21:58:43.0900 [main] D onProgressChanged(5, 59303172 / 111444303)
21:58:44.0880 [main] D onProgressChanged(5, 60466652 / 111444303)
21:58:45.0020 [main] D onProgressChanged(5, 111444303 / 111444303)`

And some times I got zero in bytesTotal argument. Not zero in first time, and then all of the calls with zero, and the last one with not zero again.

[kvasukib]

Hi @FilenkovMaxim,

Thanks for reporting to us.

1. Does the non-smooth progress behavior happen for every transfer? for every file? or just in this case?
2. Can you post the log entries when bytesTotal was zero? What is the frequency of this issue?

[FilenkovMaxim]

@kvasukib hi

1. It is at only one user on two devices (both Xiaomi), for every transfer, for every file (from our storage).
2. At this time I havn't logs for this and cannot repeat this. If it will repeated I'll post.

[FilenkovMaxim]

@kvasukib
Today it happens on a new device (Nexus 5, Android 6) and with different Internet provider

onProgressChanged(8, 37357164 / 111450625)
onProgressChanged(8, 38131308 / 111450625)
onProgressChanged(8, 38523500 / 111450625)
onProgressChanged(8, 111450625 / 111450625)

[FilenkovMaxim]

@kvasukib hello!
Have you any news on this theme?

[rohandubal]

Hello, what is the file type you are trying to upload? Are you using any custom headers in the request?

[FilenkovMaxim]

@rohandubal Hello!
Firstly, it's not upload, it was download.
It could be one of two types: .zip or .aac

I use only setRegion() and not always setAccelerateModeEnabled() options.

[FilenkovMaxim]

Hello. Any news?

Yesterday I've got again 0 in bytesTotal

it looked like this:

D: 19:57:21.5600 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 31352897 / 0)
D: 19:57:22.5710 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 33302926 / 0)
D: 19:57:23.5760 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 34728075 / 0)
D: 19:57:24.5720 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 36678104 / 0)
D: 19:57:25.5750 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 38201927 / 0)
D: 19:57:26.5860 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 40020588 / 0)
D: 19:57:27.6430 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 41527472 / 0)
D: 19:57:28.6140 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 43395174 / 0)
D: 19:57:29.6160 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 45246529 / 0)
D: 19:57:30.6180 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 47131170 / 0)
D: 19:57:31.6850 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 48654401 / 0)
D: 19:57:32.6820 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 50489409 / 0)
D: 19:57:33.6890 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 52455785 / 0)
D: 19:57:34.6930 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 54061343 / 0)
D: 19:57:35.6980 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 56003180 / 0)
D: 19:57:36.7720 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 56944927 / 0)
D: 19:57:37.7410 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 57879074 / 0)
D: 19:57:38.9950 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 59566367 / 0)
D: 19:57:39.7660 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 61041149 / 0)
D: 19:57:40.7690 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 61942010 / 0)
D: 19:57:41.7750 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 63154648 / 0)
D: 19:57:42.7850 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 65087738 / 0)
D: 19:57:43.7840 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 67004481 / 0)
D: 19:57:44.8470 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 68643325 / 0)
D: 19:57:45.8670 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 70396006 / 0)
D: 19:57:46.9500 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 71952523 / 0)
D: 19:57:47.9420 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 73558081 / 0)
D: 19:57:48.9370 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 75327701 / 0)
D: 19:57:49.9430 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 76965953 / 0)
D: 19:57:50.9480 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 78751920 / 0)
D: 19:57:51.9600 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 80161314 / 0)
D: 19:57:52.9580 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 81963628 / 0)
D: 19:57:54.1470 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 83528300 / 0)
D: 19:57:54.9130 [main] D OriginalTransfer::-#DOWNLOAD Transfer original 9847 onProgressChanged(14, 110625437 / 110625437)

My code is:

class OriginalTransfer implements com.amazonaws.mobileconnectors.s3.transferutility.TransferListener {
@Override
public final void onProgressChanged(int observerId, long bytesCurrent, long bytesTotal)
log.debug("{} onProgressChanged({}, {} / {})", tag, observerId, bytesCurrent, bytesTotal);
}
}

[kredden]

We have been able to reproduce the first case and are working on the fix. We have not been able to reproduce the issue where the bytesTotal is 0. Are you doing more than one download at a time or just one?

[kvasukib]

We released 2.6.6 that fixes the progress update. Can you try upgrading to 2.6.6 and check if it works for you?

[FilenkovMaxim]

@kvasukib thanks a lot. Today I'll try this.
@kredden No, no more tasks, only one. Today it was again on 2.6.5 version (

[kredden]

@FilenkovMaxim Are you still having issues or did this update fix them for you?

[FilenkovMaxim]

@kredden it seems to me that issue with progress was fixed. Thank you very much.
And I have no more got zero total bytes, but may be I need more time for it.

[kredden]

Great! I'm going to close this issue now, if the zero issue happens again please reopen it.

[kvasukib]

Hi @FilenkovMaxim,

I was able to reproduce the issue finally. Sorry for the delayed reply.

Test case:

Start a download of 294.18 MB file.
When download reaches 40%, closed the app.
Now re-open the app, the bytesTotal is zero.
Resume the transfer.
Now bytesTotal is back to 294.18MB
Leave the download progress to 70%
Close the app again and re-open the app.
Resume the transfer.
Now bytesTotal continues to be zero till 99%
When it is about to finish the transfer, the bytesTotal gets reset to 294.18MB
Now transfer succeeds with right state and progress values.

Logs here:

01-31 14:29:20.322 8560-8625/com.amazonaws.demo.s3transferutility V/StudioProfiler: Tracking initialization took: 514710595ns
01-31 14:29:29.717 8560-8565/com.amazonaws.demo.s3transferutility I/zygote: Do partial code cache collection, code=122KB, data=78KB
01-31 14:29:29.717 8560-8565/com.amazonaws.demo.s3transferutility I/zygote: After code cache collection, code=122KB, data=78KB
01-31 14:29:29.717 8560-8565/com.amazonaws.demo.s3transferutility I/zygote: Increasing code cache capacity to 512KB
01-31 14:30:19.098 8560-9156/com.amazonaws.demo.s3transferutility D/NetworkSecurityConfig: No Network Security Config specified, using platform default
01-31 14:30:20.241 8560-8560/com.amazonaws.demo.s3transferutility D/DownloadActivity: onProgressChanged: 193, total: 308470831, current: 165506816
01-31 14:30:21.653 8560-8560/com.amazonaws.demo.s3transferutility D/DownloadActivity: onProgressChanged: 193, total: 0, current: 168141123
01-31 14:30:21.780 8560-8571/com.amazonaws.demo.s3transferutility I/zygote: Background concurrent copying GC freed 16771(2MB) AllocSpace objects, 0(0B) LOS objects, 55% free, 1215KB/2MB, paused 141us total 122.244ms
01-31 14:30:22.628 8560-8571/com.amazonaws.demo.s3transferutility I/zygote: Background concurrent copying GC freed 1915(1554KB) AllocSpace objects, 0(0B) LOS objects, 54% free, 1276KB/2MB, paused 6.366ms total 137.809ms
01-31 14:30:22.783 8560-8560/com.amazonaws.demo.s3transferutility D/DownloadActivity: onProgressChanged: 193, total: 0, current: 170247491
01-31 14:30:23.237 8560-8571/com.amazonaws.demo.s3transferutility I/zygote: Background concurrent copying GC freed 2110(1615KB) AllocSpace objects, 0(0B) LOS objects, 51% free, 1437KB/2MB, paused 272us total 116.242ms
01-31 14:30:24.049 8560-8560/com.amazonaws.demo.s3transferutility D/DownloadActivity: onProgressChanged: 193, total: 0, current: 173406507
01-31 14:30:25.146 8560-8560/com.amazonaws.demo.s3transferutility D/DownloadActivity: onProgressChanged: 193, total: 0, current: 175512875
01-31 14:30:26.780 8560-8560/com.amazonaws.demo.s3transferutility D/DownloadActivity: onProgressChanged: 193, total: 0, current: 176566595
01-31 14:30:26.812 8560-8565/com.amazonaws.demo.s3transferutility I/zygote: Do full code cache collection, code=250KB, data=163KB
01-31 14:30:26.813 8560-8565/com.amazonaws.demo.s3transferutility I/zygote: After code cache collection, code=167KB, data=110KB

01-31 14:31:11.938 8560-8571/com.amazonaws.demo.s3transferutility I/zygote: Background concurrent copying GC freed 4407(3MB) AllocSpace objects, 0(0B) LOS objects, 57% free, 1158KB/2MB, paused 8.743ms total 292.532ms
01-31 14:31:12.394 8560-8560/com.amazonaws.demo.s3transferutility D/DownloadActivity: onProgressChanged: 193, total: 0, current: 298735939
01-31 14:31:13.301 8560-8571/com.amazonaws.demo.s3transferutility I/zygote: Background concurrent copying GC freed 2066(1552KB) AllocSpace objects, 0(0B) LOS objects, 56% free, 1206KB/2MB, paused 4.416ms total 194.056ms
01-31 14:31:15.323 8560-8560/com.amazonaws.demo.s3transferutility D/DownloadActivity: onProgressChanged: 193, total: 0, current: 300842307
01-31 14:31:15.557 8560-8571/com.amazonaws.demo.s3transferutility I/zygote: Background concurrent copying GC freed 2104(1535KB) AllocSpace objects, 0(0B) LOS objects, 54% free, 1286KB/2MB, paused 10.485ms total 140.211ms
01-31 14:31:15.891 8560-8560/com.amazonaws.demo.s3transferutility D/DownloadActivity: onProgressChanged: 193, total: 0, current: 301894955
01-31 14:31:16.866 8560-8571/com.amazonaws.demo.s3transferutility I/zygote: Background concurrent copying GC freed 2150(1632KB) AllocSpace objects, 0(0B) LOS objects, 54% free, 1302KB/2MB, paused 13.075ms total 228.926ms
01-31 14:31:18.070 8560-8560/com.amazonaws.demo.s3transferutility D/DownloadActivity: onProgressChanged: 193, total: 0, current: 304001323
01-31 14:31:19.216 8560-8560/com.amazonaws.demo.s3transferutility D/DownloadActivity: onProgressChanged: 193, total: 0, current: 306107691
01-31 14:31:19.669 8560-8571/com.amazonaws.demo.s3transferutility I/zygote: Background concurrent copying GC freed 1895(1424KB) AllocSpace objects, 0(0B) LOS objects, 56% free, 1189KB/2MB, paused 111us total 129.182ms
01-31 14:31:20.186 8560-8560/com.amazonaws.demo.s3transferutility D/DownloadActivity: onProgressChanged: 193, total: 308470831, current: 308470831
01-31 14:31:20.269 8560-8560/com.amazonaws.demo.s3transferutility D/DownloadActivity: onStateChanged: 193, COMPLETED

Sorry for the inconvenience caused. We are looking into the code to spot the bug. If you have additional logs by enabling strict mode or any other test which reproduce the issue, please do attach it here.

Thanks

[kvasukib]

We also identified that the transfer observer after an app restart doesn't have the correct state of the transfer. We are working on to fix the internal state managed by the observer and the listener as they don't have a consistent view of the transfer record.

[FilenkovMaxim]

Great! Please, notify me when you'll release. Then I'll be able to clean my code.

[kvasukib]

Thanks @FilenkovMaxim for the reply. Do you have a code snippet that you would like to share? Do you use the observer only or observer with a listener?

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[stale[bot]]

This issue has been automatically closed because of inactivity. Please open a new issue if are still encountering problems.