Datastore can fail silently when the internet connection is slow

[dgagnon]

Describe the bug
In cases where the internet connection available is slow or shaky, the datastore feature of amplify-flutter can lead to unexpected outcomes. This manifest itself in at least two cases:

1. The datastore will fail to become ready if the subscriber threads take more than 10 seconds to complete. When that happens, the following log is generated:

Logs

[ +102 ms] W/myblinds.mobil(15738): Long monitor contention with owner pool-7-thread-17 (15888) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:165) waiters=29 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 9.764s
[ +105 ms] W/myblinds.mobil(15738): Long monitor contention with owner pool-7-thread-17 (15888) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:165) waiters=30 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 9.865s
[  +83 ms] E/amplify:aws-datastore(15738): Failure encountered while attempting to start API sync.
[        ] E/amplify:aws-datastore(15738): DataStoreException{message=Timed out waiting for subscription processor to start., cause=null, recoverySuggestion=Retry}
[        ] E/amplify:aws-datastore(15738): 	at com.amplifyframework.datastore.syncengine.SubscriptionProcessor.startSubscriptions(SubscriptionProcessor.java:156)
[        ] E/amplify:aws-datastore(15738): 	at com.amplifyframework.datastore.syncengine.Orchestrator.lambda$startApiSync$3$Orchestrator(Orchestrator.java:309)
[        ] E/amplify:aws-datastore(15738): 	at com.amplifyframework.datastore.syncengine.-$$Lambda$Orchestrator$to6jsrpqq5TGk-8kfWyEK_7WfwQ.subscribe(Unknown Source:2)
[        ] E/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate.subscribeActual(CompletableCreate.java:40)
[        ] E/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
[        ] E/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
[        ] E/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
[        ] E/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
[        ] E/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
[        ] E/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
[        ] E/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
[        ] E/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.internal.operators.completable.CompletableSubscribeOn$SubscribeOnObserver.run(CompletableSubscribeOn.java:64)
[        ] E/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.core.Scheduler$DisposeTask.run(Scheduler.java:614)
[        ] E/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:65)
[        ] E/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:56)
[        ] E/amplify:aws-datastore(15738): 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[        ] E/amplify:aws-datastore(15738): 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301)
[        ] E/amplify:aws-datastore(15738): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
[        ] E/amplify:aws-datastore(15738): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
[        ] E/amplify:aws-datastore(15738): 	at java.lang.Thread.run(Thread.java:923)
[        ] W/amplify:aws-datastore(15738): API sync failed - transitioning to LOCAL_ONLY.
[        ] W/amplify:aws-datastore(15738): DataStoreException{message=Timed out waiting for subscription processor to start., cause=null, recoverySuggestion=Retry}
[        ] W/amplify:aws-datastore(15738): 	at com.amplifyframework.datastore.syncengine.SubscriptionProcessor.startSubscriptions(SubscriptionProcessor.java:156)
[        ] W/amplify:aws-datastore(15738): 	at com.amplifyframework.datastore.syncengine.Orchestrator.lambda$startApiSync$3$Orchestrator(Orchestrator.java:309)
[        ] W/amplify:aws-datastore(15738): 	at com.amplifyframework.datastore.syncengine.-$$Lambda$Orchestrator$to6jsrpqq5TGk-8kfWyEK_7WfwQ.subscribe(Unknown Source:2)
[        ] W/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate.subscribeActual(CompletableCreate.java:40)
[        ] W/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
[        ] W/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
[        ] W/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
[        ] W/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
[        ] W/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
[        ] W/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
[        ] W/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
[        ] W/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.internal.operators.completable.CompletableSubscribeOn$SubscribeOnObserver.run(CompletableSubscribeOn.java:64)
[        ] W/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.core.Scheduler$DisposeTask.run(Scheduler.java:614)
[        ] W/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:65)
[        ] W/amplify:aws-datastore(15738): 	at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:56)
[        ] W/amplify:aws-datastore(15738): 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[        ] W/amplify:aws-datastore(15738): 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301)
[        ] W/amplify:aws-datastore(15738): 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
[        ] W/amplify:aws-datastore(15738): 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
[        ] W/amplify:aws-datastore(15738): 	at java.lang.Thread.run(Thread.java:923)
[        ] I/amplify:aws-datastore(15738): Orchestrator transitioning from SYNC_VIA_API to LOCAL_ONLY
[        ] I/amplify:aws-datastore(15738): Setting currentState to LOCAL_ONLY
[        ] I/amplify:aws-datastore(15738): Stopping subscription processor.
[        ] I/flutter (15738): SUB: networkStatus
[        ] I/flutter (15738): Instance of 'AmplifyDatastoreNetworkStatusDisableEvent'
[ +475 ms] W/myblinds.mobil(15738): Long monitor contention with owner pool-7-thread-32 (16028) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:165) waiters=4 in void com.amplifyframework.api.aws.SubscriptionEndpoint.releaseSubscription(java.lang.String) for 481ms
[+1521 ms] I/amplify:aws-api(15738): No more active subscriptions. Closing web socket.
[        ] I/amplify:aws-datastore(15738): Stopped subscription processor.

2. It can cause the datastore fail syncing silently and then return empty queries even if data is present in DynamoDB.

During the initial sync, the following is logged and then, the first query done to Family returns an empty list.

Logs

[ +101 ms] W/amplify:aws-datastore(11094): Sync failed: foreign key constraint violation: ModelWithMetadata{model=SerializedModel{id='9a67e6ee-8647-4074-97f7-b594880bf646', serializedData={owner=Google_113456334824576197903, _deleted=null, role=ADMIN, data={}, _lastChangedAt=1.622233415285E12, member={id=0ec39055-ed59-43d3-a018-8c2ff98d43d7}, id=9a67e6ee-8647-4074-97f7-b594880bf646, family={id=0ec39055-ed59-43d3-a018-8c2ff98d43d7}, _version=1, status=ACTIVE}, modelSchema=ModelSchema{name='FamilyMember', pluralName='FamilyMembers', authRules=[AuthRule{authStrategy=OWNER, ownerField='owner', identityClaim='cognito:username', groupsField='null', groupClaim='null', groups=null', operations=[CREATE, UPDATE, DELETE, READ]'}, AuthRule{authStrategy=PRIVATE, ownerField='null', identityClaim='null', groupsField='null', groupClaim='null', groups=null', operations=[CREATE, UPDATE, DELETE, READ]'}], fields={data=ModelField{name='data', javaClassForValue='class java.lang.String', targetType='String', isReadOnly=false, isRequired=false, isArray=false, isEnum=false, isModel=false}, family=ModelField{name='family', javaClassForValue='interface com.amplifyframework.core.model.Model', targetType='Family', isReadOnly=false, isRequired=true, isArray=false, isEnum=false, isModel=true}, id=ModelField{name='id', javaClassForValue='class java.lang.String', targetType='String', isReadOnly=false, isRequired=true, isArray=false, isEnum=false, isModel=false}, member=ModelField{name='member', javaClassForValue='interface com.amplifyframework.core.model.Model', targetType='User', isReadOnly=false, isRequired=true, isArray=false, isEnum=false, isModel=true}, role=ModelField{name='role', javaClassForValue='class java.lang.String', targetType='String', isReadOnly=false, isRequired=true, isArray=false, isEnum=false, isModel=false}, status=ModelField{name='status', javaClassForValue='class java.lang.String', targetType='String', isReadOnly=false, isRequired=true, isArray=false, isEnum=false, isModel=false}}, associations={family=ModelAssociation{name='BelongsTo', targetName='familyId', associatedName='null', associatedType='Family'}, member=ModelAssociation{name='BelongsTo', targetName='memberId', associatedName='null', associatedType='User'}}, indexes={}, modelClass=class com.amplifyframework.datastore.appsync.SerializedModel}}, syncMetadata=ModelMetadata{id='9a67e6ee-8647-4074-97f7-b594880bf646', _deleted=null, _version=1, _lastChangedAt=Temporal.Timestamp{timestamp=1622233415285}}}
[        ] W/amplify:aws-datastore(11094): DataStoreException{message=Invalid SQL statement: INSERT INTO `FamilyMember` (`id`, `data`, `role`, `status`, `familyId`, `memberId`) VALUES (?, ?, ?, ?, ?, ?), cause=android.database.sqlite.SQLiteConstraintException: FOREIGN KEY constraint failed (code 787 SQLITE_CONSTRAINT_FOREIGNKEY), recoverySuggestion=There is a possibility that there is a bug if this error persists. Please take a look at 

To Reproduce
Steps to reproduce the behavior number 1:

1. Using Android Emulator
2. Click on Extended Controls
3. Set the network type to EDGE
4. Set the Signal Strength to Poor
5. Clear all local data for the app
6. Run the app

Steps to reproduce the behavior number 2:

1. Using Android Emulator
2. Click on Extended Controls
3. Set the network type to LTE
4. Set the Signal Strength to Good
5. Clear all local data for the app
6. Run the app

Expected behavior

1. The datastore should initialize, no matter how long it takes.
2. The datastore should either emit an event or an exception when an issue occurs during the initial sync process

Screenshots
If applicable, add screenshots to help explain your problem.

Platform
Amplify Flutter current supports iOS and Android. This issue is reproducible in (check all that apply):
[x] Android
[] iOS

Output of flutter doctor -v

  • Flutter version 2.2.0 at c:\src\flutter
  • Framework revision b22742018b (2 weeks ago), 2021-05-14 19:12:57 -0700
  • Engine revision a9d88a4d18
  • Dart version 2.13.0

[√] Android toolchain - develop for Android devices (Android SDK version 30.0.3)
  • Android SDK at C:\Users\dgagnon\AppData\Local\Android\sdk
  • Platform android-30, build-tools 30.0.3
  • Java binary at: C:\Program Files\Android\Android Studio\jre\bin\java
  • Java version OpenJDK Runtime Environment (build 1.8.0_242-release-1644-b01)
  • All Android licenses accepted.

[√] Chrome - develop for the web
  • Chrome at C:\Program Files (x86)\Google\Chrome\Application\chrome.exe

[√] Android Studio (version 4.1.0)
  • Android Studio at C:\Program Files\Android\Android Studio
  • Flutter plugin can be installed from:
     https://plugins.jetbrains.com/plugin/9212-flutter
  • Dart plugin can be installed from:
     https://plugins.jetbrains.com/plugin/6351-dart
  • Java version OpenJDK Runtime Environment (build 1.8.0_242-release-1644-b01)

[√] IntelliJ IDEA Ultimate Edition (version 2021.1)
  • IntelliJ at C:\Program Files\JetBrains\IntelliJ IDEA 2020.1.1
  • Flutter plugin version 56.0.5
  • Dart plugin version 211.7233

[√] Connected device (2 available)
  • sdk gphone x86 arm (mobile) • emulator-5554 • android-x86    • Android 11 (API 30) (emulator)
  • Chrome (web)                • chrome        • web-javascript • Google Chrome 90.0.4430.212

• No issues found!

Smartphone (please complete the following information):

• Device: Pixel 3a
• OS: Android 11
• Browser stock browser (chrome)
• Version [?]

Additional context
By setting the connection to Full and Great, behavior #1 never manifests itself and behavior #2 happens, but very rarely.

Here is the model:

type Family @model @auth(rules: [{ allow: owner }, { allow: private, provider: iam }]) {
  id: ID!
  name: String!
  members: [FamilyMember] @connection(keyName: "byFamily", fields: ["id"])
  status: GenericStatus!
  data: String
}
enum FamilyRole {
  OWNER
  KID
  USER
  ADMIN
}


type FamilyMember @model @auth(rules: [{ allow: owner }, { allow: private, provider: iam }]), @key(name: "byFamily", fields: ["familyId", "memberId"]), @key(name: "byMember", fields: ["memberId", "familyId"]) {
  id: ID!
  familyId: ID!
  memberId: ID!
  family: Family! @connection(fields: ["familyId"])
  member: User! @connection(fields: ["memberId"])
  role: FamilyRole!
  status: GenericStatus!
  data: String
}


type User @model @auth(rules: [{ allow: owner }, { allow: private, provider: iam }]) {
  id: ID!
  families: [FamilyMember] @connection(keyName: "byMember", fields: ["id"])
  email: String!
  status: GenericStatus!
  data: String
}

The code generating the error:

Future<List<T>> retrieveData<T extends Model>(
      {String modelName, QueryPredicate queryParams}) async {
    // print('RETRIEVE LIST OF MODELS FOR $this.classType');
    if (modelName == null) {
      modelName = this.primaryModelName;
    }
    List<T> results = [];
    try {
      if (this.isReady()) {
        if (queryParams != null) {
          // print('retrieveData' + queryParams.toString());
          results = await Amplify.DataStore.query(
              this.getClassTypeByModelName(modelName),
              where: queryParams);
        } else {
          // print('retrieveData no predicate');
          results = await Amplify.DataStore.query(
              this.getClassTypeByModelName(modelName));
        }
      }
      // } On ?? {
      //  throw ??AmplifyException();
      // }
    } catch (e) {
      throw UnknownErrorAmplifyException(e.toString());
    }

    if (results == null) {
      print("RetrieveData got a null from the datastore, are we initialized?");
      throw NotReadyAmplifyException();
      // results = [];
    }
    return results;
  }

[dgagnon]

Here are the full logs from a success and a failure. No changes to dynamodb or the code, only the connection settings.
success.txt

failure.txt

Here is the AppSync output for a family:

[dgagnon]

I believe that behavior #1 is caused by the consttant set in the AWS amplify android SDK:

https://github.com/aws-amplify/amplify-android/blob/main/aws-datastore/src/main/java/com/amplifyframework/datastore/syncengine/SubscriptionProcessor.java

private static final long NETWORK_OP_TIMEOUT_SECONDS = 10;

[HuiSF]

Thanks for reporting this issue @dgagnon and much appreciated that you attached such detailed investigation script.

I've been investigation a few issues (example) that involve subscription timeout. And I've identified an issue that exists amplify-android in may cause subscription timeout and merged a PR #1376 to fix. After the fix gets release I will integrate it into amplify-flutter. Hopefully this can improve subscription timeout.

Regarding your point:

The datastore should initialize, no matter how long it takes

The subscription process is designed synchronous which blocks main thread. Therefore, it may not be ideal that we keep waiting until subscription succeeds in a slow network connection environment.

After the initial subscription failed, each data model operation (save, update etc.) will retry subscription again. This is not a perfect solution, it may generates a lot of subscription timeout error logs. We my look into a better solution soon, e.g. retry subscription in the background when network connection status changed and without invoking data model operation.

[absarrahman]

This issue is still not fixed in v 0.1.6.

Logs
W/myblinds.mobil(11526): Long monitor contention with owner pool-6-thread-6 (11764) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:107) waiters=0 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 13.077s W/myblinds.mobil(11526): Long monitor contention with owner pool-6-thread-6 (11764) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:107) waiters=1 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 13.535s W/myblinds.mobil(11526): Long monitor contention with owner pool-6-thread-6 (11764) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:107) waiters=2 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 14.022s W/myblinds.mobil(11526): Long monitor contention with owner pool-6-thread-6 (11764) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:107) waiters=3 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 14.474s W/myblinds.mobil(11526): Long monitor contention with owner pool-6-thread-6 (11764) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:107) waiters=4 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 14.924s W/myblinds.mobil(11526): Long monitor contention with owner pool-6-thread-6 (11764) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:107) waiters=5 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 15.362s W/myblinds.mobil(11526): Long monitor contention with owner pool-6-thread-6 (11764) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:107) waiters=6 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 17.511s W/myblinds.mobil(11526): Long monitor contention with owner pool-6-thread-6 (11764) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:107) waiters=7 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 17.962s W/myblinds.mobil(11526): Long monitor contention with owner pool-6-thread-6 (11764) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:107) waiters=8 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 18.364s W/myblinds.mobil(11526): Long monitor contention with owner pool-6-thread-6 (11764) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:107) waiters=9 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 18.835s W/myblinds.mobil(11526): Long monitor contention with owner pool-6-thread-6 (11764) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:107) waiters=10 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 19.753s W/myblinds.mobil(11526): Long monitor contention with owner pool-6-thread-6 (11764) at void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action)(SubscriptionEndpoint.java:107) waiters=11 in void com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(com.amplifyframework.api.graphql.GraphQLRequest, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Consumer, com.amplifyframework.core.Action) for 23.397s E/amplify:aws-datastore(11526): Failure encountered while attempting to start API sync. E/amplify:aws-datastore(11526): DataStoreException{message=Timed out waiting for subscription processor to start., cause=null, recoverySuggestion=Retry} E/amplify:aws-datastore(11526): at com.amplifyframework.datastore.syncengine.SubscriptionProcessor.startSubscriptions(SubscriptionProcessor.java:156) E/amplify:aws-datastore(11526): at com.amplifyframework.datastore.syncengine.Orchestrator.lambda$startApiSync$3$Orchestrator(Orchestrator.java:309) E/amplify:aws-datastore(11526): at com.amplifyframework.datastore.syncengine.-$$Lambda$Orchestrator$to6jsrpqq5TGk-8kfWyEK_7WfwQ.subscribe(Unknown Source:2) E/amplify:aws-datastore(11526): at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate.subscribeActual(CompletableCreate.java:40) E/amplify:aws-datastore(11526): at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850) E/amplify:aws-datastore(11526): at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51) E/amplify:aws-datastore(11526): at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850) E/amplify:aws-datastore(11526): at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51) E/amplify:aws-datastore(11526): at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850) E/amplify:aws-datastore(11526): at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51) E/amplify:aws-datastore(11526): at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850) E/amplify:aws-datastore(11526): at io.reactivex.rxjava3.internal.operators.completable.CompletableSubscribeOn$SubscribeOnObserver.run(CompletableSubscribeOn.java:64) E/amplify:aws-datastore(11526): at io.reactivex.rxjava3.core.Scheduler$DisposeTask.run(Scheduler.java:614) E/amplify:aws-datastore(11526): at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:65) E/amplify:aws-datastore(11526): at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:56) E/amplify:aws-datastore(11526): at java.util.concurrent.FutureTask.run(FutureTask.java:266) E/amplify:aws-datastore(11526): at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301) E/amplify:aws-datastore(11526): at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) E/amplify:aws-datastore(11526): at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) E/amplify:aws-datastore(11526): at java.lang.Thread.run(Thread.java:919) W/amplify:aws-datastore(11526): API sync failed - transitioning to LOCAL_ONLY. W/amplify:aws-datastore(11526): DataStoreException{message=Timed out waiting for subscription processor to start., cause=null, recoverySuggestion=Retry} W/amplify:aws-datastore(11526): at com.amplifyframework.datastore.syncengine.SubscriptionProcessor.startSubscriptions(SubscriptionProcessor.java:156) W/amplify:aws-datastore(11526): at com.amplifyframework.datastore.syncengine.Orchestrator.lambda$startApiSync$3$Orchestrator(Orchestrator.java:309) W/amplify:aws-datastore(11526): at com.amplifyframework.datastore.syncengine.-$$Lambda$Orchestrator$to6jsrpqq5TGk-8kfWyEK_7WfwQ.subscribe(Unknown Source:2) W/amplify:aws-datastore(11526): at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate.subscribeActual(CompletableCreate.java:40) W/amplify:aws-datastore(11526): at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850) W/amplify:aws-datastore(11526): at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51) W/amplify:aws-datastore(11526): at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850) W/amplify:aws-datastore(11526): at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51) W/amplify:aws-datastore(11526): at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850) W/amplify:aws-datastore(11526): at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51) W/amplify:aws-datastore(11526): at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850) W/amplify:aws-datastore(11526): at io.reactivex.rxjava3.internal.operators.completable.CompletableSubscribeOn$SubscribeOnObserver.run(CompletableSubscribeOn.java:64) W/amplify:aws-datastore(11526): at io.reactivex.rxjava3.core.Scheduler$DisposeTask.run(Scheduler.java:614) W/amplify:aws-datastore(11526): at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:65) W/amplify:aws-datastore(11526): at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:56) W/amplify:aws-datastore(11526): at java.util.concurrent.FutureTask.run(FutureTask.java:266) W/amplify:aws-datastore(11526): at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301) W/amplify:aws-datastore(11526): at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) W/amplify:aws-datastore(11526): at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) W/amplify:aws-datastore(11526): at java.lang.Thread.run(Thread.java:919) I/amplify:aws-datastore(11526): Orchestrator transitioning from SYNC_VIA_API to LOCAL_ONLY I/amplify:aws-datastore(11526): Setting currentState to LOCAL_ONLY I/amplify:aws-datastore(11526): Stopping subscription processor.

This is my internet speed.

[HuiSF]

Thanks for the feedback @absarrahman
I can reproduce myself with limited network condition (simulated 3G) while trying to subscribe to 6 models.
Subscription always succeeds in iOS under the same testing conditions.
Moving this issue to amplify-android for further investigation.

[HuiSF]

amplify-android fix to increase subscription timeout period #1389

[HuiSF]

Hi all, with the latest release of amplify-flutter (0.2.1) subscription should work on slow networks (Edge, 3G).
Please keep in mind that the ultimate result depends on device network conditions. I'd recommend to have a layer of handling on long network connecting to ensure a better experience for your App users.

Please feel free to follow up if you encounter any issues.