infinite offline mutation

DeMoss15 commented 5 years ago

Bug description Mutation waiting in Persistent Queue for long period of time. Although Internet connection is good enough. Pay attention to logs of mutation in Thread: [1]

Attachments infinit_creat_mutation_log.txt

Environment Lib versions: app sync 2.7.5 cognito identity provider, s3 2.11 mobile client 2.7.4

palpatim commented 5 years ago

@DeMoss15

Thanks for reporting this issue, and sorry you're having trouble. Are you convinced that this issue is actually the same as #95? If so, we should migrate this to a comment on that thread so we can keep the conversation centralized--can you move your information (and the link to your log file) to that thread?

scb01 commented 5 years ago

@DeMoss15

After reviewing the log, it looks like this is a different issue than #95. From my reading of the log, it looks like there are a couple of mutations and a cancellation and there may be a bug in the tracking logic for canceled mutations.

It will be helpful if you can share code snippets around how you are creating the mutations, where they are being canceled etc.

DeMoss15 commented 5 years ago

@cbommas

We are executing one mutation after another. Just like that:

// try to subscribe to notifications
notificationSubscriptionUseCase.buildUseCaseObservable(NotificationSubscriptionUseCase.Params(true))
                .onErrorComplete()
// create user profile
                .andThen(profileRepository.createUserProfile(
                        params.name,
                        params.about,
                        params.street,
                        params.city,
                        params.country,
                        params.avatar,
                        params.background
                )
)

NotificationSubscriptionUseCase just create mutation: SubscribeToNotificatonsMutation.txt

And then we try to create user profile via next mutation (it was executing in Thread: [1] in logs): CreateProfileMutation.txt

That's it. I hope it will be helpfull.

scb01 commented 5 years ago

@DeMoss15

Thanks for attaching the code snippets.

In the log that you posted earlier, I am seeing mutations being cancelled.

 2019-01-18 10:44:36.885 16960-17168/com.moja V/AppSyncOfflineMutationManager: Thread:[3106]: Handling cancellation for mutation [com.moja.SubscribeForNotificationsMutation@11d7822]
 2019-01-18 10:44:36.885 16960-17168/com.moja V/AppSyncOfflineMutationManager: Thread:[3106]: Mutation being canceled is the one currently in progress. Handling it

and

 2019-01-18 10:44:36.893 16960-17168/com.moja V/AppSyncOfflineMutationInterceptor: Dispose called

Both the code snippets that you posted have the following line

    emitter.setDisposable(Disposables.fromAction { awsMutation.cancel() })

It appears that in both the code snippets SubscribeToNotificatonsMutation.txt and CreateProfileMutation.txt, a mutation is being created, enqueued for execution and then canceled. Putting this together with what I am seeing in the logs, the SDK is either canceling the mutation if it the execution is in progress or not even attempting to execute it, which would be the correct behavior as we should not execute a cancelled mutation.

Can you remove the call to cancel in your code and see if that changes the behavior?

DeMoss15 commented 5 years ago

@cbommas

If I understand you correctly: we can't cancel mutations. Although this mutations have such interface. This fix may cause NullPointerExceptions and memory leaks. Because of uncancelled mutation after dispose subscription.

First mutation (SubscribeToNotificationMutation) had been executed correctly. Than it was cancelled and started second mutation (CreateProfileMutation in Thread:[1]). We have a problem with the second one. So I don't understand what's wrong with cancellation?

Bottom line: Yes, if we remove this lines, there will be no more cancellations and everything works fine.

DeMoss15 commented 5 years ago

Second mutation is being executed after reopen application (press button home -> open app again)

scb01 commented 5 years ago

@DeMoss15 Actually, no, that isn't what I am saying ( Apologies if my previous post was not clear on this topic)

Any mutation can be canceled, at any point in time.
Mutations can be in of 4 states ( IDLE, ACTIVE, TERMINATED, CANCELED). IDLE state means that the mutation has been created and is waiting to the executed. ACTIVE means that the mutation is being executed. TERMINATED means the mutation has been completed and CANCELED means that the mutation has been canceled.
Now lets see what happens when you call cancel on a mutation. -- For a mutation in the IDLE state, this will cancel the mutation and set its state to CANCELLED. This mutation will not be executed. If it is in the mutation queue, it will be removed from the queue without being executed. -- For a mutation in the ACTIVE state, the request to cancel will stop any further work from happening on the mutation. Since ACTIVE means that the mutation is currently being executed, where it stops is non-deterministic, based on how much progress the mutation already made. The mutation's state will be set to CANCELLED -- For a mutation in the TERMINATED state, cancel does nothing and is a no-op. -- For a mutation in the CANCELLED state, another cancel request does nothing and is a no-op

As you can see, if you call cancel on a mutation, it will no longer be executed and will be removed from the queue. And in your case, the mutation will not be present ( or waiting) in the persistent queue - the queue will instead be empty.

You can see this in the last few lines of infinit_creat_mutation_log.txt attachment

 2019-01-18 10:44:49.992 16960-17164/com.moja V/AppSyncOfflineMutationManager: Thread:[3102]:Persistent mutations queue is EMPTY!. Will check inMemory Queue next
 2019-01-18 10:44:49.992 16960-17164/com.moja V/AppSyncOfflineMutationManager: Thread:[3102]: In Memory mutations queue was EMPTY!. Nothing to process, exiting

With that said, you don't have to call cancel for each mutation you create. There will not be any null pointer exceptions or memory leaks. When the mutation object goes out of scope and is no longer in the queue, it will be garbage collected. If you are seeing memory leaks, let me know and I will investigate it further on my side.

DeMoss15 commented 5 years ago

@cbommas

I got it. BUT

Why THIS (CreateProfileMutation) mutation wait in queue and wasn't being executed?

2019-01-18 10:44:36.897 16960-16960/com.moja V/S3ObjectManagerImplementation: Thread:[1]: Looking at Key [street] of type [String]
2019-01-18 10:44:36.901 16960-16960/com.moja V/S3ObjectManagerImplementation: Thread:[1]: Looking at Key [city] of type [String]
2019-01-18 10:44:36.904 16960-16960/com.moja V/S3ObjectManagerImplementation: Thread:[1]: Looking at Key [about] of type [String]
2019-01-18 10:44:36.906 16960-16960/com.moja V/S3ObjectManagerImplementation: Thread:[1]: Looking at Key [profileImage] of type [S3FileInput]
2019-01-18 10:44:36.907 16960-16960/com.moja V/S3ObjectManagerImplementation: Thread:[1]: Looking at Key [coverImage] of type [S3FileInput]
2019-01-18 10:44:36.910 16960-16960/com.moja V/PersistentOfflineMutationManager: Thread:[1]:addPersistentMutationObject: Adding mutation[dd328107-6f48-49e3-b0d9-4152ce68060c]: CreateProfileMutation 
    {"query":"mutation CreateProfile($name: String!, $street: String!, $city: String!, $about: String!, $profileImage: S3FileInput!, $coverImage: S3FileInput!) {  createUserProfile(name: $name, street: $street, city: $city, about: $about, profileImage: $profileImage, coverImage: $coverImage) {    __typename    ...UserProfileRemote  }}fragment UserProfileRemote on UserProfile {  __typename  userId  name  street  city  about  profileImage  coverImage  version}","variables":{"name":"Thanks So much for All","street":"Tyu","city":"I Have A Few","about":"I have a few years ago I was in the hospital for a few minutes","profileImage":{"bucket":"moja-backend-dev-user-profile-images","region":"us-east-1","key":"us-east-1:0efc3a57-9bfe-40ae-b366-dd42a13ef4c9/7efd28de-a6b2-4e66-9dcf-a0c2e4918079"},"coverImage":{"bucket":"moja-backend-dev-user-cover-images","region":"us-east-1","key":"us-east-1:0efc3a57-9bfe-40ae-b366-dd42a13ef4c9/57f776f2-e29f-4715-890f-ea8b6a00bb04"}}}
2019-01-18 10:44:36.917 16960-16960/com.moja V/AppSyncOfflineMutationManager: Thread:[1]: Added mutation[dd328107-6f48-49e3-b0d9-4152ce68060c] to Persistent Queue. No S3 Objects found
2019-01-18 10:44:36.917 16960-16960/com.moja V/AppSyncOfflineMutationManager: Thread:[1]: Created both in-memory and persistent records. Now going to signal queue handler.

It wasn't cancelled.

scb01 commented 5 years ago

@DeMoss15 I see - Let me look into this. I think there may be a race condition here between the cancellation request and the next mutation request. Will post back here once I have an update.

ukevgen commented 5 years ago

@palpatim @cbommas H! I'm a @DeMoss15 teammate. I see that this disscusion going into wrong way). So I did some more clean code (removed rx's chain etc.) and added more logs for better understanding what goin on.

And this is start poin for ower calls:

` override fun createProfile() {

    val subscribtionMutation = SubscribeForNotificationsMutation.builder()
            .deviceToken(SharedPrefManager.getInstance()!!.getFcmDeviceToken())
            .osVersion(systemProvider.getOsVersion())
            .appVersion(systemProvider.getAppVersion())
            .build()

    val avatarS3 = DomainRemoteMapper.toRemote(avatar!!)
    val backgroundS3 = DomainRemoteMapper.toRemote(background!!)

    val createProfileMutation = CreateProfileMutation.builder()
            .name(name)
            .about(aboutInfo)
            .street(street)
            .city(city)
            .profileImage(avatarS3)
            .coverImage(backgroundS3)
            .build()

    CompletableCreate(SubscribeToNotificationsObservable(appSyncClient, subscribtionMutation))
            .doOnComplete {
                Log.d("Presenter", "Subscribe to notification mutation was successful!")
            }
            .andThen(
                    CompletableCreate(CreateUserProfileMutationObservable(appSyncClient, createProfileMutation))
                            .doOnComplete {
                                Log.d("Presenter", "Create profile mutation was completed successful!")
                            }
            )
            .subscribe({
                Log.d("Presenter", "All mutation completed")
                view?.hideProgress()
            },{
                Log.d("Presenter", "Error ${it.message}")
            })
}`

And our SubscribeToNotificationsObservable , CreateUserProfileMutationObservable CreateUserProfileMutationObservable.txt

SubscribeToNotificationsObservable.txt

As you can see in this rx wrappers I added Log for OnSubscribe, OnResponse and for disposable action

And finaly our logs logs.txt

And what we can see: that first mutation was sucssefull completed and next observable was call onSubscrive event

2019-01-22 23:28:08.787 17247-19159/com.moja D/Presenter: Subscribe to notification mutation was successful! 2019-01-22 23:28:08.787 17247-19159/com.moja D/CreateUserProfile: OnSubscribe for CreateUserProfileMutationObservable

Than the next mutation was processing with V/AppSyncOfflineMutationInterceptor

2019-01-22 23:28:08.787 17247-19159/com.moja V/AppSyncOfflineMutationInterceptor: Thread:[8406]: Processing mutation. 2019-01-22 23:28:08.787 17247-19159/com.moja V/AppSyncOfflineMutationInterceptor: Thread:[8406]: First, checking if it is a retry of mutation that encountered a conflict. 2019-01-22 23:28:08.787 17247-19159/com.moja V/AppSyncOfflineMutationInterceptor: Thread:[8406]:Nope, hasn't encountered conflict 2019-01-22 23:28:08.789 17247-19159/com.moja V/AppSyncOfflineMutationManager: Thread:[8406]: Added mutation[a361b52a-323b-4205-97f6-cbdf0295932e] to inMemory Queue

Than we see that first Comletable is completed and Disposable from action compelted

2019-01-22 23:28:08.810 17247-19159/com.moja D/SubscribeToNotif: Dispose after onComplete for SubscribeToNotificationsObservable 2019-01-22 23:28:08.810 17247-19159/com.moja V/AppSyncOfflineMutationInterceptor: Thread:[8406]: Dispose called for mutation [com.moja.SubscribeForNotificationsMutation@20a8138]. 2019-01-22 23:28:08.810 17247-19159/com.moja V/AppSyncOfflineMutationManager: Thread:[8406]: Handling cancellation for mutation [com.moja.SubscribeForNotificationsMutation@20a8138] 2019-01-22 23:28:08.810 17247-19159/com.moja V/AppSyncOfflineMutationManager: Thread:[8406]: Mutation being canceled is the one currently in progress. Handling it 2019-01-22 23:28:08.810 17247-19159/com.moja V/PersistentOfflineMutationManager: Thread:[8406]:Removing mutation [7fe29d07-39cd-4f9a-ad8a-d3dfb36ca952] from persistent store 2019-01-22 23:28:08.817 17247-19159/com.moja V/QueueUpdateHandler: Thread:[8406]: Setting mutationInProgress as false. 2019-01-22 23:28:08.817 17247-19159/com.moja V/AppSyncOfflineMutationInterceptor: Dispose called 2019-01-22 23:28:08.817 17247-18545/com.moja V/QueueUpdateHandler: Thread:[8327]: Got message to take action on the mutation queue. 2019-01-22 23:28:08.817 17247-18545/com.moja V/QueueUpdateHandler: Thread:[8327]: Got message to process next mutation if one exists. 2019-01-22 23:28:08.817 17247-19159/com.moja D/SubscribeToNotif: awsMutation.cancel() for notification subscription observable

After than I see that 2019-01-22 23:28:08.817 17247-19159/com.moja V/PersistentOfflineMutationManager: Thread:[8406]:Removing mutation [7fe29d07-39cd-4f9a-ad8a-d3dfb36ca952] from persistent store

but this mutation id for first mutation (SubscriptionNotificationMutation)

End in the add we see that our next mutation didn't complete and we didn't cancel her.

ukevgen commented 5 years ago

I've just added delay before second mutation and all work, so maybe we have some thread blocking in the mutation que CompletableCreate(SubscribeToNotificationsObservable(appSyncClient, subscribtionMutation)) .doOnComplete { Log.d("Presenter", "Subscribe to notification mutation was successful!") } .delay(1000L, TimeUnit.MILLISECONDS) .andThen( CompletableCreate(CreateUserProfileMutationObservable(appSyncClient, createProfileMutation)) .doOnComplete { Log.d("Presenter", "Create profile mutation was completed successful!") } ) .subscribe({ Log.d("Presenter", "All mutation completed") view?.hideProgress() },{ Log.d("Presenter", "Error ${it.message}") })

scb01 commented 5 years ago

@ukevgen Thanks for the additional context. I was able to reproduce the issue on my side - effectively what is happening is the first mutation is being cancelled in its own mutation callback (invoked when it finishes executing).

This is causing the mutation queue processing logic to be thrown off and is causing the next mutation in the queue to be deleted due to a bug.

The fix for this issue will be included in the next rev of the SDK. I will post back here once I have the release out. In the meantime, I'd recommend that you revisit the logic where the mutations are canceled - I am confused by why you have the logic to cancel the mutation after it has been executed.

scb01 commented 5 years ago

@DeMoss15 @ukevgen

v2.7.6 of the SDK contains the fix. Please give this version a try and let me know how you fare.

DeMoss15 commented 5 years ago

@cbommas

This couple of mutations works correctly after update. Thank you!

scb01 commented 5 years ago

@DeMoss15 Thank you for letting me know. I will go ahead and close this issue out.

awslabs / aws-mobile-appsync-sdk-android

infinite offline mutation #102