Aws-sdk-android: S3 TransferUtility: Transfers don't seem to resume after termination, are always included in list

[hipwelljo]

Describe the bug
In my app I have started an upload, then manually terminated the app, then reopened the app. In the onResult callback from initialize I can see there is 1 transfer in the list provided by getTransfersWithType(UPLOAD) and its state is IN_PROGRESS. I then call resumeAllWithType(UPLOAD);. I wait a long while then rerun the app and I see the transfer is still provided in the list of upload transfers and it has the same status. I expected it to resume and upload since I have a good internet connection, and no longer be included in the list of transfers on the next run.

I was following along the SDK guide to implement resuming support. Perhaps I am missing something though. Currently I am not seeing any logs of state change, progress, or errors upon resuming the transfers. I am assuming though I need to set transfer listeners for these right (to monitor upload progress and state changes), or are they preserved from the previous session? Seems something else is wrong, even without listeners I would think it would upload upon resume.

To Reproduce
Steps to reproduce the behavior:

1. Start to upload a file
2. Force close the app from the recent apps screen before the upload completes
3. Rerun the app, triggering resumeAllWithType(UPLOAD)
4. Wait a long while giving it sufficient time to upload the file
5. Rerun the app and examine getTransfersWithType(UPLOAD)

Which AWS service(s) are affected?
S3 TransferUtility

Expected behavior
The transfer should have been resumed, successfully uploaded, and thus it shouldn't be in the list of transfers upon running again

Environment:

• SDK Version: 2.9.0

Device Information:

• Device: Google Pixel
• Android Version: 7.1.2
• Specific to simulators: No

Code:
To initialize and resume transfers in the startup activity's onCreate:

        AWSMobileClient.getInstance().initialize(getApplicationContext(), new Callback<UserStateDetails>() {
            @Override
            public void onResult(UserStateDetails result) {
                Log.d(TAG, "AWSMobileClient initialized. User State is " + result.getUserState());

                TransferUtility transferUtility =
                        TransferUtility.builder()
                                .context(getApplicationContext())
                                .awsConfiguration(AWSMobileClient.getInstance().getConfiguration())
                                .s3Client(new AmazonS3Client(AWSMobileClient.getInstance()))
                                .build();

                List<TransferObserver> observerList = transferUtility.getTransfersWithType(UPLOAD);
                //TODO: Need to set listeners?

                Log.d(TAG, "Upload transfers count: " + observerList.size());
                Log.d(TAG, "Upload transfers: " + observerList.toString());

                transferUtility.resumeAllWithType(UPLOAD);
            }

            @Override
            public void onError(Exception e) {
                Log.e(TAG, "Initialization error.", e);
            }
        });

        getApplicationContext().startService(new Intent(getApplicationContext(), TransferService.class));

To upload the file:

        TransferUtility transferUtility =
                TransferUtility.builder()
                        .context(context.getApplicationContext())
                        .awsConfiguration(AWSMobileClient.getInstance().getConfiguration())
                        .s3Client(new AmazonS3Client(AWSMobileClient.getInstance()))
                        .build();

        final String filename = "image_" + randomAlphaNumeric(10) + ".jpg";

        File file = scaleImage(uri, context.getCacheDir().getPath() + File.separator + filename);

        TransferObserver transferObserver = transferUtility.upload("bucketname", filename, file);
        transferObserver.setTransferListener(new TransferListener() {
            @Override
            public void onStateChanged(int id, TransferState state) {
                Log.d(TAG, "Upload state changed to " + state);
            }

            @Override
            public void onProgressChanged(int id, long bytesCurrent, long bytesTotal) {
                float percentDonef = ((float) bytesCurrent / (float) bytesTotal) * 100;
                int percentDone = (int)percentDonef;

                Log.d(TAG, "ID:" + id + " bytesCurrent: " + bytesCurrent
                        + " bytesTotal: " + bytesTotal + " " + percentDone + "%");
            }

            @Override
            public void onError(int id, Exception ex) {
                Log.e(TAG, ex);
            }
        });

Logs:
Upload transfers count: 1 Upload transfers: [TransferObserver{id=1, bucket='bucketname', key='image_jdvx8ewITz.jpg', bytesTotal=34094, bytesTransferred=0, transferState=IN_PROGRESS, filePath='/data/user/0/com.x.x/cache/image_jdvx8ewITz.jpg'}]

[kvasukib]

@hipwelljo, Thank you for reporting to us. Sorry for the delayed response. TransferUtility provides two methods to get the state and progress updates:

1) Observer model: The upload/download methods return a TransferObserver which encapsulates the state and progress of the transfer that has been started. However you need to invoke transferObserver.refresh() method in order to refresh the state and progress with the current value.

In the example code you posted, you are missing the call to the refresh when you use the observer model to obtain state and progress. So I would suggest you to do the following:

                 List<TransferObserver> observerList = transferUtility.getTransfersWithType(UPLOAD);

                Log.d(TAG, "Upload transfers count: " + observerList.size());
                Log.d(TAG, "Upload transfers: " + observerList.toString());

                transferUtility.resumeAllWithType(UPLOAD);

               for (TransferObserver observer: observerList) {
                   observer.refresh();
                   Log.d(TAG, "Transfer ID: " + observer.getId() + " ; Transfer State: " + observer.getState() + "; Transfer Progress: " + observer.getBytesTransferred());
               }

2) Listener model: You can attach a TransferListener object to the observer object. The listener's onStateChanged and onProgressChanged callbacks are invoked when there is a change of state and progress (controlled by the notification threshold set in AmazonS3Client object).

                 List<TransferObserver> observerList = transferUtility.getTransfersWithType(UPLOAD);

                Log.d(TAG, "Upload transfers count: " + observerList.size());
                Log.d(TAG, "Upload transfers: " + observerList.toString());

                transferUtility.resumeAllWithType(UPLOAD);

               for (TransferObserver observer: observerList) {
                   observer.setTransferListener(new TransferListener() {
                     @Override
                     public void onStateChanged(int id, TransferState state) {
                       Log.d(TAG, "Upload state changed to " + state);
                     }

                    @Override
                    public void onProgressChanged(int id, long bytesCurrent, long bytesTotal) {
                        float percentDonef = ((float) bytesCurrent / (float) bytesTotal) * 100;
                        int percentDone = (int)percentDonef;

                        Log.d(TAG, "ID:" + id + " bytesCurrent: " + bytesCurrent
                            + " bytesTotal: " + bytesTotal + " " + percentDone + "%");
                    }

                   @Override
                   public void onError(int id, Exception ex) {
                       Log.e(TAG, ex);
                   }
                 });
               }

[hipwelljo]

Thanks for the reply. Ok I added both in for safe measure and tried again. I force quit the app while a transfer was ongoing, reopened it and the following was logged:

AWSMobileClient initialized. User State is GUEST
Upload transfers count: 1
Upload transfers: [TransferObserver{id=1, bucket='bucketname', key='image_le5Ec6Tub5.jpg', bytesTotal=48392, bytesTransferred=48392, transferState=IN_PROGRESS, filePath='/data/data/com.mycompany.myapp/cache/cropped781448780.jpg'}]
Transfer ID: 1 ; Transfer State: IN_PROGRESS; Transfer Progress: 48392

The photo didn't resume uploading - no progress was reported, nothing else was logged. If I rerun the app that same transfer is included in the List.

[kvasukib]

@hipwelljo I'm seeing bytesTotal=48392, bytesTransferred=48392. So does this mean that the transfer completed, but the state changed callback is not yet triggered? Can you share the complete class/activity which is invoked when the app restarts?

[hipwelljo]

It looks like that one did upload successfully - it's in the s3 bucket. So it's strange it is still included in the list with an IN_PROGRESS state. I tried it again and force quit the app before it completed the transfer and here's the log for that upon reopening the app. No further logs appeared.

AWSMobileClient initialized. User State is SIGNED_OUT
Upload transfers count: 1
Upload transfers: [TransferObserver{id=1, bucket='bucketname', key='image_cWhYVSGbEP.jpg', bytesTotal=59381, bytesTransferred=0, transferState=IN_PROGRESS, filePath='/data/data/com.mycompany.myapp/cache/cropped781448780.jpg'}]
Transfer ID: 1 ; Transfer State: IN_PROGRESS; Transfer Progress: 0

[hipwelljo]

Here's that activity invoked when the app is opened.

public class SplashActivity extends AppCompatActivity {

    private static final String TAG = "SplashActivity";

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);

        AWSMobileClient.getInstance().initialize(getApplicationContext(), new Callback<UserStateDetails>() {
            @Override
            public void onResult(UserStateDetails result) {
                DpsLog.d(TAG, "AWSMobileClient initialized. User State is " + result.getUserState());

                TransferUtility transferUtility =
                        TransferUtility.builder()
                                .context(getApplicationContext())
                                .awsConfiguration(AWSMobileClient.getInstance().getConfiguration())
                                .s3Client(new AmazonS3Client(AWSMobileClient.getInstance()))
                                .build();

                List<TransferObserver> observerList = transferUtility.getTransfersWithType(UPLOAD);

                DpsLog.d(TAG, "Upload transfers count: " + observerList.size());
                DpsLog.d(TAG, "Upload transfers: " + observerList.toString());

                transferUtility.resumeAllWithType(UPLOAD); //resume any uploads that were paused on app termination

                for (TransferObserver observer: observerList) {
                    observer.refresh();
                    DpsLog.d(TAG, "Transfer ID: " + observer.getId() + " ; Transfer State: " + observer.getState() + "; Transfer Progress: " + observer.getBytesTransferred());
                }

                //OR
                for (TransferObserver observer: observerList) {
                    observer.setTransferListener(new TransferListener() {
                        @Override
                        public void onStateChanged(int id, TransferState state) {
                            DpsLog.d(TAG, "Upload state changed to " + state);
                        }

                        @Override
                        public void onProgressChanged(int id, long bytesCurrent, long bytesTotal) {
                            float percentDonef = ((float) bytesCurrent / (float) bytesTotal) * 100;
                            int percentDone = (int)percentDonef;

                            DpsLog.d(TAG, "ID:" + id + " bytesCurrent: " + bytesCurrent
                                    + " bytesTotal: " + bytesTotal + " " + percentDone + "%");
                        }

                        @Override
                        public void onError(int id, Exception ex) {
                            DpsLog.e(TAG, ex);
                        }
                    });
                }
            }

            @Override
            public void onError(Exception e) {
                DpsLog.e(TAG, "Initialization error.", e);
            }
        });

        getApplicationContext().startService(new Intent(getApplicationContext(), TransferService.class));

        finish();
    }

[kvasukib]

@hipwelljo It's possible that the TransferObserver object has a stale state. Observer needs to be refreshed in order to get the accurate information. Can you do a transferObserver.refresh() before accessing any state in the observer? Did you get the onStateChanged() callback?

[hipwelljo]

Okay, I moved this block of code

for (TransferObserver observer: observerList) {
    observer.refresh();
    Log.d(TAG, "Transfer ID: " + observer.getId() + " ; Transfer State: " + observer.getState() + "; Transfer Progress: " + observer.getBytesTransferred());
}

immediately after List<TransferObserver> observerList = transferUtility.getTransfersWithType(UPLOAD);

and tried it again, but I get the same result. No, onStateChanged() is not triggered, no other info is logged from any of the listener callbacks.

[kvasukib]

@hipwelljo Can we get into a call so we can root cause the issue faster? You can drop me an email at: karthba at amazon dot com? We can discuss both the issues you have raised.

[hipwelljo]

As we discussed on the call, I changed the code to get the list from resumeAllWithType instead of getTransfersWithType and tried it again. I'm seeing different behavior now. So I initiate an upload then force close the app. Upon relaunching, I'm now getting an empty list. It's empty no matter if I kill the app right after receiving the 0% progress notice, or right after receiving 100% (but before the state change occurs).

I start the service in the Application subclass, then I initialize in the first activity like so:

@Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);

        AWSMobileClient.getInstance().initialize(getApplicationContext(), new Callback<UserStateDetails>() {
            @Override
            public void onResult(UserStateDetails result) {
                Log.d(TAG, "AWSMobileClient initialized. User State is " + result.getUserState());

                //resume any uploads that were paused on app termination

                TransferUtility transferUtility =
                        TransferUtility.builder()
                                .context(getApplicationContext())
                                .awsConfiguration(AWSMobileClient.getInstance().getConfiguration())
                                .s3Client(new AmazonS3Client(AWSMobileClient.getInstance()))
                                .build();

                List<TransferObserver> observerList = transferUtility.resumeAllWithType(UPLOAD);

                for (TransferObserver observer: observerList) { //this shouldn't be needed since using listeners below
                    observer.refresh();
                    Log.d(TAG, "Transfer ID: " + observer.getId() + " ; Transfer State: " + observer.getState() + "; Transfer Progress: " + observer.getBytesTransferred());
                }

                Log.d(TAG, "Upload transfers count: " + observerList.size());
                Log.d(TAG, "Upload transfers: " + observerList.toString());

                for (TransferObserver observer: observerList) {
                    observer.setTransferListener(new TransferListener() {
                        @Override
                        public void onStateChanged(int id, TransferState state) {
                            Log.d(TAG, "Upload state changed to " + state);
                        }

                        @Override
                        public void onProgressChanged(int id, long bytesCurrent, long bytesTotal) {
                            float percentDonef = ((float) bytesCurrent / (float) bytesTotal) * 100;
                            int percentDone = (int)percentDonef;

                            Log.d(TAG, "ID:" + id + " bytesCurrent: " + bytesCurrent
                                    + " bytesTotal: " + bytesTotal + " " + percentDone + "%");
                        }

                        @Override
                        public void onError(int id, Exception ex) {
                            Log.e(TAG, ex);
                        }
                    });
                }
            }

            @Override
            public void onError(Exception e) {
                Log.e(TAG, "Initialization error.", e);
            }
        });

        //start new activity...
        finish();
    }

This is how the transfer is initiated:

public static void uploadImage(final Context context, final Uri uri, final DpsRunnable<Integer> onProgressChanged, final DpsRunnable<String> onComplete) {
        AmazonS3Client client = new AmazonS3Client(AWSMobileClient.getInstance());
        client.setNotificationThreshold(10);

        TransferUtility transferUtility =
                TransferUtility.builder()
                        .context(context.getApplicationContext())
                        .awsConfiguration(AWSMobileClient.getInstance().getConfiguration())
                        .s3Client(client)
                        .build();

        final String filename = "image_" + randomAlphaNumeric(10) + uri.getLastPathSegment().substring(uri.getLastPathSegment().lastIndexOf("."));

        File file = scaleImage(uri, context.getCacheDir().getPath() + File.separator + filename);

        Log.d(TAG, "Will upload " + filename);

        TransferObserver transferObserver = transferUtility.upload("bucketname", filename, file);
        transferObserver.setTransferListener(new TransferListener() {
            @Override
            public void onStateChanged(int id, TransferState state) {
                Log.d(TAG, "Upload state changed to " + state);

                if (state == TransferState.COMPLETED) {
                    //yay success!
                } else if (state == TransferState.FAILED) {
                    //try again - sdk doesn't automatically retry atm
                    //but sometimes it reports FAILED when it successfully uploaded, so need a workaround
                    //TODO client.getObjectMetadata() - check file size and last updated
                    uploadImage(context, uri, onProgressChanged, onComplete);
                }
            }

            @Override
            public void onProgressChanged(int id, long bytesCurrent, long bytesTotal) {
                float percentDonef = ((float) bytesCurrent / (float) bytesTotal) * 100;
                int percentDone = (int)percentDonef;
                onProgressChanged.run(percentDone);

                Log.d(TAG, "ID:" + id + " bytesCurrent: " + bytesCurrent
                        + " bytesTotal: " + bytesTotal + " " + percentDone + "%");
            }

            @Override
            public void onError(int id, Exception ex) {
                Log.e(TAG, ex);
            }
        });
}

And the logs:

Will upload image_Kf57NY31dl.jpg
Upload state changed to IN_PROGRESS
ID:2 bytesCurrent: 0 bytesTotal: 64890 0%
**force quit app and relaunched**
AWSMobileClient initialized. User State is GUEST
Upload transfers count: 0
Upload transfers: []

I was expecting there to be one upload transfer in that list that would be resumed.

This is interesting too. I do see that failed transfers are included in this list upon relaunching the app. So resumeAllWithType is resuming all of the previously failed transfers even though they were retried (and probably eventually succeeded). So now I have a lot of duplicate photos uploaded. Should I 'delete' a transfer before manually retrying it or what's the right thing to do here? Thanks!

[kvasukib]

@hipwelljo Thank you for the quick try. resumeAllWithType only resumes the transfers that are in one of the three states:

  final List<Integer> transferIds = getTransferIdsWithTypeAndStates(type, 
            new TransferState[] {
                TransferState.PAUSED,
                TransferState.FAILED,
                TransferState.CANCELED
            }
        );

Since your transfer is in IN_PROGRESS, it is not picked up by the call. I would suggest to do the following:

        List<TransferObserver> observers = new ArrayList<TransferObserver>();
        final List<Integer> transferIds = getTransfersWithType(TransferType.UPLOAD);

        for (final Integer transferId: transferIds) {
            observers.add(resume(transferId));
        }

        for (TransferObserver observer: observerList) {
                    observer.setTransferListener(new TransferListener() {
                        @Override
                        public void onStateChanged(int id, TransferState state) {
                            Log.d(TAG, "Upload state changed to " + state);
                        }

                        @Override
                        public void onProgressChanged(int id, long bytesCurrent, long bytesTotal) {
                            float percentDonef = ((float) bytesCurrent / (float) bytesTotal) * 100;
                            int percentDone = (int) percentDonef;

                            Log.d(TAG, "ID:" + id + " bytesCurrent: " + bytesCurrent
                                    + " bytesTotal: " + bytesTotal + " " + percentDone + "%");
                        }

                        @Override
                        public void onError(int id, Exception ex) {
                            Log.e(TAG, ex);
                        }
                    }
                    );
        }

[hipwelljo]

That did the trick thanks! What do you think about the last paragraph?

I do see that failed transfers are included in this list upon relaunching the app. So I am resuming all of the previously failed transfers even though they were retried (and probably eventually succeeded). So now I have a lot of duplicate photos uploaded. Should I 'delete' a transfer before manually retrying it or what's the right thing to do here? Thanks!

[kvasukib]

@hipwelljo I would recommend checking if the object exists in S3 for failed transfers before retrying them.

final List<Integer> transferIds = getTransferIdsWithTypeAndStates(type, 
            new TransferState[] {
                TransferState.FAILED
            }
        );
for (int transferId : transferIds) {
        if (keyDoesNotExistInS3) {
            transferUtility.resume(transferId) OR transferUtility.upload(key, file);
       }
}

[hipwelljo]

Hm this is tricky because when a transfer fails I start a new transfer to try it again, and the key/filename is not the same. So when I open the app the next time and go to resume uploads, if I look at the failed transfers none of them will exist in S3 by that key however it probably did succeed with a different key. Perhaps the logic can be changed to use the previous key. But I would like to avoid querying for the object metadata for each failed transfer too, since transfers could continually fail many times on repeat so there could be a lot of transfers in the failed state on the next app launch, and there may not be a good enough connection to determine if it exists or not.

I do see an API to deleteTransferRecord() by id. If I were to delete the failed transfer and then start a new transfer for that file, naively it seems that would solve this problem, do you see any harm in that?

[kvasukib]

@hipwelljo Yes, you can use deleteTransferRecord to remove the transfer record from the persistence store. I would suggest you to test and see if it's working as this will leave an inconsistency in the state that is stored in memory vs disk.

[hipwelljo]

Testing has been going well with that in place, it's resuming the appropriate transfers on app relaunch. Is there a way to remove it from the in-memory store in addition to deleting from disk? Or otherwise mark this transfer as being 'completed' in that I'm not interested in keeping it around anymore.

[kvasukib]

@hipwelljo Thank you for confirming. I will check into the code and let you know about the in-memory state. Regardless, any inconsistency in the state is a bug and we should be tracking it.

[hipwelljo]

I took a look at this again and may have a better solution! Rather than delete the transfer and start a new one for that same asset, I thought I could just resume the existing transfer upon fail to retry the upload (the same as I do when reopening the app and resuming any previously ongoing transfers including failed ones). Interestingly, this doesn't seem to work - the photo is not uploaded to S3 and the new listener I set on the new TransferObserver never has its callbacks triggered. Should calling TransferObserver newTransferObserver = transferUtility.resume(id); from within onStateChanged when the state is FAILED work to retry the upload? If I force close the app and reopen it then it will resume and upload as expected, so that seems odd to me it's not resuming in this scenario when the process seems to be the same. Thanks for all your help!

[kvasukib]

Can you verify if you did the following?

        transferObserver = transferUtility.upload(key, tempFile);

        // Attach a listener to the observer to get state update and progress notifications
        transferObserver.setTransferListener( new TransferListener() {
            @Override
            public void onStateChanged(int id, TransferState state) {
                Log.i(LOG_TAG, "onStateChanged = " + state);

                if (TransferState.FAILED == state) {
                    transferObserver = transferUtility.resume(transferObserver.getId());
                    transferObserver.setTransferListener(this); // Setting to `this` may retry infinitely when the upload keeps failing. You can also set a brand new TransferListener object here.
                }
            }

            @Override
            public void onProgressChanged(int id, long bytesCurrent, long bytesTotal) {
                float percentDonef = ((float) bytesCurrent / (float) bytesTotal) * 100;
                int percentDone = (int)percentDonef;

                Log.i(LOG_TAG, "ID:" + id + " bytesCurrent: " + bytesCurrent
                        + " bytesTotal: " + bytesTotal + " " + percentDone + "%");
            }

            @Override
            public void onError(int id, Exception ex) {
                // Handle errors
                ex.printStackTrace();
            }
        });

[hipwelljo]

Yes that's what I have. Well I had initially just set a new transfer listener but simply assigning this is even better! I tried that out and unfortunately I'm getting the same behavior. Here's the logs I'm seeing. First I make sure network link conditioner is enabled with the 100% loss profile then start an upload.

Will upload image_sPlLWXuzHS.jpg
ID:22 bytesCurrent: 0 bytesTotal: 39445 0%
ID:22 bytesCurrent: 0 bytesTotal: 39445 0%
Upload state changed to FAILED for 22
Retrying photo upload for 22

After that I disable the 100% loss profile and wait but no more logs appear and that image is not in the S3 bucket.

The only difference I see between your code and mine is I assign the original listener in a different helper function, which means I need to get a new instance of the TransferUtility in onStateChange. I don't suspect that'd be a problem but I do that like so:

    private static TransferUtility getTransferUtility(final Context context) {
        AmazonS3Client client = new AmazonS3Client(AWSMobileClient.getInstance());
        client.setNotificationThreshold(10);

        return TransferUtility.builder()
                .context(context.getApplicationContext())
                .awsConfiguration(AWSMobileClient.getInstance().getConfiguration())
                .s3Client(client)
                .build();
    }

[kvasukib]

@hipwelljo If it's a single-part upload, resume and upload would do the same thing. Our granularity of restoration is 5MB, i.e TransferUtility will remember what is the last 5MB chunk that has been successfully uploaded to resume from that point. Did you try calling upload again and did that work?

[hipwelljo]

If I call upload it does work, just resume does not strangely. Unfortunately I can't really call upload though because the File uri is only persisted in memory, so when the app is relaunched and we resume uploads, if one of them fails, I don't have the File to pass into upload, I just have the transfer. The other problem with that is upload creates a new id for that transfer, so I'd have to delete the old transfer and query/update my asset in my database with the new transfer id because I persist that, which isn't ideal as the transfer could fail and retry many times in quick succession.

[hipwelljo]

I have found that resume() does work if I wait a second to call it instead of immediately calling it in onStateChanged.

TransferListener listener = this;
new Handler().postDelayed(new Runnable() {
    @Override
    public void run() {
        Log.d(TAG, "Retrying photo upload for " + id);
        TransferUtility transferUtility = getTransferUtility(context);
        TransferObserver newTransferObserver = transferUtility.resume(id);
        newTransferObserver.setTransferListener(listener);
    }
}, 1000);

[kvasukib]

@hipwelljo I believe it's a race condition between the previous transfer for the same file that is terminating (success/failure/onStateChanged) and the new transfer that is being started. I am looking into the bug where there is an inconsistency in the callback being invoked.

[kvasukib]

@hipwelljo I have made some improvements to TransferUtility in 2.11. and 2.12.0. Can you upgrade and test and let me know if there is any feedback?

[hipwelljo]

Can confirm I am able to resume a failed transfer without the 1 second delay in 2.12.0. It seems this issue can be closed. Thanks!!