aws-amplify / amplify-flutter

A declarative library with an easy-to-use interface for building Flutter applications on AWS.
https://docs.amplify.aws
Apache License 2.0
1.31k stars 243 forks source link

Android stuck on "Unauthenticated access is not supported for this identity pool" and trying to retry #3109

Closed wojciechzahradnikdeviniti closed 1 year ago

wojciechzahradnikdeviniti commented 1 year ago

Description

Hi, I have a problem on the Android platform and it is probably connected with Auth/Cognito and DataStore.

I am not logged in. My code looks like:

await Amplify.addPlugins([
    AmplifyAuthCognito(),
    AmplifyStorageS3(),
    AmplifyAPI(modelProvider: ModelProvider.instance),
    AmplifyDataStore(
      modelProvider: ModelProvider.instance,
      syncExpressions: [
        DataStoreSyncExpression(User.classType, () => User.CLIENTID.eq(clientId)),
      ],
    )
  ]);
await Amplify.configure(amplifyconfig);

My app starts:

Launching lib/main.dart on sdk gphone64 arm64 in debug mode...
✓  Built build/app/outputs/flutter-apk/app-development-debug.apk.
Connecting to VM Service at ws://127.0.0.1:63331/BG-LqeY1s0w=/ws
W/amplify:aws-datastore(14292): The doSyncRetry configuration will be deprecated in a future version. Please discontinue use of this API.
W/amplify:aws-datastore(14292): Disabling sync retries will be deprecated in a future version.
I/amplify:flutter:datastore(14292): Added Auth plugin
I/amplify:flutter:datastore(14292): Added API plugin
I/flutter (14292): Amplify configured
I/amplify:flutter:datastore(14292): Unhandled DataStoreHubEvent: SUCCEEDED
I/amplify:flutter:datastore(14292): com.amplifyframework.core.category.CategoryInitializationResult@49c4191
[log] INFO: 2023-05-26 12:21:49.733530: Full paths for routes:
        => /
        => /welcome
[log] INFO: 2023-05-26 12:21:49.740300: setting initial location /
I/amplify:aws-datastore(14292): Network available, start datastore
I/amplify:aws-datastore(14292): Orchestrator lock acquired.
I/amplify:aws-datastore(14292): DataStore plugin initialized.
I/amplify:aws-datastore(14292): Orchestrator transitioning from STOPPED to SYNC_VIA_API
I/amplify:aws-datastore(14292): Starting to observe local storage changes.
I/amplify:aws-datastore(14292): Now observing local storage. Local changes will be enqueued to mutation outbox.
I/amplify:aws-datastore(14292): Setting currentState to LOCAL_ONLY
I/amplify:aws-datastore(14292): Setting currentState to SYNC_VIA_API
I/amplify:aws-datastore(14292): Orchestrator lock released.
I/amplify:aws-datastore(14292): Starting API synchronization mode.
[log] INFO: 2023-05-26 12:21:49.956395: bloc: Created AuthBloc
[log] INFO: 2023-05-26 12:21:50.056325: bloc: Created SnackBarBloc
[log] INFO: 2023-05-26 12:21:50.068746: Using MaterialApp configuration
I/flutter (14292): HUBB: outboxStatus
I/amplify:aws-datastore(14292): Starting processing subscription events.
[log] FINER: 2023-05-26 12:21:50.891823: Opened server connection
[log] FINER: 2023-05-26 12:21:50.897833: Request sent
[log] FINER: 2023-05-26 12:21:51.056448: Received headers
[log] FINER: 2023-05-26 12:21:51.061371: Subscription canceled
[log] FINER: 2023-05-26 12:21:51.061505: Canceling request
[log] FINER: 2023-05-26 12:21:51.061694: Detaching socket
E/amplify:aws-datastore(14292): Failure encountered while attempting to start API sync.
E/amplify:aws-datastore(14292): DataStoreException{message=DataStore subscriptionProcessor failed to start., cause=DataStoreException{message=Error during subscription., cause=ApiAuthException{message=Token is null, cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Evaluate details.}, recoverySuggestion=Check your internet.}
E/amplify:aws-datastore(14292):     at com.amplifyframework.datastore.syncengine.Orchestrator.lambda$startApiSync$3$com-amplifyframework-datastore-syncengine-Orchestrator(Orchestrator.java:306)
E/amplify:aws-datastore(14292):     at com.amplifyframework.datastore.syncengine.Orchestrator$$ExternalSyntheticLambda6.subscribe(Unknown Source:2)
E/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate.subscribeActual(CompletableCreate.java:40)
E/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
E/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
E/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
E/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
E/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
E/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
E/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
E/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.internal.operators.completable.CompletableSubscribeOn$SubscribeOnObserver.run(CompletableSubscribeOn.java:64)
E/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.core.Scheduler$DisposeTask.run(Scheduler.java:614)
E/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:65)
E/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:56)
E/amplify:aws-datastore(14292):     at java.util.concurrent.FutureTask.run(FutureTask.java:264)
E/amplify:aws-datastore(14292):     at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:307)
E/amplify:aws-datastore(14292):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
E/amplify:aws-datastore(14292):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
E/amplify:aws-datastore(14292):     at java.lang.Thread.run(Thread.java:1012)
E/amplify:aws-datastore(14292): Caused by: DataStoreException{message=Error during subscription., cause=ApiAuthException{message=Token is null, cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Evaluate details.}
E/amplify:aws-datastore(14292):     at com.amplifyframework.datastore.appsync.AppSyncClient.lambda$subscription$2(AppSyncClient.java:321)
E/amplify:aws-datastore(14292):     at com.amplifyframework.datastore.appsync.AppSyncClient$$ExternalSyntheticLambda5.accept(Unknown Source:4)
E/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionOperation.lambda$start$1$com-amplifyframework-api-aws-SubscriptionOperation(SubscriptionOperation.java:87)
E/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionOperation$$ExternalSyntheticLambda3.accept(Unknown Source:4)
E/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(SubscriptionEndpoint.java:139)
E/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionOperation.lambda$start$2$com-amplifyframework-api-aws-SubscriptionOperation(SubscriptionOperation.java:77)
E/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionOperation$$ExternalSyntheticLambda0.run(Unknown Source:2)
E/amplify:aws-datastore(14292):     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:463)
E/amplify:aws-datastore(14292):     at java.util.concurrent.FutureTask.run(FutureTask.java:264)
E/amplify:aws-datastore(14292):     ... 3 more
E/amplify:aws-datastore(14292): Caused by: ApiAuthException{message=Token is null, cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}
E/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.sigv4.DefaultCognitoUserPoolsAuthProvider.fetchToken(DefaultCognitoUserPoolsAuthProvider.java:81)
E/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.sigv4.DefaultCognitoUserPoolsAuthProvider.getLatestAuthToken(DefaultCognitoUserPoolsAuthProvider.java:87)
E/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionAuthorizer.forCognitoUserPools(SubscriptionAuthorizer.java:150)
E/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionAuthorizer.createHeaders(SubscriptionAuthorizer.java:99)
E/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionAuthorizer.createHeadersForConnection(SubscriptionAuthorizer.java:74)
E/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionEndpoint.buildConnectionRequestUrl(SubscriptionEndpoint.java:311)
E/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(SubscriptionEndpoint.java:134)
E/amplify:aws-datastore(14292):     ... 7 more
W/amplify:aws-datastore(14292): API sync failed - transitioning to LOCAL_ONLY.
W/amplify:aws-datastore(14292): DataStoreException{message=DataStore subscriptionProcessor failed to start., cause=DataStoreException{message=Error during subscription., cause=ApiAuthException{message=Token is null, cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Evaluate details.}, recoverySuggestion=Check your internet.}
W/amplify:aws-datastore(14292):     at com.amplifyframework.datastore.syncengine.Orchestrator.lambda$startApiSync$3$com-amplifyframework-datastore-syncengine-Orchestrator(Orchestrator.java:306)
W/amplify:aws-datastore(14292):     at com.amplifyframework.datastore.syncengine.Orchestrator$$ExternalSyntheticLambda6.subscribe(Unknown Source:2)
W/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate.subscribeActual(CompletableCreate.java:40)
W/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
W/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
W/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
W/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
W/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
W/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
W/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
W/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.internal.operators.completable.CompletableSubscribeOn$SubscribeOnObserver.run(CompletableSubscribeOn.java:64)
W/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.core.Scheduler$DisposeTask.run(Scheduler.java:614)
W/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:65)
W/amplify:aws-datastore(14292):     at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:56)
W/amplify:aws-datastore(14292):     at java.util.concurrent.FutureTask.run(FutureTask.java:264)
W/amplify:aws-datastore(14292):     at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:307)
W/amplify:aws-datastore(14292):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
W/amplify:aws-datastore(14292):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
W/amplify:aws-datastore(14292):     at java.lang.Thread.run(Thread.java:1012)
W/amplify:aws-datastore(14292): Caused by: DataStoreException{message=Error during subscription., cause=ApiAuthException{message=Token is null, cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Evaluate details.}
W/amplify:aws-datastore(14292):     at com.amplifyframework.datastore.appsync.AppSyncClient.lambda$subscription$2(AppSyncClient.java:321)
W/amplify:aws-datastore(14292):     at com.amplifyframework.datastore.appsync.AppSyncClient$$ExternalSyntheticLambda5.accept(Unknown Source:4)
W/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionOperation.lambda$start$1$com-amplifyframework-api-aws-SubscriptionOperation(SubscriptionOperation.java:87)
W/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionOperation$$ExternalSyntheticLambda3.accept(Unknown Source:4)
W/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(SubscriptionEndpoint.java:139)
W/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionOperation.lambda$start$2$com-amplifyframework-api-aws-SubscriptionOperation(SubscriptionOperation.java:77)
W/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionOperation$$ExternalSyntheticLambda0.run(Unknown Source:2)
W/amplify:aws-datastore(14292):     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:463)
W/amplify:aws-datastore(14292):     at java.util.concurrent.FutureTask.run(FutureTask.java:264)
W/amplify:aws-datastore(14292):     ... 3 more
W/amplify:aws-datastore(14292): Caused by: ApiAuthException{message=Token is null, cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}
W/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.sigv4.DefaultCognitoUserPoolsAuthProvider.fetchToken(DefaultCognitoUserPoolsAuthProvider.java:81)
W/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.sigv4.DefaultCognitoUserPoolsAuthProvider.getLatestAuthToken(DefaultCognitoUserPoolsAuthProvider.java:87)
W/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionAuthorizer.forCognitoUserPools(SubscriptionAuthorizer.java:150)
W/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionAuthorizer.createHeaders(SubscriptionAuthorizer.java:99)
W/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionAuthorizer.createHeadersForConnection(SubscriptionAuthorizer.java:74)
W/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionEndpoint.buildConnectionRequestUrl(SubscriptionEndpoint.java:311)
W/amplify:aws-datastore(14292):     at com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(SubscriptionEndpoint.java:134)
W/amplify:aws-datastore(14292):     ... 7 more
I/amplify:aws-datastore(14292): Orchestrator transitioning from SYNC_VIA_API to LOCAL_ONLY
I/amplify:aws-datastore(14292): Setting currentState to LOCAL_ONLY
I/amplify:aws-datastore(14292): Stopping subscription processor.
I/amplify:aws-datastore(14292): Stopped subscription processor.
I/flutter (14292): HUBB: networkStatus
I/flutter (14292): HUBB: networkStatus false

and then my Auth module stuck because it's trying to connect/reconnect to Cognito so I am receiving:

[log] FINER: 2023-05-26 12:21:51.541213: Opened server connection
[log] FINER: 2023-05-26 12:21:51.541915: Request sent
[log] FINER: 2023-05-26 12:21:51.692247: Received headers
[log] FINER: 2023-05-26 12:21:51.692708: Subscription canceled
[log] FINER: 2023-05-26 12:21:51.692777: Canceling request
[log] FINER: 2023-05-26 12:21:51.692820: Detaching socket
[log] FINER: 2023-05-26 12:21:52.126202: Opened server connection
[log] FINER: 2023-05-26 12:21:52.126701: Request sent
[log] FINER: 2023-05-26 12:21:52.280358: Received headers
[log] FINER: 2023-05-26 12:21:52.280826: Subscription canceled
[log] FINER: 2023-05-26 12:21:52.281159: Canceling request
[log] FINER: 2023-05-26 12:21:52.281288: Detaching socket
[log] FINER: 2023-05-26 12:21:53.343802: Opened server connection
[log] FINER: 2023-05-26 12:21:53.344787: Request sent
[log] FINER: 2023-05-26 12:21:53.509521: Received headers
[log] FINER: 2023-05-26 12:21:53.510054: Subscription canceled
[log] FINER: 2023-05-26 12:21:53.510512: Canceling request
[log] FINER: 2023-05-26 12:21:53.510575: Detaching socket
[log] FINER: 2023-05-26 12:21:53.965582: Opened server connection
[log] FINER: 2023-05-26 12:21:53.967231: Request sent
[log] FINER: 2023-05-26 12:21:54.119830: Received headers
[log] FINER: 2023-05-26 12:21:54.120327: Subscription canceled
[log] FINER: 2023-05-26 12:21:54.120397: Canceling request
[log] FINER: 2023-05-26 12:21:54.120448: Detaching socket
[log] FINER: 2023-05-26 12:21:54.561420: Opened server connection
[log] FINER: 2023-05-26 12:21:54.562490: Request sent
[log] FINER: 2023-05-26 12:21:54.713442: Received headers
[log] FINER: 2023-05-26 12:21:54.715486: Subscription canceled
[log] FINER: 2023-05-26 12:21:54.715684: Canceling request
[log] FINER: 2023-05-26 12:21:54.715794: Detaching socket
[log] FINER: 2023-05-26 12:21:55.193070: Opened server connection
[log] FINER: 2023-05-26 12:21:55.198652: Request sent
[log] FINER: 2023-05-26 12:21:55.360084: Received headers
[log] FINER: 2023-05-26 12:21:55.361165: Subscription canceled
[log] FINER: 2023-05-26 12:21:55.361419: Canceling request
[log] FINER: 2023-05-26 12:21:55.361531: Detaching socket

and it takes about 2/3 minutes when it releases Auth module. During that time I cannot check if user is logged in/sign up/in etc. After that time it works fine. When I am logged in it also works fine. The problem is with unauthenticated user.

Categories

Steps to Reproduce

No response

Screenshots

image image image image image

Platforms

Flutter Version

3.10.1

Amplify Flutter Version

1.1.0

Deployment Method

Amplify CLI

Schema

type User @model @auth(rules: [{ allow: private }, { allow: private, provider: iam }]) {
  id: ID!
  firstName: String!
  lastName: String!
}
Equartey commented 1 year ago

Hey @wojciechzahradnikdeviniti

Sorry you are having this issue.

  1. Can you provide more context on what you mean by "Auth module stuck"? What operation are you trying to perform?
  2. Can you also provide relevant code snippets from your auth module?
  3. Did you setup your auth plugin through Amplify CLI?
  4. Does your auth setup use any custom config?
wojciechzahradnikdeviniti commented 1 year ago

Hi @Equartey

Thanks for the answer.

  1. I mean that this retry problem block other Auth functions for example await Amplify.Auth.fetchAuthSession(), await Amplify.Auth.getCurrentUser() or even await Amplify.Auth.signIn so I need to wait for it to finish retrying.

  2. When I open the app I want to check if user is signed in so I call this function, but I cannot, it gets stuck on line final result = await Amplify.Auth.fetchAuthSession(); referring to problem I described in this issue

    Future<bool> isUserSignedIn() async {
    try {
      final result = await Amplify.Auth.fetchAuthSession();
      return result.isSignedIn;
    } catch (_) {
      return false;
    }
    }
  3. No, it was configured already. I only pulled existing config.

  4. My config

    "api": {
        "plugins": {
            "awsAPIPlugin": {
                "AdminQueries": {
                    "endpointType": "REST",
                    "endpoint": "https://xxx.execute-api.xxx.amazonaws.com/xxx",
                    "region": "xxx",
                    "authorizationType": "AMAZON_COGNITO_USER_POOLS"
                },
                "elitecontractorweb": {
                    "endpointType": "GraphQL",
                    "endpoint": "https://xxx.appsync-api.xxx.amazonaws.com/graphql",
                    "region": "xxx",
                    "authorizationType": "AMAZON_COGNITO_USER_POOLS"
                }
            }
        }
    },
    "auth": {
        "plugins": {
            "awsCognitoAuthPlugin": {
                "UserAgent": "aws-amplify-cli/0.1.0",
                "Version": "0.1.0",
                "IdentityManager": {
                    "Default": {}
                },
                "AppSync": {
                    "Default": {
                        "ApiUrl": "https://xxx.appsync-api.xxx.amazonaws.com/graphql",
                        "Region": "xxx,
                        "AuthMode": "AMAZON_COGNITO_USER_POOLS",
                        "ClientDatabasePrefix": "xxx_AMAZON_COGNITO_USER_POOLS"
                    },
                    "elitecontractorweb_AWS_IAM": {
                        "ApiUrl": "https://xxx.appsync-api.xxx.amazonaws.com/graphql",
                        "Region": "xxx",
                        "AuthMode": "AWS_IAM",
                        "ClientDatabasePrefix": "xxx_AWS_IAM"
                    }
                },
                "CredentialsProvider": {
                    "CognitoIdentity": {
                        "Default": {
                            "PoolId": "xxx",
                            "Region": "xxx"
                        }
                    }
                },
                "CognitoUserPool": {
                    "Default": {
                        "PoolId": "xxx",
                        "AppClientId": "xxx",
                        "Region": "xxx"
                    }
                },
                "Auth": {
                    "Default": {
                        "authenticationFlowType": "USER_SRP_AUTH",
                        "mfaConfiguration": "OFF",
                        "mfaTypes": [
                            "SMS"
                        ],
                        "passwordProtectionSettings": {
                            "passwordPolicyMinLength": 8,
                            "passwordPolicyCharacters": []
                        },
                        "signupAttributes": [
                            "EMAIL"
                        ],
                        "socialProviders": [],
                        "usernameAttributes": [
                            "EMAIL"
                        ],
                        "verificationMechanisms": [
                            "EMAIL"
                        ]
                    }
                },
                "S3TransferUtility": {
                    "Default": {
                        "Bucket": "xxx",
                        "Region": "xxx"
                    }
                }
            }
        }
    },

There are few more screens: image image image image image image

Equartey commented 1 year ago

Hey @wojciechzahradnikdeviniti

Thanks for providing more context.

The DataStore error is expected as an unauthorized user. After the user has signed in, calling Amplify.DataStore.start() can restart the service.

Still working on reproducing your reconnection issue.

The auth blocking behavior is expected, but not the duration it's locking up.

  1. Are you calling these auth functions multiple times, or multiple at a time?
  2. Can you provide more of your own code to help me understand your work flow?
wojciechzahradnikdeviniti commented 1 year ago

@Equartey Yes, when I am signed in then the problem does not occur. But I still have a problem with an unauthorized user.

  1. Only once but basically you don't need to call any of those functions to get this problem. You need to check "All exceptions" in breakpoints (if you're using VS code) in debug mode and then this error will be catched.

  2. I'm not doing anything special. Below I prepared a sample code without any Auth function. It's not working as well. This problem appears after await Amplify.configure(amplifyconfig);

class MyApp extends StatefulWidget {
  const MyApp({Key? key}) : super(key: key);

  @override
  State<MyApp> createState() => _MyAppState();
}

class _MyAppState extends State<MyApp> {

  @override
  void initState() {
    super.initState();
    RoutingConfig.defineRoutes(router);
    _configureAmplify();
  }

  @override
  Widget build(BuildContext context) {
    return Authenticator(
      child: MaterialApp(
        onGenerateRoute: router.generator,
        builder: Authenticator.builder(),
        title: 'My App',
        debugShowCheckedModeBanner: false,
        theme: ThemeData(
          primarySwatch: primaryPallette,
          canvasColor: Colors.white,
          brightness: Brightness.light,
          useMaterial3: true,
        ),
        home: datastoreReady
            ? DashboardPage()
            : Center(
                child: CircularProgressIndicator(),
              ),
      ),
    );
  }
}
Future _configureAmplify() async {
  await Amplify.addPlugins([
    AmplifyAuthCognito(),
    AmplifyStorageS3(),
    AmplifyAPI(modelProvider: ModelProvider.instance),
    AmplifyDataStore(
      modelProvider: ModelProvider.instance,
      syncExpressions: [
        DataStoreSyncExpression(User.classType, () => User.CLIENTID.eq(clientId)),
      ],
    )
  ]);
  try {
    await Amplify.configure(amplifyconfig);
    listenForAuthChanges();
  } on AmplifyAlreadyConfiguredException {
    if (kDebugMode) {
      print(
          "Tried to reconfigure Amplify; this can occur when your app restarts on Android. ==========================================================================================================================================================================================================================");
    }
    datastoreReady = true;
  } on Exception {
    if (kDebugMode) {
      print(
          "Exception here ================================================================================================================.");
    }
  }
}
StreamSubscription<AuthHubEvent> listenForAuthChanges() {
  Amplify.Hub.listen(HubChannel.DataStore, (event) {
    safePrint('DataStore is ready not: ${event.eventName}');
    switch (event.eventName) {
      case 'ready':
        safePrint('DataStore is ready');

        datastoreReady = true;

        break;
    }
  });

}
Equartey commented 1 year ago

Hey @wojciechzahradnikdeviniti

Thanks for providing the code snippet. I think we're getting closer here.

I could not see the exact issue you're describing, but there are some issues I noticed with your sample code. If these are present in your actual app, please update them and report back your findings.

  1. Make sure any changes to the state that should trigger an update to the UI are wrapped in setState(() {...}). For example, when you call datastoreReady = true; instead use setState(() { datastoreReady = true; });. This will cause the UI to update when the variable is changed, in this case resulting in the loading indicator to be removed and your dashboard to appear.
  2. I noticed when starting the sample app signed out and then signing in, DataStore needs to be restarted. This can be achieved via the Hub:
    Amplify.Hub.listen(HubChannel.Auth, (event) {
    if (event.type == AuthHubEventType.signedIn) {
    Amplify.DataStore.start();
    }
    });

Between these two changes, I could achieve a smooth flow through the app. If you see differently, please don't hesitate to respond with additional context and code snippets!

wojciechzahradnikdeviniti commented 1 year ago

Hey @Equartey

Thanks for advices but probably you still don't understand where the problem is. I have a problem when I start the app and when the user is NOT logged in. It does not depend on datastoreReady state or event.type == AuthHubEventType.signedIn. When I have code like this problem also appears:

class MyApp extends StatefulWidget {
  const MyApp({Key? key}) : super(key: key);

  @override
  State<MyApp> createState() => _MyAppState();
}

class _MyAppState extends State<MyApp> with WidgetsBindingObserver {
  AuthService authService = Get.put(AuthService());

  @override
  void initState() {
    super.initState();
    RoutingConfig.defineRoutes(router);
    _configureAmplify();
  }

  @override
  Widget build(BuildContext context) {
    return Authenticator(
      child: MaterialApp(
        onGenerateRoute: router.generator,
        builder: Authenticator.builder(),
        title: 'My App',
        debugShowCheckedModeBanner: false,
        theme: ThemeData(
          primarySwatch: primaryPallette,
          canvasColor: Colors.white,
          brightness: Brightness.light,
          useMaterial3: true,
        ),
      ),
    );
  }
}
Future _configureAmplify() async {
  await Amplify.addPlugins([
    AmplifyAuthCognito(),
    AmplifyStorageS3(),
    AmplifyAPI(modelProvider: ModelProvider.instance),
    AmplifyDataStore(
      modelProvider: ModelProvider.instance,
      syncExpressions: [
        DataStoreSyncExpression(User.classType, () => User.CLIENTID.eq(clientId)),
      ],
    )
  ]);
  try {
    await Amplify.configure(amplifyconfig);
  } catch (e) {
    print("Exception $e");
  }
}

I mean that this is probably the problem with Cognito, API & DataStore modules working together.

Flow:

  1. Open the app with the fresh install on Android

  2. Amplify configure await Amplify.configure(amplifyconfig); image

  3. After configure those logs appears:

    I/amplify:aws-datastore( 7323): Creating table: User
    I/amplify:aws-datastore( 7323): Creating index for table: User
    I/amplify:flutter:datastore( 7323): Unhandled DataStoreHubEvent: SUCCEEDED
    I/amplify:flutter:datastore( 7323): com.amplifyframework.core.category.CategoryInitializationResult@1c8822f
    I/amplify:aws-datastore( 7323): Network available, start datastore
    I/amplify:aws-datastore( 7323): Orchestrator lock acquired.
    I/amplify:aws-datastore( 7323): DataStore plugin initialized.
    I/amplify:aws-datastore( 7323): Orchestrator transitioning from STOPPED to SYNC_VIA_API
    I/amplify:aws-datastore( 7323): Starting to observe local storage changes.
    I/amplify:aws-datastore( 7323): Now observing local storage. Local changes will be enqueued to mutation outbox.
    I/amplify:aws-datastore( 7323): Setting currentState to LOCAL_ONLY
    I/amplify:aws-datastore( 7323): Setting currentState to SYNC_VIA_API
    I/amplify:aws-datastore( 7323): Orchestrator lock released.
    I/amplify:aws-datastore( 7323): Starting API synchronization mode.
    I/amplify:aws-datastore( 7323): Starting processing subscription events.
    D/EGL_emulation( 7323): app_time_stats: avg=19.56ms min=3.28ms max=124.86ms count=51
    E/amplify:aws-datastore( 7323): Failure encountered while attempting to start API sync.
    E/amplify:aws-datastore( 7323): DataStoreException{message=DataStore subscriptionProcessor failed to start., cause=DataStoreException{message=Error during subscription., cause=ApiAuthException{message=Token is null, cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Evaluate details.}, recoverySuggestion=Check your internet.}
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.datastore.syncengine.Orchestrator.lambda$startApiSync$3$com-amplifyframework-datastore-syncengine-Orchestrator(Orchestrator.java:306)
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.datastore.syncengine.Orchestrator$$ExternalSyntheticLambda6.subscribe(Unknown Source:2)
    E/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate.subscribeActual(CompletableCreate.java:40)
    E/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
    E/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
    E/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
    E/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
    E/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
    E/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
    E/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
    E/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.internal.operators.completable.CompletableSubscribeOn$SubscribeOnObserver.run(CompletableSubscribeOn.java:64)
    E/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.core.Scheduler$DisposeTask.run(Scheduler.java:614)
    E/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:65)
    E/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:56)
    E/amplify:aws-datastore( 7323):     at java.util.concurrent.FutureTask.run(FutureTask.java:264)
    E/amplify:aws-datastore( 7323):     at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:307)
    E/amplify:aws-datastore( 7323):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
    E/amplify:aws-datastore( 7323):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
    E/amplify:aws-datastore( 7323):     at java.lang.Thread.run(Thread.java:1012)
    E/amplify:aws-datastore( 7323): Caused by: DataStoreException{message=Error during subscription., cause=ApiAuthException{message=Token is null, cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Evaluate details.}
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.datastore.appsync.AppSyncClient.lambda$subscription$2(AppSyncClient.java:321)
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.datastore.appsync.AppSyncClient$$ExternalSyntheticLambda5.accept(Unknown Source:4)
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionOperation.lambda$start$1$com-amplifyframework-api-aws-SubscriptionOperation(SubscriptionOperation.java:87)
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionOperation$$ExternalSyntheticLambda3.accept(Unknown Source:4)
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(SubscriptionEndpoint.java:139)
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionOperation.lambda$start$2$com-amplifyframework-api-aws-SubscriptionOperation(SubscriptionOperation.java:77)
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionOperation$$ExternalSyntheticLambda0.run(Unknown Source:2)
    E/amplify:aws-datastore( 7323):     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:463)
    E/amplify:aws-datastore( 7323):     at java.util.concurrent.FutureTask.run(FutureTask.java:264)
    E/amplify:aws-datastore( 7323):     ... 3 more
    E/amplify:aws-datastore( 7323): Caused by: ApiAuthException{message=Token is null, cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.sigv4.DefaultCognitoUserPoolsAuthProvider.fetchToken(DefaultCognitoUserPoolsAuthProvider.java:81)
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.sigv4.DefaultCognitoUserPoolsAuthProvider.getLatestAuthToken(DefaultCognitoUserPoolsAuthProvider.java:87)
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionAuthorizer.forCognitoUserPools(SubscriptionAuthorizer.java:150)
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionAuthorizer.createHeaders(SubscriptionAuthorizer.java:99)
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionAuthorizer.createHeadersForConnection(SubscriptionAuthorizer.java:74)
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionEndpoint.buildConnectionRequestUrl(SubscriptionEndpoint.java:311)
    E/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(SubscriptionEndpoint.java:134)
    E/amplify:aws-datastore( 7323):     ... 7 more
    W/amplify:aws-datastore( 7323): API sync failed - transitioning to LOCAL_ONLY.
    W/amplify:aws-datastore( 7323): DataStoreException{message=DataStore subscriptionProcessor failed to start., cause=DataStoreException{message=Error during subscription., cause=ApiAuthException{message=Token is null, cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Evaluate details.}, recoverySuggestion=Check your internet.}
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.datastore.syncengine.Orchestrator.lambda$startApiSync$3$com-amplifyframework-datastore-syncengine-Orchestrator(Orchestrator.java:306)
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.datastore.syncengine.Orchestrator$$ExternalSyntheticLambda6.subscribe(Unknown Source:2)
    W/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate.subscribeActual(CompletableCreate.java:40)
    W/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
    W/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
    W/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
    W/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
    W/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
    W/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.internal.operators.completable.CompletablePeek.subscribeActual(CompletablePeek.java:51)
    W/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2850)
    W/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.internal.operators.completable.CompletableSubscribeOn$SubscribeOnObserver.run(CompletableSubscribeOn.java:64)
    W/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.core.Scheduler$DisposeTask.run(Scheduler.java:614)
    W/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:65)
    W/amplify:aws-datastore( 7323):     at io.reactivex.rxjava3.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:56)
    W/amplify:aws-datastore( 7323):     at java.util.concurrent.FutureTask.run(FutureTask.java:264)
    W/amplify:aws-datastore( 7323):     at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:307)
    W/amplify:aws-datastore( 7323):     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
    W/amplify:aws-datastore( 7323):     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
    W/amplify:aws-datastore( 7323):     at java.lang.Thread.run(Thread.java:1012)
    W/amplify:aws-datastore( 7323): Caused by: DataStoreException{message=Error during subscription., cause=ApiAuthException{message=Token is null, cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}, recoverySuggestion=Evaluate details.}
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.datastore.appsync.AppSyncClient.lambda$subscription$2(AppSyncClient.java:321)
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.datastore.appsync.AppSyncClient$$ExternalSyntheticLambda5.accept(Unknown Source:4)
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionOperation.lambda$start$1$com-amplifyframework-api-aws-SubscriptionOperation(SubscriptionOperation.java:87)
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionOperation$$ExternalSyntheticLambda3.accept(Unknown Source:4)
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(SubscriptionEndpoint.java:139)
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionOperation.lambda$start$2$com-amplifyframework-api-aws-SubscriptionOperation(SubscriptionOperation.java:77)
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionOperation$$ExternalSyntheticLambda0.run(Unknown Source:2)
    W/amplify:aws-datastore( 7323):     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:463)
    W/amplify:aws-datastore( 7323):     at java.util.concurrent.FutureTask.run(FutureTask.java:264)
    W/amplify:aws-datastore( 7323):     ... 3 more
    W/amplify:aws-datastore( 7323): Caused by: ApiAuthException{message=Token is null, cause=null, recoverySuggestion=Sorry, we don't have a suggested fix for this error yet.}
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.sigv4.DefaultCognitoUserPoolsAuthProvider.fetchToken(DefaultCognitoUserPoolsAuthProvider.java:81)
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.sigv4.DefaultCognitoUserPoolsAuthProvider.getLatestAuthToken(DefaultCognitoUserPoolsAuthProvider.java:87)
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionAuthorizer.forCognitoUserPools(SubscriptionAuthorizer.java:150)
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionAuthorizer.createHeaders(SubscriptionAuthorizer.java:99)
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionAuthorizer.createHeadersForConnection(SubscriptionAuthorizer.java:74)
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionEndpoint.buildConnectionRequestUrl(SubscriptionEndpoint.java:311)
    W/amplify:aws-datastore( 7323):     at com.amplifyframework.api.aws.SubscriptionEndpoint.requestSubscription(SubscriptionEndpoint.java:134)
    W/amplify:aws-datastore( 7323):     ... 7 more
    I/amplify:aws-datastore( 7323): Orchestrator transitioning from SYNC_VIA_API to LOCAL_ONLY
    I/amplify:aws-datastore( 7323): Setting currentState to LOCAL_ONLY
    I/amplify:aws-datastore( 7323): Stopping subscription processor.
    I/amplify:aws-datastore( 7323): Stopped subscription processor.
  4. After that the described problem appears. As I said in previous posts, Auth module is trying to retry auth session for about 2/3 minutes and during this time I cant do anything with Amplify.Auth functions (calling await on those functions is waiting to the end of retrying problem) image image image image

wojciechzahradnikdeviniti commented 1 year ago

Hi, any updates on this issue?

dnys1 commented 1 year ago

Hi @wojciechzahradnikdeviniti, the only way I'm able to reproduce this sort of issue is by disabling my network which causes the fetchAuthSession calls to timeout (and that does take a while).

Could this be a network issue? On even a modest network connection, I see DataStore startup failing within under 10 seconds and my manual calls to fetchAuthSession failing shortly after. I'm not able to recreate startups >10 seconds without severely restricting my internet connection.

It is true that DataStore itself is calling fetchAuthSession behind the scenes and that calls to any Amplify.Auth.X methods are queued (meaning only one can happen at a time).

wojciechzahradnikdeviniti commented 1 year ago

I don't think so. My internet connection is ok, other things are working fine.

alex-yaya commented 1 year ago

Hi Guys. Any update on this issue?

Equartey commented 1 year ago

Hey @alex-yaya

Since we haven't been able to reproduce this issue, there aren't any meaningful updates to provide here.

If you're having the same issue or something similar, please open a new issue and provide detailed reproduction steps.

dnys1 commented 1 year ago

Closing this as we were unable to reproduce. Please feel free to open a new issue if you continue to experience this issue.