Amplify-android: Initial sync during DataStore initialization failed.

Created on 4 Sep 2020 · 13Comments · Source: aws-amplify/amplify-android

If a user runs the app first time before sign-in then next error has occurred:

09-04 20:31:33.707 9423-9479/com.sensodix E/amplify:aws-datastore: Error encountered in the DataStore.
    AmplifyException {message=Initial cloud sync failed., cause=AmplifyException {message=Failure performing sync query to AppSync., cause=AmplifyException {message=Could not retrieve the response body from the returned JSON, cause=java.io.IOException: Failed to retrieve Cognito User Pools token., recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Check your internet connection.}
        at com.amplifyframework.datastore.syncengine.SyncProcessor.lambda$createHydrationTask$8$SyncProcessor(SyncProcessor.java:161)
        at com.amplifyframework.datastore.syncengine.-$$Lambda$SyncProcessor$-2QSLtdRgTPoxsmAWkh9ybwd5JA.accept(lambda)
        at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek$CompletableObserverImplementation.onError(CompletablePeek.java:88)
        at io.reactivex.rxjava3.internal.operators.single.SingleFlatMapCompletable$FlatMapCompletableObserver.onError(SingleFlatMapCompletable.java:97)
        at io.reactivex.rxjava3.internal.operators.single.SingleFlatMap$SingleFlatMapCallback$FlatMapSingleObserver.onError(SingleFlatMap.java:117)
        at io.reactivex.rxjava3.internal.operators.completable.CompletableToSingle$ToSingle.onError(CompletableToSingle.java:73)
        at io.reactivex.rxjava3.internal.util.AtomicThrowable.tryTerminateConsumer(AtomicThrowable.java:156)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapCompletableCompletable$FlatMapCompletableMainSubscriber.onError(FlowableFlatMapCompletableCompletable.java:149)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableTake$TakeSubscriber.onError(FlowableTake.java:86)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlattenIterable$FlattenIterableSubscriber.checkTerminated(FlowableFlattenIterable.java:406)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlattenIterable$FlattenIterableSubscriber.drain(FlowableFlattenIterable.java:266)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlattenIterable$FlattenIterableSubscriber.onError(FlowableFlattenIterable.java:192)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableDoOnEach$DoOnEachSubscriber.onError(FlowableDoOnEach.java:111)
        at io.reactivex.rxjava3.internal.util.AtomicThrowable.tryTerminateConsumer(AtomicThrowable.java:94)
        at io.reactivex.rxjava3.internal.util.HalfSerializer.onError(HalfSerializer.java:67)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableConcatMap$ConcatMapImmediate.innerError(FlowableConcatMap.java:210)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableConcatMap$ConcatMapInner.onError(FlowableConcatMap.java:571)
        at io.reactivex.rxjava3.internal.operators.single.SingleToFlowable$SingleToFlowableObserver.onError(SingleToFlowable.java:67)
        at io.reactivex.rxjava3.internal.operators.single.SingleCreate$Emitter.tryOnError(SingleCreate.java:95)
        at io.reactivex.rxjava3.internal.operators.single.SingleCreate$Emitter.onError(SingleCreate.java:81)
        at com.amplifyframework.datastore.syncengine.-$$Lambda$PymunRoF4O3jbMDeD82w6kHUXIM.accept(lambda)
        at com.amplifyframework.datastore.appsync.AppSyncClient.lambda$sync$1(AppSyncClient.java:98)
        at com.amplifyframework.datastore.appsync.-$$Lambda$AppSyncClient$suvEma05s-p8v-66iE4cswLKYac.accept(lambda)
        at com.amplifyframework.api.aws.AppSyncGraphQLOperation$OkHttpCallback.onFailure(AppSyncGraphQLOperation.java:150)
        at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:525)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
        at java.lang.Thread.run(Thread.java:818)
     Caused by: AmplifyException {message=Failure performing sync query to AppSync., cause=AmplifyException {message=Could not retrieve the response body from the returned JSON, cause=java.io.IOException: Failed to retrieve Cognito User Pools token., recoverySuggestion=Sorry, we don't have a suggest
09-04 20:31:33.708 9423-9467/com.sensodix E/amplify:aws-datastore: Failure encountered while attempting to start API sync.
    AmplifyException {message=Initial sync during DataStore initialization failed., cause=java.lang.RuntimeException: AmplifyException {message=Failure performing sync query to AppSync., cause=AmplifyException {message=Could not retrieve the response body from the returned JSON, cause=java.io.IOException: Failed to retrieve Cognito User Pools token., recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=There is a possibility that there is a bug if this error persists. Please take a look at 
    https://github.com/aws-amplify/amplify-android/issues to see if there are any existing issues that 
    match your scenario, and file an issue with the details of the bug if there isn't.}
        at com.amplifyframework.datastore.syncengine.Orchestrator.lambda$startApiSync$4$Orchestrator(Orchestrator.java:279)
        at com.amplifyframework.datastore.syncengine.-$$Lambda$Orchestrator$LZNjaZMRgCaJlw-lrjSVwfuZjK0.subscribe(lambda)
        at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate.subscribeActual(CompletableCreate.java:40)
        at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
        at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
        at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
        at io.reactivex.rxjava3.internal.operators.completable.CompletableOnErrorComplete.subscribeActual(CompletableOnErrorComplete.java:35)
        at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
        at io.reactivex.rxjava3.internal.operators.completable.CompletableSubscribeOn$SubscribeOnObserver.run(CompletableSubscribeOn.java:64)
        at io.reactivex.rxjava3.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:41)
        at io.reactivex.rxjava3.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:28)
        at java.util.concurrent.FutureTask.run(FutureTask.java:237)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:152)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:265)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
        at java.lang.Thread.run(Thread.java:818)
     Caused by: java.lang.RuntimeException: AmplifyException {message=Failure performing sync query to AppSync., cause=AmplifyException {message=Could not retrieve the response body from the returned JSON, cause=java.io.IOException: Failed to retrieve Cognito User Pools token., recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}
        at io.reactivex.rxjava3.internal.util.ExceptionHelper.wrapOrThrow(ExceptionHelper.java:46)
        at io.reactivex.rxjava3.internal.observers.BlockingMultiObserver.blockingAwait(BlockingMultiObserver.java:145)
        at io.reactivex.rxjava3.core.Completable.blockingAwait(Completable.java:1490)
        at com.amplifyframework.datastore.syncengine.Orchestrator.lambda$startApiSync$4$Orchestrator(Orchestrator.java:276)
        at com.amplifyframework.datastore.syncengine.-$$Lambda$Orchestrator$LZNjaZMRgCaJlw-lrjSVwfuZjK0.subscribe(lambda) 
        at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate.subscribeActual(CompletableCreate.java:40) 
        at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850) 
        at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51) 
        at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850) 
        at io.reactivex.rxjava3.internal.operators.completable.CompletableOnErrorComplete.subscribeActual(CompletableOnErrorComplete.java:35) 
        at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850) 
        at io.reactivex.rxjava3.internal.operators.completable.CompletableSubscribeOn$SubscribeOnObserver.run(CompletableSubscribeOn.java:64) 
        at io.reactivex.rxjava3.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:41) 
        at io.reactivex.rxjava3.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:28) 
        at java.util.concurrent.FutureTask.run(FutureTask.java:237) 
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:152) 
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:265) 
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112) 
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587) 
        at java.lang.Thread.run(Thread.java:818) 
     Caused by: AmplifyException {message=Failure performing sync query to AppSync., cause=AmplifyException {message=Could not retrieve the response body from the returned JSON, cause=java.io.IOException: Failed to retrieve Cognito User Pools token., recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}
        at com.amplifyframework.datastore.appsync.AppSyncClient.lambda$sync$1(AppSyncClient.java:98)
        at com.amplifyframework.datastore.appsync.-$$Lambda$AppSyncClient$suvEma05s-p8v-66iE4cswLKYac.accept(lambda)
        at com.amplifyframework.api.aws.AppSyncGraphQLOperation$OkHttpCallback.onFailure(AppSyn

My environment:
Amplify Framework 1.3.1
Addroid API 22, 29

DataStore Usage Question

Source

abogatov

Most helpful comment

Should I unsubscribe after receiving SYNC_QUERIES_READY event?

You shouldn't need to. It should only be called once.

Currently, to avoid duplicate handling of the READY event I do the unsubscribe call as soon I receive the event (without it if you try to call this method again then the event will be generated twice and so on). And I have to implement this for each call to the DataStore.

This is a bug :). I fixed it yesterday (https://github.com/aws-amplify/amplify-android/pull/952), and it will go out in our next release.

richardmcclellan on 4 Nov 2020

👍2

All 13 comments

Hi @abogatov, currently, DataStore is initialized (subscriptions enabled, sync queries started, etc) as soon as Amplify.configure() gets called, which is usually right when your app starts. If your models are protected with the @auth directive, this initialization fails if the end user is not signed in yet, as you've reported. This is a known issue that we are working on.

As a workaround for now, you can ignore this exception, and just call DataStore.query (or any other DataStore method) after you are signed in, and DataStore will automatically reinitialize itself.

richardmcclellan on 8 Sep 2020

Hi @richardmcclellan, thank you for the answer.
Unfortunately after login the call of DataStore.query returns empty data. But if I close the app and try the call of DataStore.query again then I will see data in the response.
Is it due to that it takes time for the synchronization to be performed? But then is there any way how we can determine that the initialization process in progress and we should wait before call DataStore.query? Could you please give me some advise how solve the problem.

abogatov on 9 Sep 2020

Hi @abogatov, you can listen for the READY event on the DATASTORE Hub channel, and then do your query, like this:

        Amplify.Hub.subscribe(HubChannel.DATASTORE, 
                hubEvent -> DataStoreChannelEventName.READY.equals(hubEvent.getName()), 
                hubEvent -> Amplify.DataStore.query(Todo.class, result -> { }, error -> { }));

The READY event was just added in the release last week, so make sure you are using the latest version of Amplify (1.3.1)

richardmcclellan on 9 Sep 2020

Hi @richardmcclellan, thank you for the example. Yes I use latest version (1.3.1)
I've tried it but no success. I have next code:

val result = MutableLiveData<Resource<Zones>>(Resource.loading())
val subscriptionToken = Amplify.Hub.subscribe(HubChannel.DATASTORE, { hubEvent ->
    Log.i("Sensodix", "DataStore event: " + hubEvent.name)
    DataStoreChannelEventName.READY.toString() == hubEvent.name
}
) {
    Amplify.DataStore.query(any
        com.amplifyframework.datastore.generated.model.Zone::class.java,
        { response ->
            result.postValue(Resource.success(Zones.map(response)))
        },
        { error ->
            result.postValue(Resource.error(error.cause?.message ?: Constants.UNEXPECTED_ERROR_MSG, error.cause))
        }
    )
}

(Also I have a subscribe to the HubChannel.AUTH channel.)

Steps that I did:

Uninstall my app
Install and run my app (I am logging the error I described above).
Next I login and run my code that above
Content of the logcat:

09-09 16:29:43.735 8906-8906/com.sensodix I/Sensodix: Initialized Amplify
09-09 16:30:53.377 8906-9023/com.sensodix I/Sensodix: Auth just became signed in.

So there are no any messages in the HubChannel.DATASTORE channel.

Close my app and re-run. After that I start to receive messages from the DATASTORE channel

09-09 16:52:07.814 9055-9055/com.sensodix I/Sensodix: Initialized Amplify
09-09 16:52:13.875 9055-9098/com.sensodix I/Sensodix: DataStore event: subscriptionsEstablished
09-09 16:52:13.884 9055-9098/com.sensodix I/Sensodix: DataStore event: syncQueriesStarted
09-09 16:52:14.801 9055-9098/com.sensodix I/Sensodix: DataStore event: networkStatus
09-09 16:52:16.288 9055-9098/com.sensodix I/Sensodix: DataStore event: modelSynced
09-09 16:52:17.289 9055-9098/com.sensodix I/Sensodix: DataStore event: modelSynced
09-09 16:52:17.296 9055-9098/com.sensodix I/Sensodix: DataStore event: syncQueriesReady
09-09 16:52:27.305 9055-9098/com.sensodix I/Sensodix: DataStore event: ready

Probably after the initialize error of the DataStore it not re-initialize after login.
Is there any way to re-initialize the DataStore after login?

abogatov on 9 Sep 2020

Hi @abogatov, I've taken a closer look at this. As I mentioned, DataStore initialization is triggered on any interaction with the DataStore, if a previous initialization failed. However, I've just realized it doesn't wait until the initialization is complete before returning. So, for now, here's what you can do:

Sign in
Call DataStore.query to reinitialize the DataStore, but ignore the results
Wait for the READY Hub event.
Call DataStore.query again to get actual results

Here's some code for doing this:

Amplify.DataStore.query(Todo.class, result -> { /* ignore this result */ }, error -> { });        
Amplify.Hub.subscribe(HubChannel.DATASTORE, 
    hubEvent -> DataStoreChannelEventName.READY.toString().equals(hubEvent.getName()), 
    hubEvent -> Amplify.DataStore.query(Todo.class, result -> { /* expect the actual results here */ }, error -> { })
);

In the future, we'll consider ways to improve this, so there aren't so many steps required.

richardmcclellan on 10 Sep 2020

Hi @richardmcclellan, thank you for the support.
It a bit illogical. Before retrieving some data from DataStore we should run with the same query. And after getting READY event we should not forget to unsubscribe (otherwise we will get the READY event cyclically), it complicates things.
It just can be only as temporarily decision. I hope it will fixed soon.
Should we re-open this ticket because it still seems as issue (to not to forget about this problem)?

abogatov on 11 Sep 2020

Hi @richardmcclellan, I saw that you introduced a new functionality in the DataStore API (1.5.0). Thank you for that. Could you please explain me can the DataStore::start method simplify the above and avoid Amplify.Hub.subscribe to wait READY?

abogatov on 4 Nov 2020

Hi @abogatov,

The biggest change in 1.5.0 is that Amplify.configure() no longer starts the DataStore sync process. This should eliminate the exceptions you reported in this ticket, which were a result of trying to sync data before a user was signed in (hence the java.io.IOException: Failed to retrieve Cognito User Pools token).

Now, there are two ways to start DataStore:

Call any DataStore operation (query, save, delete, or observe). This will start the sync process if it's not already started (this behavior has always been in place)
Call DataStore.start.

Per your previous comment about the READY event firing repeatedly, I just fixed this bug (https://github.com/aws-amplify/amplify-android/pull/952), and it will be available after the next release. For an immediate workaround, listen for the SYNC_QUERIES_READY event instead which is fired as soon as the base sync is completed (it doesn't wait for subscriptions to be established like READY does, but since you just want to query, that should be fine. I'd suggest the following:

// If you're only interested in the remote data:
private void queryForRemoteData() {
    start()
    queryAfterReady()
}

// If you'd like to get the local cached data first, followed by the remote data once it's available:
private void queryForLocalDataThenRemoteData() {
    query()
    queryAfterReady()
}

private void queryAfterReady() {
    Amplify.Hub.subscribe(HubChannel.DATASTORE, 
            hubEvent -> DataStoreChannelEventName.SYNC_QUERIES_READY.toString().equals(hubEvent.getName()), 
            hubEvent -> query())
    );
}

private void start() {
    Amplify.DataStore.start(
        () -> Log.d(TAG, "DataStore has been started.  Subscribe to `SYNC_QUERIES_READY` to know when sync is complete"), 
        error -> Log.e(TAG, "Failure starting DataStore")
    );
}

private void query() {
    Amplify.DataStore.query(Todo.class, 
        result -> { /* Display results on your UI */ }, 
        error -> { }
}

richardmcclellan on 4 Nov 2020

Hi @richardmcclellan, thanks a lot. I'll try your advice. Can I ask quick question:
Should I unsubscribe after receiving SYNC_QUERIES_READY event?
Currently, to avoid duplicate handling of the READY event I do the unsubscribe call as soon I receive the event (without it if you try to call this method again then the event will be generated twice and so on). And I have to implement this for each call to the DataStore.

abogatov on 4 Nov 2020

Should I unsubscribe after receiving SYNC_QUERIES_READY event?

You shouldn't need to. It should only be called once.

Currently, to avoid duplicate handling of the READY event I do the unsubscribe call as soon I receive the event (without it if you try to call this method again then the event will be generated twice and so on). And I have to implement this for each call to the DataStore.

This is a bug :). I fixed it yesterday (https://github.com/aws-amplify/amplify-android/pull/952), and it will go out in our next release.

richardmcclellan on 4 Nov 2020

👍2

Hi @richardmcclellan, I'm still trying to use this functionality. I've upgrade the framework to the latest version 1.6.0 but I have a problem. When I first call the queryForRemoteData it works fine but if I call it second time, no events will be generated and the query method won't called.
Is it expected behavior?

abogatov on 16 Nov 2020

Hi @abogatov, yes, that is expected, although I admit, probably a bit confusing. Here's what I would suggest - keep track of whether the SYNC_QUERIES_READY event has fired, and use that to determine whether you still need to wait for it, or just call query right away:

class MainActivity {
    boolean syncQueriesReady = false

    private void onCreate(savedInstanceState: Bundle) {
        queryForRemoteData()
    }

    private void queryForRemoteData() {
        start();
        if (syncQueriesReady) {
            query();
        } else {
            queryAfterReady();
        }
    }

    private void queryAfterReady() {
        Amplify.Hub.subscribe(HubChannel.DATASTORE, 
                hubEvent -> DataStoreChannelEventName.SYNC_QUERIES_READY.toString().equals(hubEvent.getName()), 
                hubEvent -> {
                    syncQueriesReady = true;
                    query();
                })
        )
    }

    private void start() {
        Amplify.DataStore.start(
            () -> Log.d(TAG, "DataStore has been started.  Subscribe to `SYNC_QUERIES_READY` to know when sync is complete"), 
            error -> Log.e(TAG, "Failure starting DataStore")
        )
    }

    private void query() {
        Amplify.DataStore.query(Todo.class, 
            result -> { /* Display results on your UI */ }, 
            error -> { }
        );
    }
}

richardmcclellan on 16 Nov 2020

hi @richardmcclellan, thank you for your support. I'll try this approach.

abogatov on 17 Nov 2020

🚀1

Was this page helpful?

0 / 5 - 0 ratings