All mutations hadn't been executed after internet connection type change #2

[DeMoss15]

SDK version: 2.11.0
AppSync version: 2.7.6

It's hard to reproduce this issue.
Steps to reproduce looks like:
execute few mutations -> wait about 15 min -> switch internet connection -> mutations doesn't work
Logs looks like something wrong with queue or AppSyncOfflineMutationManager

Please pay your attention for this log:
FROM EXECUTED MUTATION TO FAIL.txt

Let's look at it closer:

Here we can see the last executed mutation:

02-08 16:17:14.983  2511  4668 V AppSyncOfflineMutationInterceptor: Thread:[3340]: Processing mutation.
02-08 16:17:14.983  2511  4668 V AppSyncOfflineMutationInterceptor: Thread:[3340]: First, checking if it is a retry of mutation that encountered a conflict.
02-08 16:17:14.983  2511  4668 V AppSyncOfflineMutationInterceptor: Thread:[3340]:Nope, hasn't encountered  conflict
02-08 16:17:14.985  2511  4668 V AppSyncOfflineMutationManager: Thread:[3340]:  Added mutation[02918de8-1789-489b-91e9-3e85b32741fb] to inMemory Queue
02-08 16:17:14.985  2511  4668 V S3ObjectManagerImplementation: Thread:[3340]: Looking at Key [buyerStorefrontId] of type [j]
02-08 16:17:14.985  2511  4668 V S3ObjectManagerImplementation: Thread:[3340]: Looking at Key [sellerStorefrontId] of type [j]
02-08 16:17:14.985  2511  4668 V S3ObjectManagerImplementation: Thread:[3340]: Looking at Key [withShipping] of type [Boolean]
02-08 16:17:14.985  2511  4668 V S3ObjectManagerImplementation: Thread:[3340]: Looking at Key [shippingAddress] of type [String]
02-08 16:17:14.989  2511  4668 V PersistentOfflineMutationManager: Thread:[3340]:addPersistentMutationObject: Adding mutation[02918de8-1789-489b-91e9-3e85b32741fb]: d 
02-08 16:17:14.989  2511  4668 V PersistentOfflineMutationManager: {"query":"mutation Checkout($buyerStorefrontId: StorefrontId, $sellerStorefrontId: StorefrontId!, $withShipping: Boolean!, $shippingAddress: String, $status: OrderStatus) {  checkout(buyerStorefrontId: $buyerStorefrontId, sellerStorefrontId: $sellerStorefrontId, withShipping: $withShipping, shippingAddress: $shippingAddress, status: $status) {    __typename    ...CheckoutRemote  }}fragment ItemRemote on Item {  __typename  userId  createdAt  updatedAt  variations {    __typename    ...ItemVariation  }  title  categories {    __typename    ...ItemCategory  }  photos {    __typename    ...ItemPhotoRemote  }  description  available  version  author {    __typename    ...StorefrontProfileRemote  }}fragment ItemVariation on ItemVariation {  __typename  id  title  price  photos {    __typename    ...ItemPhotoRemote  }  available  shippingAvailable  negotiable}fragment ItemCategory on ItemCategory {  __typename  id  name}fragment ItemPhotoRemote on ItemPhoto {  __typename  position  image}fragment CheckoutRemote on Order {  __typename  orderId  userId  storefrontId  buyer {    __typename    ...UserProfileRemote  }  buyerStorefront {    __typename    ...StorefrontProfileRemote  }  buyerType  createdAt  updatedAt  finalPrice  totalPrice  shippingAddress  comment  orderItems {    __typename    ...OrderItemRemote  }  withShipping  status}fragment OrderItemRemote on OrderItem {  __typename  userId  item {    __typename    ...ItemRemote  }  quantity  createdAt  updatedAt  variationId}fragment UserProfileRemote on UserProfile {  __typename  userId  name  street  city  about  profileImage  coverImage  version}fragment StorefrontProfileRemote on StorefrontProfile {  __typename  about  city  coverImage  createdAt  name  offeringDescription  profileImage  shippingDescription  street  fromTrustedNetwork  updatedAt  userId  version}","variables":{"buyerStorefrontId":{"userId":"d730091d-162b-4d1c-9511-4eeaf88c17cd","createdAt":"2019-02-07T16:45:19.814Z"},"sellerStorefrontId":{"userId":"b8f336ba-dd1d-4b85-ad5d-a920c52a6daa","createdAt":"2019-02-08T07:26:23.853Z"},"withShipping":true,"shippingAddress":"We Have, Thanks For, Ghana"}}
02-08 16:17:14.999  2511  4668 V AppSyncOfflineMutationManager: Thread:[3340]: Added mutation[02918de8-1789-489b-91e9-3e85b32741fb] to Persistent Queue. No S3 Objects found
02-08 16:17:15.000  2511  4668 V AppSyncOfflineMutationManager: Thread:[3340]: Created both in-memory and persistent records. Now going to signal queue handler.
02-08 16:17:15.000  2511  3001 V QueueUpdateHandler: Thread:[3169]: Got message to take action on the mutation queue.
02-08 16:17:15.000  2511  3001 V QueueUpdateHandler: Thread:[3169]: Got message to process next mutation if one exists.
02-08 16:17:15.001  2511  3001 V AppSyncOfflineMutationManager: Thread:[3169]:Persistent mutations queue is EMPTY!. Will check inMemory Queue next
02-08 16:17:15.001  2511  3001 V QueueUpdateHandler: Thread:[3169]: Setting mutationInProgress as true.
02-08 16:17:15.001  2511  3001 V AppSyncOfflineMutationManager: Thread:[3169]: Processing next from in Memory queue
02-08 16:17:15.001  2511  3001 V InMemoryOfflineMutationManager: Thread:[3169]:Executing mutation [02918de8-1789-489b-91e9-3e85b32741fb]
02-08 16:17:15.001  2511  3001 V InMemoryOfflineMutationObject: Thread:[3169]: Executing mutation by proceeding with the chain.
02-08 16:17:15.001  2511  3001 V S3ObjectManagerImplementation: Thread:[3169]: Looking at Key [buyerStorefrontId] of type [j]
02-08 16:17:15.001  2511  3001 V S3ObjectManagerImplementation: Thread:[3169]: Looking at Key [sellerStorefrontId] of type [j]
02-08 16:17:15.001  2511  3001 V S3ObjectManagerImplementation: Thread:[3169]: Looking at Key [withShipping] of type [Boolean]
02-08 16:17:15.002  2511  3001 V S3ObjectManagerImplementation: Thread:[3169]: Looking at Key [shippingAddress] of type [String]
02-08 16:17:15.002  2511  3001 V AppSyncComplexObjectsInterceptor: Thread:[3169]: No s3 Objects found. Proceeding with the chain
02-08 16:17:15.003  2511  5056 V InterceptorCallback: Thread:[3353]: onFetch()
02-08 16:17:15.005  2511  5066 D RetryInterceptor: Retry Interceptor called
02-08 16:17:15.005  2511  5066 D AppSyncSigV4SignerInterceptor: Signer Interceptor called
02-08 16:17:15.974  2511  5066 I RetryInterceptor: Returning network response: success
02-08 16:17:16.087  2511  5066 V InterceptorCallback: Thread:[3361]: onResponse()
02-08 16:17:16.089  2511  5066 V AppSyncOfflineMutationInterceptor: Thread:[3361]: Dispose called for mutation [com.moja.d@600d3d].
02-08 16:17:16.089  2511  5066 V AppSyncOfflineMutationManager: Thread:[3361]: Handling cancellation for mutation [com.moja.d@600d3d]
02-08 16:17:16.089  2511  5066 V AppSyncOfflineMutationManager: Thread:[3361]: Mutation being canceled is the one currently in progress. Handling it 
02-08 16:17:16.089  2511  5066 V PersistentOfflineMutationManager: Thread:[3361]:Removing mutation [02918de8-1789-489b-91e9-3e85b32741fb] from persistent store
02-08 16:17:16.093  2511  5059 D RetryInterceptor: Retry Interceptor called
02-08 16:17:16.093  2511  5059 D AppSyncSigV4SignerInterceptor: Signer Interceptor called
02-08 16:17:16.105  2511  5066 V QueueUpdateHandler: Thread:[3361]: Setting mutationInProgress as false.
02-08 16:17:16.105  2511  5066 V AppSyncOfflineMutationInterceptor: Dispose called
02-08 16:17:16.105  2511  5066 V PersistentOfflineMutationManager: Thread:[3361]:Removing mutation [02918de8-1789-489b-91e9-3e85b32741fb] from persistent store
02-08 16:17:16.106  2511  5066 V QueueUpdateHandler: Thread:[3361]: Setting mutationInProgress as false.
02-08 16:17:16.106  2511  5066 D InterceptorCallback: Thread:[3361]: onCompleted()
02-08 16:17:16.106  2511  3001 V QueueUpdateHandler: Thread:[3169]: Got message to take action on the mutation queue.
02-08 16:17:16.106  2511  3001 V QueueUpdateHandler: Thread:[3169]: Got message to process next mutation if one exists.
02-08 16:17:16.107  2511  3001 V AppSyncOfflineMutationManager: Thread:[3169]:Persistent mutations queue is EMPTY!. Will check inMemory Queue next
02-08 16:17:16.107  2511  3001 V AppSyncOfflineMutationManager: Thread:[3169]: In Memory mutations queue was EMPTY!. Nothing to process, exiting

than we have a log of internet connection status change:

02-08 16:30:06.111  2511  3001 V QueueUpdateHandler: Thread:[3169]: Got message to take action on the mutation queue.
02-08 16:30:06.111  2511  3001 V QueueUpdateHandler: Thread:[3169]: Got message to process next mutation if one exists.
02-08 16:30:06.112  2511  3001 V AppSyncOfflineMutationManager: Thread:[3169]:Persistent mutations queue is EMPTY!. Will check inMemory Queue next
02-08 16:30:06.112  2511  3001 V AppSyncOfflineMutationManager: Thread:[3169]: In Memory mutations queue was EMPTY!. Nothing to process, exiting
02-08 16:31:31.164  2511  3000 D AppSyncOfflineMutationManager: Thread:[3168]: Internet DISCONNECTED.
02-08 16:31:31.322  2511  3000 D AWSAppSyncDeltaSync: Delta Sync: Network Down detected.
02-08 16:31:32.831  2511  3001 V AppSyncOfflineMutationInterceptor: Thread:[3169]: processing Mutations
02-08 16:31:32.831  2511  3001 V QueueUpdateHandler: Thread:[3169]: Got message to take action on the mutation queue.
02-08 16:31:32.831  2511  3001 V QueueUpdateHandler: Thread:[3169]: Got message to process next mutation if one exists.
02-08 16:31:32.831  2511  3001 V AppSyncOfflineMutationManager: Thread:[3169]: Internet wasn't available. Exiting

and here is the first failed mutation:

02-08 17:33:42.341  2511  6468 V AppSyncOfflineMutationManager: Thread:[3409]:  Added mutation[5543e750-6367-4d2f-92e3-7fa7a4929faf] to inMemory Queue
02-08 17:33:42.342  2511  6468 V S3ObjectManagerImplementation: Thread:[3409]: Looking at Key [name] of type [String]
02-08 17:33:42.349  2511  6468 V S3ObjectManagerImplementation: Thread:[3409]: Looking at Key [street] of type [String]
02-08 17:33:42.354  2511  6468 V S3ObjectManagerImplementation: Thread:[3409]: Looking at Key [city] of type [String]
02-08 17:33:42.355  2511  6468 V S3ObjectManagerImplementation: Thread:[3409]: Looking at Key [about] of type [String]
02-08 17:33:42.357  2511  6468 V S3ObjectManagerImplementation: Thread:[3409]: Looking at Key [expectedVersion] of type [Integer]
02-08 17:33:42.363  2511  6468 V PersistentOfflineMutationManager: Thread:[3409]:addPersistentMutationObject: Adding mutation[5543e750-6367-4d2f-92e3-7fa7a4929faf]: bc 
02-08 17:33:42.363  2511  6468 V PersistentOfflineMutationManager: {"query":"mutation UpdateProfile($name: String, $street: String, $city: String, $about: String, $profileImage: S3FileInput, $coverImage: S3FileInput, $expectedVersion: Int!) {  updateUserProfile(name: $name, street: $street, city: $city, about: $about, profileImage: $profileImage, coverImage: $coverImage, expectedVersion: $expectedVersion) {    __typename    ...UserProfileRemote  }}fragment UserProfileRemote on UserProfile {  __typename  userId  name  street  city  about  profileImage  coverImage  version}","variables":{"name":"Gleb","street":"We Have","city":"Thanks For","about":"Thanks for the invite but I will not be able to make that work for your company to get e have","expectedVersion":1}}
02-08 17:33:42.456  2511  6468 V AppSyncOfflineMutationManager: Thread:[3409]: Added mutation[5543e750-6367-4d2f-92e3-7fa7a4929faf] to Persistent Queue. No S3 Objects found
02-08 17:33:42.456  2511  6468 V AppSyncOfflineMutationManager: Thread:[3409]: Created both in-memory and persistent records. Now going to signal queue handler.
02-08 17:33:42.457  2511  3001 V QueueUpdateHandler: Thread:[3169]: Got message to take action on the mutation queue.
02-08 17:33:42.457  2511  3001 V QueueUpdateHandler: Thread:[3169]: Got message to process next mutation if one exists.
02-08 17:33:42.457  2511  3001 V AppSyncOfflineMutationManager: Thread:[3169]: Internet wasn't available. Exiting

I think something strange is happening beyond this log:

02-08 17:33:19.789  2511  3001 V QueueUpdateHandler: Thread:[3169]: Got message to process next mutation if one exists.
02-08 17:33:19.790  2511  3001 V AppSyncOfflineMutationManager: Thread:[3169]: Internet wasn't available. Exiting
02-08 17:33:22.802  2511  2511 V PhoneWindow: DecorView setVisiblity: visibility = 0, Parent = ViewRoot{e28e02e com.moja/com.moja.flow.main.MainActivity,ident = 5}, this = DecorView@4800773[MainActivity]
02-08 17:33:22.878  2511  6472 I System.out: port:8888
02-08 17:33:22.927  2511  2511 D Surface : Surface::allocateBuffers(this=0x7bc0e99000)
02-08 17:33:22.948  2511  2595 D Surface : Surface::connect(this=0x7bc0e99000,api=1)
02-08 17:33:23.270  2511  6501 D RetryInterceptor: Retry Interceptor called
02-08 17:33:23.270  2511  6501 D AppSyncSigV4SignerInterceptor: Signer Interceptor called
02-08 17:33:23.384  2511  6472 I System.out: [OkHttp] sendRequest<<
02-08 17:33:23.400  2511  2511 W glide-disk-cach: type=1400 audit(0.0:3690): avc: denied { search } for name="clients" dev="debugfs" ino=44 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:debugfs_ion:s0 tclass=dir permissive=0
02-08 17:33:23.410  2511  2511 W glide-disk-cach: type=1400 audit(0.0:3691): avc: denied { search } for name="clients" dev="debugfs" ino=44 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:debugfs_ion:s0 tclass=dir permissive=0
02-08 17:33:23.746  2511  2511 D CognitoCachingCredentialsProvider: Loading credentials from SharedPreferences
02-08 17:33:23.759  2511  2511 D CognitoCachingCredentialsProvider: Clearing credentials from SharedPreferences
02-08 17:33:23.760  2511  2511 D CognitoCachingCredentialsProvider: Clearing credentials from SharedPreferences
02-08 17:33:23.761  2511  6466 D CognitoCachingCredentialsProvider: Loading credentials from SharedPreferences
02-08 17:33:23.761  2511  6466 D CognitoCachingCredentialsProvider: No valid credentials found in SharedPreferences
02-08 17:33:23.768  2511  6466 I System.out: port:8888
02-08 17:33:23.783  2511  6501 I System.out: port:8888
02-08 17:33:24.262  2511  6466 I System.out: [OkHttp] sendRequest<<
02-08 17:33:24.489  2511  6466 D CognitoCachingCredentialsProvider: Saving credentials to SharedPreferences
02-08 17:33:24.491  2511  6466 D CognitoCachingCredentialsProvider: Saving identity id to SharedPreferences
02-08 17:33:24.564  2511  6466 I System.out: [OkHttp] sendRequest<<
02-08 17:33:24.659  2511  2511 V AppSyncOfflineMutationInterceptor: Dispose called
02-08 17:33:24.661  2511  6501 W RetryInterceptor: Encountered IO Exception making HTTP call [java.io.IOException: Canceled]
02-08 17:33:24.768  2511  6466 D CognitoCachingCredentialsProvider: Saving credentials to SharedPreferences
02-08 17:33:24.942  2511  6500 V AppSyncOfflineMutationInterceptor: Dispose called
02-08 17:33:24.942  2511  6622 V AppSyncOfflineMutationInterceptor: Dispose called
02-08 17:33:24.944  2511  6499 V AppSyncOfflineMutationInterceptor: Dispose called
02-08 17:33:24.962  2511  6625 V AppSyncOfflineMutationInterceptor: Dispose called
02-08 17:33:26.377  2511  6625 V AppSyncOfflineMutationInterceptor: Dispose called
02-08 17:33:26.395  2511  6499 V AppSyncOfflineMutationInterceptor: Dispose called
02-08 17:33:28.791  2511  6501 D RetryInterceptor: Retry Interceptor called
02-08 17:33:28.791  2511  6501 D AppSyncSigV4SignerInterceptor: Signer Interceptor called
02-08 17:33:28.808  2511  6925 D RetryInterceptor: Retry Interceptor called
02-08 17:33:28.809  2511  6925 D AppSyncSigV4SignerInterceptor: Signer Interceptor called
02-08 17:33:29.224  2511  6501 I RetryInterceptor: Returning network response: success
02-08 17:33:29.284  2511  6501 V AppSyncOfflineMutationInterceptor: Dispose called
02-08 17:33:29.578  2511  6925 I RetryInterceptor: Returning network response: success
02-08 17:33:29.636  2511  6925 V AppSyncOfflineMutationInterceptor: Dispose called

Unfortunately, I don't understand what exactly. But it seems next line says that network is OK:

02-08 17:33:29.578  2511  6925 I RetryInterceptor: Returning network response: success

[sunchunqiang]

Hi @DeMoss15 When you said internet connection type change, do you mean switching internet connection from off to on?
Could you also please provide some code snippet for the issue?

[DeMoss15]

Hi, @muellerfr. I mean switching type of internet connection. for example: from wifi to mobile internet or vice versa. And please, specify what do you mean under the "code snippet". What should this code show?

[sunchunqiang]

Hi, @DeMoss15 you said "execute few mutations -> wait about 15 min -> switch internet connection -> mutations doesn't work", my question is, in the first 15 min, is the internet connection available? if yes, why does not the mutations finish in this 15min?

It will be helpful if you can provide code snippet of how you initialize the environment and execute the mutations

[DeMoss15]

@sunchunqiang It's only approximately steps.
Internet connection is on (wifi). Than user executes some mutations and leaves his phone laying down for [about]15 minutes (intenten still on). Then he takes this phone, switches internet connection to mobile internet. And here it is. Mutations stop working.
This issue is duplicate of this because there was no answer since last message for 7 days. So you can find some answers there.

Here is our settings for AWSAppSyncClient and CognitoUserPoolsAuthProvider

private fun getUserPool(userPoolId: String, userPoolClientId: String): CognitoUserPoolsAuthProvider {
            return BasicCognitoUserPoolsAuthProvider(CognitoUserPool(
                    MojaApplication.applicationContext(),
                    userPoolId,
                    userPoolClientId,
                    ApiSettings.USER_POOLS_CLIENT_SECRET,
                    ApiSettings.USER_POOL_REGION))
        }

        fun getInstance(appSettings: AppSettingsRepository, context: Context): AWSAppSyncClient {
            return AWSAppSyncClient.builder()
                    .context(MojaApplication.applicationContext())
                    .cognitoUserPoolsAuthProvider(getUserPool(
                            appSettings.getSettings().userPoolId,
                            appSettings.getSettings().userPoolClientId))
                    .region(ApiSettings.AWS_REGION)
                    .defaultResponseFetcher(NetworkOnlyFetcher())
                    .conflictResolver(MojaConflictResolver())
                    .serverUrl(appSettings.getSettings().graphqlUrl)
                    .okHttpClient(provideOkHttpClient(context))
                    .build()
        }

and example of mutation:

override fun subscribeToNotifications(deviceToken: String, appVersion: String, osVersion: String): Completable {
        val mutation = SubscribeForNotificationsMutation.builder()
                .deviceToken(deviceToken)
                .osVersion(osVersion)
                .appVersion(appVersion)
                .build()
        return CompletableCreate(SubscribeToNotificationsObservable(appSyncClient, mutation))
                .subscribeOn(AndroidSchedulers.mainThread())
                .observeOn(Schedulers.io())
    }

// ==============================================================================

class SubscribeToNotificationsObservable(private val awsAppSyncClient: AWSAppSyncClient,
                                         private val mutation: SubscribeForNotificationsMutation) : CompletableOnSubscribe {

    override fun subscribe(emitter: CompletableEmitter) {
        val awsMutation = awsAppSyncClient.mutate(mutation)
        awsMutation.enqueue(object : GraphQLCall.Callback<SubscribeForNotificationsMutation.Data>() {
            override fun onResponse(response: Response<SubscribeForNotificationsMutation.Data>) {
                emitter.onComplete()
            }

            override fun onFailure(e: ApolloException) {
                emitter.onError(e)
            }
        })
        emitter.setDisposable(Disposables.fromAction { awsMutation.cancel() })
    }
}

[scb01]

@DeMoss15

I see the same behavior as in #108. In the attached log, I see that the device went offline at 16:31:31

  02-08 16:31:31.164  2511  3000 D AppSyncOfflineMutationManager: Thread:[3168]: Internet DISCONNECTED

After that I see the following at 16:31:58, 17:03:18 and 17:03:22 in the log, but at no point do we get a signal that the device was connected.

  02-08 16:31:58.491  2511  3000 D AppSyncOfflineMutationManager: Thread:[3168]: Internet DISCONNECTED.
  02-08 17:03:18.387  2511  3000 D AppSyncOfflineMutationManager: Thread:[3168]: Internet DISCONNECTED.
  02-08 17:03:22.397  2511  3000 D AppSyncOfflineMutationManager: Thread:[3168]: Internet DISCONNECTED.

As you've mentioned, this is hard to reproduce and I haven't been able to reproduce it locally yet. I will continue to work on this - in the interests of eliminating variables, can you confirm that you do have the permission android.permission.ACCESS_NETWORK_STATE included in your app manifest?

[scb01]

@DeMoss15

While I wasn't able to reproduce this locally, I made some tweaks to the network checking logic to be more resilient. Can you give the latest version, 2.7.8, a try and see if that resolves the issue?

[DeMoss15]

@cbommas

Yes, we have android.permission.ACCESS_NETWORK_STATE permission in out manifest. I will update dependencies and try reproduce it again today.

[DeMoss15]

@cbommas
We can't reproduce it anymore. Thank you!

[scb01]

@DeMoss15

Glad to know that the issue is resolved. Thanks for confirming.