Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

TransferUtility Pause/Resume Progress #677

Closed
RuiEEE opened this issue Jan 25, 2019 · 12 comments
Closed

TransferUtility Pause/Resume Progress #677

RuiEEE opened this issue Jan 25, 2019 · 12 comments
Assignees
Labels
pending-community-response Issue is pending response from the issue requestor question General question s3 Issues with the AWS Android SDK for Simple Storage Service (S3).

Comments

@RuiEEE
Copy link

RuiEEE commented Jan 25, 2019

Describe the bug
After 2.11.0, when pausing and resuming an upload I'm not getting updates on the progress. Moreover, when I pause, I receive the FAILED state, If I resume it, the upload will eventually resume (and complete) but not get notified on the same transfer listener. I tried re-attaching the listener after the resume but it won't get notifed anyway.

To Reproduce

  1. Start an upload via TransferUtility
  2. Pause
  3. Resume
  4. The attached TransferListener will not get notified of the progress after resuming but eventually the upload will complete.

Which AWS service(s) are affected?
TransferUtility

Expected behavior
After pause and resuming a specific transfer, I expect the same transfer listener to be notified of the progress.

Environment:
2.11.0

Device Information:

  • Samsung S7 Edge
  • Android O

Additional context
On SDK version 2.10.1 I'm getting the expected updates

@mutablealligator
Copy link
Contributor

mutablealligator commented Jan 25, 2019

Hi @RuiEEE Sorry for the inconvenience caused.
Are you attaching a TransferListener to the TransferObserver object returned by the resume method?
Can you post a code snippet?
What is the size of the file you are uploading?

@mutablealligator mutablealligator self-assigned this Jan 25, 2019
@mutablealligator mutablealligator added the s3 Issues with the AWS Android SDK for Simple Storage Service (S3). label Jan 25, 2019
@RuiEEE
Copy link
Author

RuiEEE commented Jan 25, 2019

Yes. At first I wasn't because in version 2.10.1 was not needed. But then I was but I'm still not getting callbacks on the listener.

@mutablealligator mutablealligator added the question General question label Jan 25, 2019
@mutablealligator
Copy link
Contributor

mutablealligator commented Jan 25, 2019

@RuiEEE I wrote a test to reproduce this issue and pasting the test here.

    @Test
    public void testListener_Upload_PauseResume() throws Exception {
        Log.d(LOG_TAG, "testListener_Upload_PauseResume begin");

        final long size = 4 * MB;
        final File tempFile = temp.newFile();
        fillFile(tempFile, size);

        final CountDownLatch countDownLatch = new CountDownLatch(1);
        transferObserver =
                transferUtility.upload(
                        "pr-" + tempFile.getName(),
                        tempFile);

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

                if (TransferState.COMPLETED == state) {
                    // Handle a completed upload.
                    Log.i(LOG_TAG, "Upload Successful");
                    countDownLatch.countDown();
                }
            }

            @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) {
                Log.e(LOG_TAG, "Error uploading", ex);
                assertTrue("Upload failed with exception: " + ex.getMessage(), false);
            }
        };
        transferObserver.setTransferListener(transferListener);

        waitUntilStateReached(TransferState.IN_PROGRESS, 5000);
        transferUtility.pause(transferObserver.getId());
        waitUntilStateReached(TransferState.PAUSED, 5000);

        Log.d(LOG_TAG, "Progress after paused: Transferred = " +
                transferObserver.getBytesTransferred() +
                "; Total = " +
                transferObserver.getBytesTotal());

        TransferObserver observerAfterResume = transferUtility.resume(transferObserver.getId());
        observerAfterResume.setTransferListener(transferListener);
        waitUntilStateReached(TransferState.IN_PROGRESS, 5000);

        try {
            countDownLatch.await();
        } catch (InterruptedException ie) {
            ie.printStackTrace();
        }

        transferObserver.refresh();
        assertEquals(TransferState.COMPLETED, transferObserver.getState());
        assertTrue(sS3Client.doesObjectExist(BUCKET_NAME, "pr-" + tempFile.getName()));

        Log.d(LOG_TAG, "testListener_Upload_PauseResume end");
    }

Here are the logs from the test:

01-25 11:49:00.952 8683-8683/? I/zygote: Not late-enabling -Xcheck:jni (already on)
01-25 11:49:00.962 8683-8683/? W/zygote: Unexpected CPU variant for X86 using defaults: x86
01-25 11:49:00.975 8683-8683/com.amazonaws.s3transferutilitysample I/zygote: The ClassLoaderContext is a special shared library.
01-25 11:49:00.976 8683-8683/com.amazonaws.s3transferutilitysample I/zygote: The ClassLoaderContext is a special shared library.
01-25 11:49:00.976 8683-8683/com.amazonaws.s3transferutilitysample W/zygote: ClassLoaderContext classpath element mismatch for position 0. expected=/system/framework/android.test.mock.jar, found=/system/framework/android.test.runner.jar (PCL[/system/framework/android.test.mock.jar*1065265343:/system/framework/android.test.runner.jar*1742119008] | PCL[/system/framework/android.test.runner.jar*1742119008:/system/framework/android.test.mock.jar*1065265343])
    Found duplicate classes, falling back to extracting from APK : /data/app/com.amazonaws.s3transferutilitysample.test-MWEfNOfBVQw0KaXEUe7RTw==/base.apk
    NOTE: This wastes RAM and hurts startup performance.
    Found duplicated class when checking oat files: 'Ljunit/runner/BaseTestRunner;' in /data/app/com.amazonaws.s3transferutilitysample.test-MWEfNOfBVQw0KaXEUe7RTw==/base.apk and /system/framework/android.test.runner.jar
01-25 11:49:01.002 8683-8683/com.amazonaws.s3transferutilitysample W/zygote: ClassLoaderContext classpath size mismatch for position 0. expected=0, found=3 (PCL[] | PCL[/system/framework/android.test.runner.jar*1742119008:/system/framework/android.test.mock.jar*1065265343:/data/app/com.amazonaws.s3transferutilitysample.test-MWEfNOfBVQw0KaXEUe7RTw==/base.apk*4162428444])
01-25 11:49:01.010 8683-8683/com.amazonaws.s3transferutilitysample W/System: ClassLoader referenced unknown path: 
01-25 11:49:01.020 8683-8683/com.amazonaws.s3transferutilitysample I/MonitoringInstr: Instrumentation started on process com.amazonaws.s3transferutilitysample
01-25 11:49:01.021 8683-8683/com.amazonaws.s3transferutilitysample I/MonitoringInstr: Setting context classloader to 'dalvik.system.PathClassLoader[DexPathList[[zip file "/system/framework/android.test.runner.jar", zip file "/system/framework/android.test.mock.jar", zip file "/data/app/com.amazonaws.s3transferutilitysample.test-MWEfNOfBVQw0KaXEUe7RTw==/base.apk", zip file "/data/app/com.amazonaws.s3transferutilitysample-LCJbVruoB5CwH_mRqzwCBw==/base.apk"],nativeLibraryDirectories=[/data/app/com.amazonaws.s3transferutilitysample.test-MWEfNOfBVQw0KaXEUe7RTw==/lib/x86, /data/app/com.amazonaws.s3transferutilitysample-LCJbVruoB5CwH_mRqzwCBw==/lib/x86, /system/lib, /vendor/lib]]]', Original: 'dalvik.system.PathClassLoader[DexPathList[[zip file "/system/framework/android.test.runner.jar", zip file "/system/framework/android.test.mock.jar", zip file "/data/app/com.amazonaws.s3transferutilitysample.test-MWEfNOfBVQw0KaXEUe7RTw==/base.apk", zip file "/data/app/com.amazonaws.s3transferutilitysample-LCJbVruoB5CwH_mRqzwCBw==/base.apk"],nativeLibraryDirectories=[/data/app/com.amazonaws.s3transferutilitysample.test-MWEfNOfBVQw0KaXEUe7RTw==/lib/x86, /data/app/com.amazonaws.s3transferutilitysample-LCJbVruoB5CwH_mRqzwCBw==/lib/x86, /system/lib, /vendor/lib]]]'
01-25 11:49:01.041 8683-8683/com.amazonaws.s3transferutilitysample D/OpenGLRenderer: HWUI GL Pipeline
01-25 11:49:01.046 8683-8683/com.amazonaws.s3transferutilitysample I/MonitoringInstr: No JSBridge.
01-25 11:49:01.049 8683-8683/com.amazonaws.s3transferutilitysample I/TransferService: Starting Transfer Service to listen for network connectivity changes.
01-25 11:49:01.055 8683-8683/com.amazonaws.s3transferutilitysample I/TransferService: Registering the network receiver
01-25 11:49:01.058 8683-8683/com.amazonaws.s3transferutilitysample I/TransferService: Putting the service in Foreground state.
01-25 11:49:01.095 8683-8683/com.amazonaws.s3transferutilitysample I/nsferNetworkLossHandler: Network connectivity changed detected.
    Network connected: true
01-25 11:49:01.097 8683-8698/com.amazonaws.s3transferutilitysample I/MonitoringInstr: Setting context classloader to 'dalvik.system.PathClassLoader[DexPathList[[zip file "/system/framework/android.test.runner.jar", zip file "/system/framework/android.test.mock.jar", zip file "/data/app/com.amazonaws.s3transferutilitysample.test-MWEfNOfBVQw0KaXEUe7RTw==/base.apk", zip file "/data/app/com.amazonaws.s3transferutilitysample-LCJbVruoB5CwH_mRqzwCBw==/base.apk"],nativeLibraryDirectories=[/data/app/com.amazonaws.s3transferutilitysample.test-MWEfNOfBVQw0KaXEUe7RTw==/lib/x86, /data/app/com.amazonaws.s3transferutilitysample-LCJbVruoB5CwH_mRqzwCBw==/lib/x86, /system/lib, /vendor/lib]]]', Original: 'dalvik.system.PathClassLoader[DexPathList[[zip file "/system/framework/android.test.runner.jar", zip file "/system/framework/android.test.mock.jar", zip file "/data/app/com.amazonaws.s3transferutilitysample.test-MWEfNOfBVQw0KaXEUe7RTw==/base.apk", zip file "/data/app/com.amazonaws.s3transferutilitysample-LCJbVruoB5CwH_mRqzwCBw==/base.apk"],nativeLibraryDirectories=[/data/app/com.amazonaws.s3transferutilitysample.test-MWEfNOfBVQw0KaXEUe7RTw==/lib/x86, /data/app/com.amazonaws.s3transferutilitysample-LCJbVruoB5CwH_mRqzwCBw==/lib/x86, /system/lib, /vendor/lib]]]'
01-25 11:49:01.141 8683-8698/com.amazonaws.s3transferutilitysample I/UsageTrackerFacilitator: Usage tracking enabled
01-25 11:49:01.195 8683-8698/com.amazonaws.s3transferutilitysample D/TestExecutor: Adding listener android.support.test.internal.runner.listener.LogRunListener
    Adding listener android.support.test.internal.runner.listener.InstrumentationResultPrinter
    Adding listener android.support.test.internal.runner.listener.ActivityFinisherRunListener
01-25 11:49:01.204 8683-8698/com.amazonaws.s3transferutilitysample I/TestRunner: run started: 1 tests
01-25 11:49:01.266 8683-8698/com.amazonaws.s3transferutilitysample D/CognitoCachingCredentialsProvider: Loading credentials from SharedPreferences
01-25 11:49:01.315 8683-8683/com.amazonaws.s3transferutilitysample E/TransferService: No notification is passed in the intent. Unable to transition to foreground.
01-25 11:49:01.322 8683-8698/com.amazonaws.s3transferutilitysample I/TestRunner: started: testListener_Upload_PauseResume(com.amazonaws.s3transferutilitysample.ProgressReportingInstrumentedTest)
01-25 11:49:01.334 8683-8683/com.amazonaws.s3transferutilitysample I/MonitoringInstr: Activities that are still in CREATED to STOPPED: 0
01-25 11:49:01.335 8683-8698/com.amazonaws.s3transferutilitysample D/TransferUtilityInstrumentedTest: testListener_Upload_PauseResume begin
01-25 11:49:01.545 8683-8698/com.amazonaws.s3transferutilitysample D/TransferUtilityInstrumentedTest: Checking for state = IN_PROGRESS; Sleeping for 2000 ms
01-25 11:49:01.561 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: onStateChanged = IN_PROGRESS
01-25 11:49:01.564 8683-8711/com.amazonaws.s3transferutilitysample I/TransferStatusUpdater: Creating a new progress listener for transfer: 173
01-25 11:49:01.597 8683-8711/com.amazonaws.s3transferutilitysample I/AmazonS3Client: Key: pr-junit289454320914146642.tmp; Request: PUT https://tu-sample.s3.amazonaws.com /pr-junit289454320914146642.tmp 
01-25 11:49:01.606 8683-8712/com.amazonaws.s3transferutilitysample I/TransferStatusUpdater: Current: 0; New: 0
01-25 11:49:01.616 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: ID:173 bytesCurrent: 0 bytesTotal: 4194304 0%
01-25 11:49:01.617 8683-8711/com.amazonaws.s3transferutilitysample D/NetworkSecurityConfig: No Network Security Config specified, using platform default
01-25 11:49:01.913 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 131072; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:01.923 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 262144; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:01.930 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 393216; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:02.353 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 524288; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:02.569 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 655360; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:02.785 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 786432; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:02.790 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 917504; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:02.799 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 1048576; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:02.803 8683-8712/com.amazonaws.s3transferutilitysample I/TransferStatusUpdater: Current: 0; New: 1048576
01-25 11:49:02.806 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 131072; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:02.815 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: ID:173 bytesCurrent: 1048576 bytesTotal: 4194304 25%
01-25 11:49:03.029 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 262144; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.056 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 393216; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.075 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 524288; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.093 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 655360; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.111 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 786432; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.139 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 917504; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.161 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 1048576; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.162 8683-8712/com.amazonaws.s3transferutilitysample I/TransferStatusUpdater: Current: 1048576; New: 1048576
01-25 11:49:03.171 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: ID:173 bytesCurrent: 2097152 bytesTotal: 4194304 50%
01-25 11:49:03.203 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 131072; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.220 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 262144; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.243 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 393216; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.261 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 524288; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.281 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 655360; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.297 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 786432; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.313 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 917504; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.330 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 1048576; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.331 8683-8712/com.amazonaws.s3transferutilitysample I/TransferStatusUpdater: Current: 2097152; New: 1048576
01-25 11:49:03.348 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: ID:173 bytesCurrent: 3145728 bytesTotal: 4194304 75%
01-25 11:49:03.359 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 131072; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.379 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 262144; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.392 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 393216; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.396 8683-8711/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 524288; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:03.560 8683-8698/com.amazonaws.s3transferutilitysample D/TransferUtilityInstrumentedTest: Checking for state = PAUSED; Sleeping for 2000 ms
01-25 11:49:03.560 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: onStateChanged = PAUSED
01-25 11:49:03.613 8683-8712/com.amazonaws.s3transferutilitysample I/TransferStatusUpdater: Current: 3145728; New: 0
01-25 11:49:03.613 8683-8711/com.amazonaws.s3transferutilitysample E/UploadTask: Single-part Upload transfer 173 is interrupted by user: 
01-25 11:49:03.619 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: ID:173 bytesCurrent: 3145728 bytesTotal: 4194304 75%
01-25 11:49:03.620 8683-8712/com.amazonaws.s3transferutilitysample I/TransferStatusUpdater: Current: 3145728; New: 524288
01-25 11:49:03.626 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: ID:173 bytesCurrent: 3670016 bytesTotal: 4194304 87%
01-25 11:49:05.564 8683-8698/com.amazonaws.s3transferutilitysample D/TransferUtilityInstrumentedTest: Progress after paused: Transferred = 3670016; Total = 4194304
01-25 11:49:05.566 8683-8698/com.amazonaws.s3transferutilitysample D/TransferUtilityInstrumentedTest: Checking for state = IN_PROGRESS; Sleeping for 2000 ms
01-25 11:49:05.572 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: onStateChanged = IN_PROGRESS
01-25 11:49:05.573 8683-8716/com.amazonaws.s3transferutilitysample I/TransferStatusUpdater: Creating a new progress listener for transfer: 173
01-25 11:49:05.585 8683-8716/com.amazonaws.s3transferutilitysample I/AmazonS3Client: Key: pr-junit289454320914146642.tmp; Request: PUT https://tu-sample.s3.amazonaws.com /pr-junit289454320914146642.tmp 
01-25 11:49:05.586 8683-8712/com.amazonaws.s3transferutilitysample I/TransferStatusUpdater: Current: 0; New: 0
01-25 11:49:05.592 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: ID:173 bytesCurrent: 3670016 bytesTotal: 4194304 87%
01-25 11:49:05.863 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 131072; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:05.877 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 262144; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:05.880 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 393216; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:06.516 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 524288; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:06.537 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 655360; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:06.777 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 786432; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:06.789 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 917504; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:06.795 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 1048576; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:06.795 8683-8712/com.amazonaws.s3transferutilitysample I/TransferStatusUpdater: Current: 0; New: 1048576
01-25 11:49:06.803 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: ID:173 bytesCurrent: 4718592 bytesTotal: 4194304 112%
01-25 11:49:07.015 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 131072; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.032 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 262144; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.048 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 393216; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.066 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 524288; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.076 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 655360; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.094 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 786432; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.114 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 917504; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.132 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 1048576; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.133 8683-8712/com.amazonaws.s3transferutilitysample I/TransferStatusUpdater: Current: 1048576; New: 1048576
01-25 11:49:07.140 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: ID:173 bytesCurrent: 5767168 bytesTotal: 4194304 137%
01-25 11:49:07.143 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 131072; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.373 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 262144; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.389 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 393216; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.405 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 524288; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.421 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 655360; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.438 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 786432; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.455 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 917504; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.478 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 1048576; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.479 8683-8712/com.amazonaws.s3transferutilitysample I/TransferStatusUpdater: Current: 2097152; New: 1048576
01-25 11:49:07.488 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: ID:173 bytesCurrent: 6815744 bytesTotal: 4194304 162%
01-25 11:49:07.501 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 131072; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.519 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 262144; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.538 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 393216; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.553 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 524288; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.557 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 655360; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.790 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 786432; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.807 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 917504; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.817 8683-8716/com.amazonaws.s3transferutilitysample I/essReportingInputStream: unnotifiedByteCount = 1048576; bytesRead = 131072; notificationThreshold = 1048576
01-25 11:49:07.819 8683-8712/com.amazonaws.s3transferutilitysample I/TransferStatusUpdater: Current: 3145728; New: 1048576
01-25 11:49:07.827 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: ID:173 bytesCurrent: 7864320 bytesTotal: 4194304 187%
01-25 11:49:08.338 8683-8715/com.amazonaws.s3transferutilitysample W/OkHttpClient: A connection to https://tu-sample.s3.amazonaws.com/ was leaked. Did you forget to close a response body?
01-25 11:49:08.342 8683-8712/com.amazonaws.s3transferutilitysample I/TransferStatusUpdater: Current: 4194304; New: 0
01-25 11:49:08.343 8683-8688/com.amazonaws.s3transferutilitysample I/zygote: Do partial code cache collection, code=30KB, data=19KB
    After code cache collection, code=29KB, data=19KB
    Increasing code cache capacity to 128KB
01-25 11:49:08.354 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: ID:173 bytesCurrent: 4194304 bytesTotal: 4194304 100%
01-25 11:49:08.365 8683-8683/com.amazonaws.s3transferutilitysample I/TransferUtilityInstrumentedTest: onStateChanged = COMPLETED
    Upload Successful
01-25 11:49:08.366 8683-8698/com.amazonaws.s3transferutilitysample I/AmazonS3Client: Key: pr-junit289454320914146642.tmp; Request: HEAD https://tu-sample.s3.amazonaws.com /pr-junit289454320914146642.tmp 
01-25 11:49:08.539 8683-8698/com.amazonaws.s3transferutilitysample D/TransferUtilityInstrumentedTest: testListener_Upload_PauseResume end
01-25 11:49:08.542 8683-8698/com.amazonaws.s3transferutilitysample I/TestRunner: finished: testListener_Upload_PauseResume(com.amazonaws.s3transferutilitysample.ProgressReportingInstrumentedTest)
01-25 11:49:08.545 8683-8683/com.amazonaws.s3transferutilitysample I/MonitoringInstr: Activities that are still in CREATED to STOPPED: 0
01-25 11:49:08.547 8683-8698/com.amazonaws.s3transferutilitysample I/TestRunner: run finished: 1 tests, 0 failed, 0 ignored
01-25 11:49:08.890 8683-8683/com.amazonaws.s3transferutilitysample I/MonitoringInstr: Activities that are still in CREATED to STOPPED: 0
01-25 11:49:08.890 8683-8698/com.amazonaws.s3transferutilitysample I/MonitoringInstr: waitForActivitiesToComplete() took: 0ms

I am able to get progress and state updates before pause and after resume successfully. Can you let me know if I'm missing something in the test?

This test uses single-part upload. What is the size of the file you are uploading?

@mutablealligator mutablealligator added the pending-community-response Issue is pending response from the issue requestor label Jan 25, 2019
@RuiEEE
Copy link
Author

RuiEEE commented Jan 25, 2019

I'll try to replicate in a different project, I'm using notification to trigger pause/resume. Files are usually multipart. They go from 10mb to 80mb, its video files.

@mutablealligator
Copy link
Contributor

@RuiEEE Thank you for the quick response. As you can see, I have attached the listener to observerAfterResume object to get the updates. You can also query the observerAfterResume by calling refresh() followed by getState() and getBytesTransferred(). Both methods would work. Let me know how your testing goes.

@mutablealligator
Copy link
Contributor

mutablealligator commented Feb 4, 2019

@RuiEEE 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.
  1. Fix the progress reporting to not go beyond 100% and reset when a part failed.

See 2.11.1 for more information.

@RuiEEE
Copy link
Author

RuiEEE commented Feb 4, 2019

I've checked the notes on the new 2.11.1 version, I ran some manual tests last week and I was able to get the progress on the observer, I must have been doing something wrong before, but I kept getting a state failed after pausing(with exception thrown and all).

I've also noticed that after resuming the progress would go backwards a little, for example, I paused at 78% and when resumed, it would go back to 50% and resume from there. It seemed that the whole piece for the multipart was being dropped and then pick on the last part, I'm not sure I'm being clear.

Regardless, on the next couple of days(tomorrow most likely) I'll update the SDK and get back to you.

Thanks for being on top of it!

@mutablealligator
Copy link
Contributor

@RuiEEE Thank you for the quick response. I have updated the comment with detailed root cause analysis and fix description. What you observed is accurate. My fix will make sure the progress does not go backwards and does not go beyond 100%. I will wait for your feedback on the fix.

@mutablealligator
Copy link
Contributor

@RuiEEE Just checking to see how your progress on testing and if you have any feedback to share.

@mutablealligator mutablealligator added closing soon Issue will auto-close if there is no additional activity within 7 days. and removed pending-community-response Issue is pending response from the issue requestor labels Feb 13, 2019
@RuiEEE
Copy link
Author

RuiEEE commented Feb 19, 2019

Hey. Sorry for the late response, I got caught up in other stuff and because there was no major issue I didn't get back to you.

I've noticed that whenever I pause I get some of these errors. Maybe it's fine and expected:

com.amazonaws.AbortedException: 
        at com.amazonaws.internal.SdkInputStream.abortIfNeeded(SdkInputStream.java:59)
        at com.amazonaws.auth.AwsChunkedEncodingInputStream.read(AwsChunkedEncodingInputStream.java:159)
        at java.io.InputStream.read(InputStream.java:101)
        at com.amazonaws.http.UrlHttpClient.write(UrlHttpClient.java:244)
        at com.amazonaws.http.UrlHttpClient.writeContentToConnection(UrlHttpClient.java:171)
        at com.amazonaws.http.UrlHttpClient.execute(UrlHttpClient.java:75)
        at com.amazonaws.http.AmazonHttpClient.executeHelper(AmazonHttpClient.java:371)
        at com.amazonaws.http.AmazonHttpClient.execute(AmazonHttpClient.java:212)
        at com.amazonaws.services.s3.AmazonS3Client.invoke(AmazonS3Client.java:4655)
        at com.amazonaws.services.s3.AmazonS3Client.uploadPart(AmazonS3Client.java:3672)
        at com.amazonaws.mobileconnectors.s3.transferutility.UploadPartTask.call(UploadPartTask.java:60)
        at com.amazonaws.mobileconnectors.s3.transferutility.UploadPartTask.call(UploadPartTask.java:30)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        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)

One other thing, I was setting a transferlistener everytime I was resuming the transfer(mostly because I'm running the upload on a service and wanted to make sure a transferlistener was attached) and for some reason it was attaching multiple transferlisteners instead of replacing the previous one. I know this because I was getting multiple callbacks on the stateChanged:

This is after pausing and resuming 3 times:
2019-02-19 20:15:53.081 18201-18201 D/Amazon: State Changed to PAUSED from id 70
2019-02-19 20:15:53.115 18201-18201 D/Amazon: State Changed to PAUSED from id 70
2019-02-19 20:15:53.147 18201-18201 D/Amazon: State Changed to PAUSED from id 70

from the function onStateChange

override fun onStateChanged(id: Int, state: TransferState) {
     Log.d("Amazon", "State Changed to $state from id $id")
}

Right now, I'm just setting one TransferListener whenever I start uploading and it's working as intended(it was not back in 2.10.x, and thats why I was setting a transferlistener everytime I resumed a transfer).

@stale stale bot removed the closing soon Issue will auto-close if there is no additional activity within 7 days. label Feb 19, 2019
@mutablealligator
Copy link
Contributor

@RuiEEE Thank you for the feedback. The exception is logged in the LogCat because when the SDK tries to pause the transfer, we kill the thread that aborts the operation in progress. However I expect you don't see an app crash and you get the state change update to PAUSED.

Also, you're right that you only need one listener and we have identified and fixed the problem with managing the listeners.

If you do not have any other questions, I can go ahead and close the issue. Otherwise, let me know how I can help you.

@frankmuellr frankmuellr added the pending-community-response Issue is pending response from the issue requestor label Feb 19, 2019
@RuiEEE
Copy link
Author

RuiEEE commented Feb 19, 2019

@kvasukib Yeah, the app doesn't crash, just fills the log with those exceptions, I was just making sure it is intended.

Cool. No, I'm good. Thanks a lot for your fast response and assistance!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
pending-community-response Issue is pending response from the issue requestor question General question s3 Issues with the AWS Android SDK for Simple Storage Service (S3).
Projects
None yet
Development

No branches or pull requests

3 participants