Aws-sdk-android: S3 TransferUtility : TransferListener onProgressChanged gets invoked more than once

[amankumarjain]

I am using S3 service
This is my code implementation

private void uploadFileToS3(String bucket, final String upload_file_name, final File file, final String imageWidth, final String imageHeight, final Boolean async) {

        String key = "KEY";
        String secret = "SECRET";
        BasicAWSCredentials credentials = new BasicAWSCredentials(key, secret);
        AmazonS3Client s3 = new AmazonS3Client(credentials);
        s3.setRegion(Region.getRegion(Regions.AP_SOUTHEAST_1));
        TransferUtility transferUtility = new TransferUtility(s3, this);

        observer = transferUtility.upload(bucket, upload_file_name, file);

        // only on async we will show dialog
        final CustomBottomSheetDialog dialog = new CustomBottomSheetDialog(mainActivity, R.layout.sync_image_progress_loader, false);

        observer.setTransferListener(new TransferListener() {
            @Override
            public void onStateChanged(int id, TransferState state) {
                if (state == TransferState.IN_PROGRESS) {
                    if (!async)
                        dialog.show();
                } else if(state == TransferState.COMPLETED) {
                    if (!async)
                        dialog.dismiss();
                    imageCallbackInterface.imageUploadCompleted(file, upload_file_name, imageWidth, imageHeight);
                } else  if (state ==  TransferState.FAILED) {
                    if (!async)
                        dialog.dismiss();
                    toast("Failed to Upload Image, Try Again.", Toast.LENGTH_SHORT);
                } else if (state == TransferState.CANCELED) {
                    if (!async)
                        dialog.dismiss();
                    toast("Upload Cancelled", Toast.LENGTH_LONG);
                } else if(state == TransferState.WAITING_FOR_NETWORK) {
                    if (!async)
                        dialog.dismiss();
                    toast("NO INTERNET ACCESS", Toast.LENGTH_SHORT);
                    observer.cleanTransferListener();
                }
            }

            @Override
            public void onProgressChanged(int id, long bytesCurrent, long bytesTotal) {
                Log.d("bytescurrent, bytestotal", String.valueOf(bytesCurrent)+","+String.valueOf(bytesTotal));
                Integer percentage = (int) (((float)(bytesCurrent)/(float)bytesTotal)*100);
                Log.d("percentage", String.valueOf(percentage));
                ((TextView) dialog.bottom_sheet_dialog.findViewById(R.id.sync_image_progress_value)).setText(String.valueOf(percentage) + "%");
            }

            @Override
            public void onError(int id, Exception ex) {
                log(ex.getMessage());
            }
        });

    }

File is succesfully uploaded to s3 but observer onProgressChanged listener is returning same bytesCurrent and bytesTotal every time when onProgressChanged called.

[kvasukib]

Hi @amankumarjain,

Thank you for reporting to us. Few questions before we proceed:

What version of SDK and Android are you using?
Can you paste the logs where bytesCurrent and bytesTotal values are printed?
Does this happen on both simulators/devices? Any specific device where you are able to reproduce it?
Does the transfer finish successfully inspite of the wrong progress update? Do you get a onStateChanged callback with state COMPLETED?
Was there any network disconnect and reconnect observed in the middle of the transfer?
Size and type of the file?

[amankumarjain]

• sdk version: 2.3.3, android: 7.0(remi note 4), 4.2.2(htc desire)
• transfer state failed, cancelled or waiting for network not called while upload.

 observer.setTransferListener(new TransferListener() {
            @Override
            public void onStateChanged(int id, TransferState state) {
                if (state == TransferState.IN_PROGRESS) {
                    Log.d("s3stateprogress", "called");
                    if (!async)
                        dialog.show();
                } else if(state == TransferState.COMPLETED) {
                    Log.d("s3statecompleted", "called");
                    if (!async)
                        dialog.dismiss();
                    imageCallbackInterface.imageUploadCompleted(file, upload_file_name, imageWidth, imageHeight);
                } else  if (state ==  TransferState.FAILED) {
                    Log.d("s3statefailed", "called");
                    if (!async)
                        dialog.dismiss();
                    toast("Failed to Upload Image, Try Again.", Toast.LENGTH_SHORT);
                } else if (state == TransferState.CANCELED) {
                    Log.d("s3statecanceled", "called");
                    if (!async)
                        dialog.dismiss();
                    toast("Upload Cancelled", Toast.LENGTH_LONG);
                } else if(state == TransferState.WAITING_FOR_NETWORK) {
                    Log.d("s3waitingfornetwork", "called");
                    if (!async)
                        dialog.dismiss();
                    toast("NO INTERNET ACCESS", Toast.LENGTH_SHORT);
                    observer.cleanTransferListener();
                }
            }

            @Override
            public void onProgressChanged(int id, long bytesCurrent, long bytesTotal) {
                Log.d("s3bytescurrent, s3bytestotal", String.valueOf(bytesCurrent)+","+String.valueOf(bytesTotal));
                Integer percentage = (int) (((float)(bytesCurrent)/(float)bytesTotal)*100);
                ((TextView) dialog.bottom_sheet_dialog.findViewById(R.id.sync_image_progress_value)).setText(String.valueOf(percentage) + "%");
            }

            @Override
            public void onError(int id, Exception ex) {
                log(ex.getMessage());
            }
        });


02-08 00:31:38.851 7530-7530/in.codersbyte.namostu D/s3stateprogress: called
02-08 00:31:38.861 7530-7530/in.codersbyte.namostu D/s3bytescurrent, s3bytestotal: 0,54790
02-08 00:31:39.243 7530-7530/in.codersbyte.namostu D/s3bytescurrent, s3bytestotal: 54790,54790
02-08 00:31:39.779 7530-7530/in.codersbyte.namostu D/s3bytescurrent, s3bytestotal: 54790,54790
02-08 00:31:39.779 7530-7530/in.codersbyte.namostu D/s3bytescurrent, s3bytestotal: 54790,54790
02-08 00:31:39.793 7530-7530/in.codersbyte.namostu D/s3statecompleted: called

• i have only tested it on devices, ex: redmi note4, htc desire (these two devices)
• yes completed state gets called after succesful complete, no network discount

[kvasukib]

Thank you for the detailed information @amankumarjain. Would you like to try our latest SDK 2.6.14 and see if it mitigates the progress update problem? We had few bug fixes around progress tracking fixed in 2.3.x and 2.4.x. Thanks.

[amankumarjain]

update to 2.6.14 still i am facing same problem

02-08 03:21:17.581 16757-16757/in.codersbyte.namostu D/s3bytescurrent, s3bytestotal: 0,79621
02-08 03:21:18.472 16757-16757/in.codersbyte.namostu D/s3bytescurrent, s3bytestotal: 79621,79621
02-08 03:21:18.488 16757-16757/in.codersbyte.namostu D/s3bytescurrent, s3bytestotal: 79621,79621
02-08 03:21:18.505 16757-16757/in.codersbyte.namostu D/s3bytescurrent, s3bytestotal: 79621,79621

and TransferUtility is deprecated in this version, may i know whats the alternative for this.

[kvasukib]

I did see that now in 2.3.+ version: (same behavior in 2.6.+ version)

02-07 16:50:46.776 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onProgressChanged: 127, total: 2704505, current: 0
02-07 16:50:47.226 3530-4088/com.amazonaws.demo.s3transferutility D/CRLSetManager: getInstance binder: android.os.BinderProxy@422039d8
02-07 16:50:47.486 3530-4088/com.amazonaws.demo.s3transferutility D/dalvikvm: GC_FOR_ALLOC freed 1989K, 56% free 5829K/13172K, paused 22ms, total 22ms
02-07 16:50:47.486 3530-3540/com.amazonaws.demo.s3transferutility W/CursorWrapperInner: Cursor finalized without prior close()
02-07 16:50:47.606 3530-4088/com.amazonaws.demo.s3transferutility D/dalvikvm: GC_FOR_ALLOC freed 2216K, 58% free 5646K/13172K, paused 20ms, total 20ms
02-07 16:50:47.666 3530-4088/com.amazonaws.demo.s3transferutility D/dalvikvm: GC_FOR_ALLOC freed 1917K, 57% free 5776K/13172K, paused 13ms, total 13ms
02-07 16:50:47.726 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onProgressChanged: 127, total: 2704505, current: 2704505
02-07 16:50:49.926 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onProgressChanged: 127, total: 2704505, current: 2704505
02-07 16:50:49.956 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onProgressChanged: 127, total: 2704505, current: 2704505
02-07 16:50:49.966 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onStateChanged: 127, COMPLETED

The progress update happens for every certain X amount of bytes and the file if its smaller than the threshold, the progress update is made just once.

For example the fule I uploaded is approximately 2.7MB so the progress was just instantaneous from 0 to 2.7MB but the onProgressChanged was called more than once (three times).

Now I tried a file of 3.75MB

02-07 16:53:30.631 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onProgressChanged: 128, total: 3932610, current: 0
02-07 16:53:31.121 3530-4446/com.amazonaws.demo.s3transferutility D/CRLSetManager: getInstance binder: android.os.BinderProxy@422039d8
02-07 16:53:31.421 3530-4446/com.amazonaws.demo.s3transferutility D/dalvikvm: GC_FOR_ALLOC freed 2272K, 58% free 5549K/13172K, paused 21ms, total 21ms
02-07 16:53:31.421 3530-3540/com.amazonaws.demo.s3transferutility W/CursorWrapperInner: Cursor finalized without prior close()
02-07 16:53:31.511 3530-4446/com.amazonaws.demo.s3transferutility D/dalvikvm: GC_FOR_ALLOC freed 1879K, 58% free 5646K/13172K, paused 13ms, total 14ms
02-07 16:53:31.571 3530-4446/com.amazonaws.demo.s3transferutility D/dalvikvm: GC_FOR_ALLOC freed 1913K, 57% free 5776K/13172K, paused 11ms, total 11ms
02-07 16:53:31.621 3530-4446/com.amazonaws.demo.s3transferutility D/dalvikvm: GC_FOR_ALLOC freed 2158K, 58% free 5647K/13172K, paused 11ms, total 11ms
02-07 16:53:31.631 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onProgressChanged: 128, total: 3932610, current: 2490368
02-07 16:53:31.681 3530-4446/com.amazonaws.demo.s3transferutility D/dalvikvm: GC_FOR_ALLOC freed 1917K, 57% free 5777K/13172K, paused 11ms, total 11ms
02-07 16:53:37.711 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onProgressChanged: 128, total: 3932610, current: 3932610
02-07 16:53:37.741 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onProgressChanged: 128, total: 3932610, current: 3932610
02-07 16:53:37.741 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onProgressChanged: 128, total: 3932610, current: 3932610

Now there were three progress updates: 0MB, 2.4MB, 3.75MB. But for the last progress update, it was called thrice.

Now I tried a file of 294.18MB (video/mp4)

The last few entries:

02-07 16:58:49.244 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onProgressChanged: 130, total: 308470831, current: 334554159
02-07 16:58:51.294 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onProgressChanged: 130, total: 308470831, current: 335136862
02-07 16:58:51.344 3530-5204/com.amazonaws.demo.s3transferutility D/dalvikvm: GC_FOR_ALLOC freed 2224K, 56% free 5800K/13172K, paused 21ms, total 22ms
02-07 16:58:51.474 3530-5204/com.amazonaws.demo.s3transferutility D/dalvikvm: GC_FOR_ALLOC freed 1924K, 56% free 5924K/13172K, paused 12ms, total 12ms
02-07 16:58:52.374 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onProgressChanged: 130, total: 308470831, current: 336316510
02-07 16:58:54.144 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onProgressChanged: 130, total: 308470831, current: 336316510
02-07 16:58:54.704 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onProgressChanged: 130, total: 308470831, current: 308470831
02-07 16:58:54.754 3530-3530/com.amazonaws.demo.s3transferutility D/UploadActivity: onStateChanged: 130, COMPLETED

Overall it looks like there are duplicate callbacks getting invoked when the transfer finishes (mostly when state changes to COMPLETED). This might be a bug in the code where we invoke the onProgressChanged more than once. We are looking into it.

For files < 5MB this appears like bytesCurrent == bytesTotal, but for files >= 5MB you can clearly see that we update progress as transfer progresses.

[amankumarjain]

I am uploading image file which will always be less than 256 kb.
This scenario is happening past 2,3 days because when i have implemented this setup 15 days before onProgressChanged was working fine for any size file. (version 2.3.3)

[kvasukib]

@amankumarjain Do you have any logs where uploading a file less than 256KB did not result in duplicate callbacks?

[amankumarjain]

now its not working as expected, i don't know what happened but previouslly it was not duplicate callbacks it was different callback with different currentBytes and totalBytes when i have implemented this i have tested it very properlly. now in my production app also this same error is hapenning, it started 2,3 days back previouslly it was running fine.

[kvasukib]

Thank you @amankumarjain for the quick response. I could reproduce this issue easily in releases from 2.3.x to the latest. I am looking into the progress event and progress update code to find why the callback is invoked more than once especially during the finish of the transfer. I will update on this thread once I have the concrete the root cause. Thank you for the patience.

You can however use the setNotificationThreshold to control the frequency of the progress update. Setting it to a value lower than the default can give you more granular progress updates, but beware of the fact that there will be a lot of callbacks. This API is available in AmazonS3Client class that you construct and pass it to TransferUtility.

[lolsheeplol]

@amankumarjain I didn't see if your question about TransferUtility being deprecated was answered so I thought I'd chime in. Only the public constructor was deprecated, and it's recommended to instead use TransferUtility.builder().s3Client(s3).context(context).build() instead.

[kvasukib]

Hi @amankumarjain, We have identified the problem with the download operation. For every X bytes of data received over the network, the TransferUtility gets a callback which inturn calls the transfer listener that you have attached with the observer. In addition to this the thread that downloads the file updates the progress to bytesTotal after the file is saved to disk through the same interface, which makes an extra callback to the listener. Hence, you get duplicate callbacks when the download finishes. Same theory applied to the upload as well. We are working on to fix the problem. Thank you for your patience.

[kvasukib]

@amankumarjain Sorry for the delay. I am working on a fix that would fix the duplicate callbacks in progress update along with the issue reported in #611

[kvasukib]

@amankumarjain I have fixed this issue in 2.11.1 version of the SDK. It contains improved exception handling and pause/resume handling and fixes the progress reporting issue when a transfer is paused and resumed. Please upgrade to 2.11.1 and let us know if it fixes the issue.

Root cause analysis:

1) When a transfer is paused by the user or due to network drop, the thread that is managing the multipart transfer is interrupted. When the thread is interrupted and encounters an exception, there is a case where we skip setting the transfer to PAUSED or WAITING_FOR_NETWORK, and instead moves to FAILED.

2) When a transfer is paused by the user or due to network drop, the thread that is managing the multipart transfer is interrupted. When a multi-part transfer (N parts) is interrupted, there are X number of parts that may have been completed, Y number of parts that may been in progress and Z number of parts that are yet to be started (X + Y + Z = N). When a part that is in progress is interrupted, and then resumed at a later point, the part is retried from the beginning, however the progress made in the previous attempt that is interrupted is not reset from the total progress. This caused the progress reported to go over 100%.

Description of the fix:

The fix involves

1) improving the exception handling of transfers:
Improved the state, progress and error reporting when the transfers are interrupted.

• When the transfer is paused or cancelled by the user, the state is reported correctly.
• When the transfer is interrupted because of a network drop, the state is set to WAITING_FOR_NETWORK when the TransferNetworkLossHandler is used.
• When the transfer is interrupted otherwise, the transfer is set to FAILED and the exception is reported via TransferListener.onError callback.

2) Fix the progress reporting to not go beyond 100% and reset when a part failed.

See 2.11.1 for more information.

[stale[bot]]

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