search

aws-amplify / amplify-android

The fastest and easiest way to use AWS from your Android app.
https://docs.amplify.aws/lib/q/platform/android/
Apache License 2.0
238 stars 111 forks source link

DataStore subscriptionProcessor failed #2734

Open mvishnureddy007 opened 4 months ago

mvishnureddy007 commented 4 months ago

Before opening, please confirm:

Language and Async Model

Java

Amplify Categories

Authentication, GraphQL API, DataStore

Gradle script dependencies

implementation 'com.amplifyframework:core:2.13.0' implementation 'com.amplifyframework:aws-api:2.13.0' implementation 'com.amplifyframework:aws-datastore:2.13.0' implementation 'com.amplifyframework:aws-auth-cognito:2.13.0' implementation 'com.amplifyframework:rxbindings:2.13.0'

Environment information

implementation 'com.amplifyframework:core:2.13.0' implementation 'com.amplifyframework:aws-api:2.13.0' implementation 'com.amplifyframework:aws-datastore:2.13.0' implementation 'com.amplifyframework:aws-auth-cognito:2.13.0' implementation 'com.amplifyframework:rxbindings:2.13.0'

Please include any relevant guides or documentation you're referencing

No response

Describe the bug

Hi, We are getting this error after user has been logged in and out for multiple times.

DataStoreException{message=DataStore subscriptionProcessor failed to start., cause=GraphQLResponseException{message=Subscription error for MessageRecipient: [GraphQLResponse.Error{message='subscription exceeds maximum value limit 20 for operator containsAny.', locations='null', path='null', extensions='{errorCode=400}'}], errors=[GraphQLResponse.Error{message='subscription exceeds maximum value limit 20 for operator containsAny.', locations='null', path='null', extensions='{errorCode=400}'}], recoverySuggestion=See attached list of GraphQLResponse.Error objects.}, recoverySuggestion=Check your internet.}

GraphQLResponseException{message=Subscription error for MessageRecipient: [GraphQLResponse.Error{message='subscription exceeds maximum value limit 20 for operator containsAny.', locations='null', path='null', extensions='{errorCode=400}'}], errors=[GraphQLResponse.Error{message='subscription exceeds maximum value limit 20 for operator containsAny.', locations='null', path='null', extensions='{errorCode=400}'}], recoverySuggestion=See attached list of GraphQLResponse.Error objects.}

Reproduction steps (if applicable)

No response

Code Snippet

// Put your code below this line.

Log output

``` // Put your logs below this line ```

amplifyconfiguration.json

No response

GraphQL Schema

```graphql // Put your schema below this line ```

Additional information and screenshots

No response

tylerjroach commented 4 months ago

@mvishnureddy007 You appear to be running into a limit on the AppSync side. Do you have >20 containsAny predicates?

mvishnureddy007 commented 4 months ago

@tylerjroach We don't have containsAny predicate in our code. I'm providing our observer Code here

QueryPredicate predicate = MessageRecipient.USER_ID.eq(ApplicationData.shared.userProfileData.getId()); QuerySortBy sortBy = new QuerySortBy("MessageRecipient", "sentAt", QuerySortOrder.ASCENDING); List sortByList = new ArrayList(); sortByList.add(sortBy); ObserveQueryOptions options = new ObserveQueryOptions(predicate, sortByList); Amplify.DataStore.observeQuery(MessageRecipient.class, options, observationStarted, onQuerySnapshot, onObservationError, onObservationComplete);

Our scenario is happening because of Same user logged into multiple devices.

I'm providing schema type MessageRecipient @model @auth(rules: [ {allow: groups, groupsField: "permittedTo"} ]) { id: ID! messageId: ID! @index(name:"byMessage") groupId: String! @index(name: "byGroup") userId: Int! @index(name:"byUser") status: MessageStatus! sentAt: AWSDateTime! readAt: AWSDateTime permittedTo: [String!] }

tylerjroach commented 4 months ago

Even though the Android client only uses client-side filtering, the service still uses Enhanced Subscription Filtering on the service side to enforce dynamic auth rules.

This rule

@auth(rules: [
  {allow: groups, groupsField: "permittedTo"}
])

Gets applied service-side in the subscription auth resolver with the containsAny operator to match the groups the user is in to the groups define in the group field permittedTo. The limit is listed here.

Most likely the root cause is: either some of the records have too many groups listed in the permittedTo field or the other way around, the user is a member of too many groups.

I'm not exactly sure how multiple sign-in/sign-outs, or multiple devices would cause the failure. As far as I understand, the limit is per subscriber.

If the explanation above doesn't help resolve the issue, please reply back with information around how Amplify is configured. How DataStore is started/stopped, and any other information you believe may be relevant, such as specific scenarios around the mentioned multiple device/sign-ins.

mvishnureddy007 commented 3 months ago

If the user can be part of more than 20 groups, which is common situation in our workflow. Can you help us, how to handle this?

iartemiev commented 3 months ago

There's no way to accommodate this when using AppSync subscriptions due to the way subscription filtering is implemented in the service. This is a hard limit in the service and it's not possible to increase it on a case-by-case basis.

You may be able to disable subscriptions for models that use dynamic group auth ({allow: groups, groupsField: "permittedTo"}) and then rely on DataStore sync queries to retrieve new/updated records, similar to a polling approach, but it's not possible to get this working with real-time subscription messages without reducing the number of groups to <= 20.

Note that the same limit applies for a list of owners or any other dynamic, list-based row-level authorization.

mvishnureddy007 commented 3 months ago

We have removed this

({allow: groups, groupsField: "permittedTo"})

Subscription is working fine.

But we got another issue. ie., After every fresh login the Data store query sync is taking long time to get data from cloud. Step we are following

  1. Once logged into mobile we are checking auth session.
  2. After that we are doing this for start data store query Amplify.DataStore.start( () -> Log.i("MyAmplifyApp", "DataStore started"), error -> Log.e("MyAmplifyApp", "Error starting DataStore", error) );
  3. Once i go to chat at first time data store query retring empty or 1 record only.
tylerjroach commented 3 months ago

@mvishnureddy007 Please update to Amplify Android 2.14.11. The last few Amplify releases have provided significant performance improvements for subscription and sync.

Please report back after updating.

mvishnureddy007 commented 3 months ago

After updated Amplify Android 2.14.11 also the Data store query sync is taking long time to get data from cloud. And observer query also delayed to get the real time data for user messages

mvishnureddy007 commented 2 months ago

@mvishnureddy007 Please update to Amplify Android 2.14.11. The last few Amplify releases have provided significant performance improvements for subscription and sync.

Please report back after updating.

After updated Amplify Android 2.14.11 also the Data store query sync is taking long time to get data from cloud. And observer query also delayed to get the real time data for user messages

mvishnureddy007 commented 2 months ago

@mvishnureddy007 Please update to Amplify Android 2.14.11. The last few Amplify releases have provided significant performance improvements for subscription and sync.

Please report back after updating.

As soon as I logged in to the app this logs I got continuously

2024-05-07 10:33:36.303 29894-30946 amplify:aws-datastore SQLCommandProcessor executeExists in 1 ms inTransaction: true SQL: SELECT EXISTS(SELECT 1 FROM ModelMetadata WHERE ModelMetadata.id = ?); 2024-05-07 10:33:36.305 29894-30946 amplify:aws-datastore V Could not find getId() on com.amplifyframework.datastore.appsync.ModelMetadata. Fallback to direct field access. 2024-05-07 10:33:36.305 29894-30946 amplify:aws-datastore V Could not find get_deleted() on com.amplifyframework.datastore.appsync.ModelMetadata. Fallback to direct field access. 2024-05-07 10:33:36.306 29894-30946 amplify:aws-datastore V Could not find get_lastChangedAt() on com.amplifyframework.datastore.appsync.ModelMetadata. Fallback to direct field access. 2024-05-07 10:33:36.306 29894-30946 amplify:aws-datastore V Could not find get_version() on com.amplifyframework.datastore.appsync.ModelMetadata. Fallback to direct field access. 2024-05-07 10:33:36.306 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = MessageRecipient|*** 2024-05-07 10:33:36.306 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = null 2024-05-07 10:33:36.306 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = * 2024-05-07 10:33:36.306 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = 2 2024-05-07 10:33:36.307 29894-30946 amplify:aws-datastore V SQLCommandProcessor execute in 1 ms inTransaction: true SQL: INSERT INTO ModelMetadata (id, _deleted, _lastChangedAt, _version) VALUES (?, ?, ?, ?) 2024-05-07 10:33:36.310 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = 8d84c7ee-041b-4fe8-b472-a6b862761396 2024-05-07 10:33:36.310 29894-30946 amplify:aws-datastore V SQLCommandProcessor executeExists in 0 ms inTransaction: true SQL: SELECT EXISTS(SELECT 1 FROM MessageRecipient WHERE MessageRecipient.id = ?); 2024-05-07 10:33:36.321 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = ***** 2024-05-07 10:33:36.321 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = 2024-03-20T06:25:53.389000000Z 2024-05-07 10:33:36.321 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = ** 2024-05-07 10:33:36.321 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = ** 2024-05-07 10:33:36.321 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = ["",""] 2024-05-07 10:33:36.322 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = null 2024-05-07 10:33:36.322 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = 2024-03-20T06:25:51.668000000Z 2024-05-07 10:33:36.322 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = READ 2024-05-07 10:33:36.322 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = 2024-03-20T06:25:53.639000000Z 2024-05-07 10:33:36.322 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = * 2024-05-07 10:33:36.322 29894-30946 amplify:aws-datastore V SQLCommandProcessor execute in 1 ms inTransaction: true SQL: INSERT INTO MessageRecipient (id, createdAt, groupId, messageId, permittedTo, readAt, sentAt, status, updatedAt, userId) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) 2024-05-07 10:33:36.325 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = 8 2024-05-07 10:33:36.325 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = ***** 2024-05-07 10:33:36.325 29894-30946 amplify:aws-datastore V SQLCommandProcessor executeExists in 0 ms inTransaction: true SQL: SELECT EXISTS(SELECT 1 FROM MessageRecipient WHERE (MessageRecipient.userId = ? AND MessageRecipient.id = ?)); 2024-05-07 10:33:36.327 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = MessageRecipient|**

Once it is finished the real time messaging and data store query is working fine with out delay

Can any once help us what is the problem? How to fix it.

mvishnureddy007 commented 2 weeks ago

@mvishnureddy007 Please update to Amplify Android 2.14.11. The last few Amplify releases have provided significant performance improvements for subscription and sync. Please report back after updating.

As soon as I logged in to the app this logs I got continuously

2024-05-07 10:33:36.303 29894-30946 amplify:aws-datastore SQLCommandProcessor executeExists in 1 ms inTransaction: true SQL: SELECT EXISTS(SELECT 1 FROM ModelMetadata WHERE ModelMetadata.id = ?); 2024-05-07 10:33:36.305 29894-30946 amplify:aws-datastore V Could not find getId() on com.amplifyframework.datastore.appsync.ModelMetadata. Fallback to direct field access. 2024-05-07 10:33:36.305 29894-30946 amplify:aws-datastore V Could not find get_deleted() on com.amplifyframework.datastore.appsync.ModelMetadata. Fallback to direct field access. 2024-05-07 10:33:36.306 29894-30946 amplify:aws-datastore V Could not find get_lastChangedAt() on com.amplifyframework.datastore.appsync.ModelMetadata. Fallback to direct field access. 2024-05-07 10:33:36.306 29894-30946 amplify:aws-datastore V Could not find get_version() on com.amplifyframework.datastore.appsync.ModelMetadata. Fallback to direct field access. 2024-05-07 10:33:36.306 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = MessageRecipient|*** 2024-05-07 10:33:36.306 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = null 2024-05-07 10:33:36.306 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = * 2024-05-07 10:33:36.306 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = 2 2024-05-07 10:33:36.307 29894-30946 amplify:aws-datastore V SQLCommandProcessor execute in 1 ms inTransaction: true SQL: INSERT INTO ModelMetadata (id, _deleted, _lastChangedAt, _version) VALUES (?, ?, ?, ?) 2024-05-07 10:33:36.310 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = 8d84c7ee-041b-4fe8-b472-a6b862761396 2024-05-07 10:33:36.310 29894-30946 amplify:aws-datastore V SQLCommandProcessor executeExists in 0 ms inTransaction: true SQL: SELECT EXISTS(SELECT 1 FROM MessageRecipient WHERE MessageRecipient.id = ?); 2024-05-07 10:33:36.321 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = ***** 2024-05-07 10:33:36.321 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = 2024-03-20T06:25:53.389000000Z 2024-05-07 10:33:36.321 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = ** 2024-05-07 10:33:36.321 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = ** 2024-05-07 10:33:36.321 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = ["",""] 2024-05-07 10:33:36.322 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = null 2024-05-07 10:33:36.322 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = 2024-03-20T06:25:51.668000000Z 2024-05-07 10:33:36.322 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = READ 2024-05-07 10:33:36.322 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = 2024-03-20T06:25:53.639000000Z 2024-05-07 10:33:36.322 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = * 2024-05-07 10:33:36.322 29894-30946 amplify:aws-datastore V SQLCommandProcessor execute in 1 ms inTransaction: true SQL: INSERT INTO MessageRecipient (id, createdAt, groupId, messageId, permittedTo, readAt, sentAt, status, updatedAt, userId) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) 2024-05-07 10:33:36.325 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = 8 2024-05-07 10:33:36.325 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = ***** 2024-05-07 10:33:36.325 29894-30946 amplify:aws-datastore V SQLCommandProcessor executeExists in 0 ms inTransaction: true SQL: SELECT EXISTS(SELECT 1 FROM MessageRecipient WHERE (MessageRecipient.userId = ? AND MessageRecipient.id = ?)); 2024-05-07 10:33:36.327 29894-30946 amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = MessageRecipient|**

Once it is finished the real time messaging and data store query is working fine with out delay

Can any once help us what is the problem? How to fix it.

Can any one reply for this issue. We are getting this issue in production and lot of users are using the application, getting this issue

mvishnureddy007 commented 2 weeks ago

@tylerjroach can you give solution for the issue? Please Because it is happening in Production Users

lawmicha commented 2 weeks ago

Hi @mvishnureddy007,

The logs don't appear to contain a specific error. Can you clarify what you mean by "once it is finished"? Are you calling DataStore.start() and then listening to the .ready event to indicate that your local database is ready to be queried?

If you can provide more information, such as code snippets of the actions you're performing and how long it takes before the query is working fine, that would help clarify the issue.

DataStore queries always return data from the local database. Even if you don't wait for the .ready event, you can query the database, but it may return a subset of data if there is more that is currently being synced down. Some developers may code against this if they need the full dataset before displaying it to their users.

You can use the observeQuery API to receive a stream of data if this fits your use case. It will provide updates as data is synced, with a field indicating whether it is in sync with your backend. You can find more details here: Observe query results in real-time.

mvishnureddy007 commented 2 weeks ago

Hi @lawmicha ,

  1. I logged into the application.
  2. I checked if an authentication session was available using Amplify.Auth.fetchAuthSession().
  3. If the authentication session was not available, I signed in using Amplify.Auth.signIn().
  4. I navigated to the chat page to view the messages. To retrieve the messages, I used the following method: Amplify.DataStore.query( Message.class, Where.matches(predicate).sorted(sortBy), response -> {}, Timber::e );
  5. Initially, I did not receive any messages. However, after 10 to 15 seconds, data started coming in from DataStore.query.
  6. As soon as I logged into the application, I observed the following logs: Logs from Amplify.addPlugin(new AndroidLoggingPlugin(LogLevel.VERBOSE)):

amplify:aws-datastore SQLCommandProcessor executeExists in 1 ms inTransaction: true SQL: SELECT EXISTS(SELECT 1 FROM ModelMetadata WHERE ModelMetadata.id = ?); amplify:aws-datastore V Could not find getId() on com.amplifyframework.datastore.appsync.ModelMetadata. Fallback to direct field access. amplify:aws-datastore V Could not find get_deleted() on com.amplifyframework.datastore.appsync.ModelMetadata. Fallback to direct field access. amplify:aws-datastore V Could not find get_lastChangedAt() on com.amplifyframework.datastore.appsync.ModelMetadata. Fallback to direct field access. amplify:aws-datastore V Could not find get_version() on com.amplifyframework.datastore.appsync.ModelMetadata. Fallback to direct field access. amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = MessageRecipient|*** amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = null amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = * amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = 2 amplify:aws-datastore V SQLCommandProcessor execute in 1 ms inTransaction: true SQL: INSERT INTO ModelMetadata (id, _deleted, _lastChangedAt, _version) VALUES (?, ?, ?, ?) amplify:aws-datastore V SQLCommandProcessor.bindValueToStatement(..., value = 8d84c7ee-041b-4fe8-b472-a6b862761396

These logs continued to print, and once this process ended, the query API worked fine and I started receiving data immediately.