When I launch the app while the wifi is turned OFF, and turn ON the wifi, an unauthorized log message displayed

[medhatIbsais-Harri]

Describe the bug

When I launch the app while the wifi is turned OFF, and turn ON the wifi while I’m inside the app, an unauthorized log message displayed.

Steps To Reproduce

1. turn the wifi OFF
2. launch your app
3. turn the wifi ON
4. the data store will not sync and an unauthorized message will be displayed in XCode logs

Expected behavior

To start syncing data normally

Amplify Framework Version

1.28.0

Amplify Categories

DataStore

Dependency manager

Cocoapods

Swift version

5.0

CLI version

Not Installed

Xcode version

13.3.1

Relevant log output

2022-09-20 12:10:18.059065+0300 TeamHub Pro[316:4831] ConnectionProviderError.unauthorized
2022-09-20 12:10:18.059377+0300 TeamHub Pro[316:4831] ConnectionProviderError.unauthorized
2022-09-20 12:10:18.059522+0300 TeamHub Pro[316:4831] ConnectionProviderError.unauthorized
2022-09-20 12:10:18.070895+0300 TeamHub Pro[316:4831] [AWSModelReconciliationQueue] receiveCompletion: error: DataStoreError: Subscription item event failed with error: Unauthorized
Caused by:
APIError: Subscription item event failed with error: Unauthorized
Caused by:
unauthorized
2022-09-20 12:10:18.075637+0300 TeamHub Pro[316:4857] [AWSDataStorePlugin] StorageEngine completed with error: DataStoreError: Subscription item event failed with error: Unauthorized
Caused by:
DataStoreError: Subscription item event failed with error: Unauthorized
Caused by:
APIError: Subscription item event failed with error: Unauthorized
Caused by:
unauthorized

Is this a regression?

Yes

Regression additional context

No response

Device

iPad 5th generation

iOS Version

15.5

Specific to simulators

No response

Additional context

No response

[atierian]

Thanks for opening this issue @medhatIbsais-Harri. I see you opened a similar issue #2167, and that we're tracking this here #2152 as well.

The main difference here is that the app is launched without network connectivity then toggled on, which is resulting in an unauthorized error. Whereas in your previous issue, the app was launched with network connectivity, then turned off, then on again. Is that correct?

[medhatIbsais-Harri]

@atierian Yes, that is correct

[atierian]

Thanks for confirming. We'll investigate and come back to you here with any updates.

[medhatIbsais-Harri]

@atierian Thank you

[chrisbonifacio]

@medhatIbsais-Harri could you share your GraphQL schema, appsync authorization types, and whether multi auth is enabled in your datastore config so that we can reproduce the issue with the same setup?

[medhatIbsais-Harri]

Hello @chrisbonifacio, thanks for responding, I'm working at Harri and we have an enterprise account on AWS, can you get the info from the system or should I open a support ticket on AWS?

[lawmicha]

Hi @medhatIbsais-Harri, please go ahead and open a support ticket, thank you!

[medhatIbsais-Harri]

Hello @lawmicha, just to follow up, I have opened a support ticket, and this is the case ID: 10874796681

[manaswi223]

Hello @medhatIbsais-Harri 👋🏼, thank you for opening the support ticket! I'm actively trying to reproduce the issue with your given schema.graphql. Will contact you with few questions I have :) Appreciate your patience.

[lawmicha]

Hi @medhatIbsais-Harri, please check the updated support ticket, i'll add some info here publiclly with the schema details redacted, feel free to update us here or there. There are two logging contexts that may be helpful to debug, please use the latest v1 branch https://github.com/aws-amplify/amplify-swift/tree/v1 which contains the unreleased version of 1.28.2, or the unstable build "v1.28.2-unstable.12", or 2.0.0 (https://github.com/aws-amplify/amplify-swift/releases/tag/v2.0.0) v2.0.0 contains API breaking changes and all APIs have been replaced with Swift’s Async/Await structured concurrency. These versions of the library have the following logging contexts: “InitializeSubscription” and “Lifecycle”.

Without dealing with network connectivity issues, please ensure that the app can successfully establish the subscriptions. Unauthorized is expected when the user is signed out. By signing in the user and calling DataStore.start, DataStore should successfully establish the subscriptions. If you can test the app without network connectivity scenarios, are you able to successfully start DataStore? The “InitializeSubscription” logs should show that the subscriptions are connected and moving onto “performInitialSync”

We attempted to reproduce network connectivity issue and were able to get back

APIError: Subscription item event failed with error
Caused by: connection

This is expected since network connectivity issues causes the websocket connections to break and puts DataStore into a stopped state. The system will eventually recover when any of the DataStore operations kick off the sync process, the logs to watch out for while debugging should be the “Lifecycle event” such as

[RemoteSyncEngine] [Lifecycle event 1]: subscriptionsEstablished
[AWSInitialSyncOrchestrator] [Lifecycle event 2]: syncQueriesStarted
[ModelSyncedEventEmitter] [Lifecycle event 3]: modelSyncedEvent model: [ModelName]
[SyncEventEmitter] [Lifecycle event 3]: modelSyncedReceived progress: 1/[total number of models]
[SyncEventEmitter] [Lifecycle event 3]: modelSyncedReceived progress: 2/[total number of models]
[AWSDataStorePlugin] [Lifecycle event 4]: syncQueriesReady
[RemoteSyncEngine] [Lifecycle event 5]: syncStarted
[AWSDataStorePlugin] [Lifecycle event 6]: ready

You can additionally use the Hub to react to these events if you are looking to hook logic into your app that depends on a particular model to be fully synchronized or for when DataStore is ready (https://docs.amplify.aws/lib/datastore/datastore-events/q/platform/ios/)

I'm looking to consolidate that issues that you have raised in this repo:

• Error happened when I return back from offline mode and turn on the wifi, Also a crash happened if I restarted the data store again #2167 stop start crashes the app
• When return back online multiple mutations sent to AppSync #2235 question about dedupping mutation events
• When I launch the app while the wifi is turned OFF, and turn ON the wifi, an unauthorized log message displayed  #2323 network connectivity issue
• DataStore does not restart after toggle airplane mode off and on #2152 DataStore improvement on handling network connectivity changes

[lawmicha]

without network connectivity then toggled on, which is resulting in an unauthorized error

@manaswi223 let's try this out as well. if there's no network, and launching the app (assuming DataStore.start is called) then the subscription connection shouldn't be able to be established, are we able to reproduce this to get Unauthorized?

Unauthorized from the subscription can happen in two places, if the token cannot be retrieved, then the subscription request fails fast and returns an Unauthorized sourced from the client or If the token can be retrieved but the request is determined to be Unauthorized by AppSync.

[medhatIbsais-Harri]

Hello @lawmicha, thanks for helping us here,
for the problem of unauthorized, we decided to refresh our tokens once the network connection is back, because the token expires every one hour,
for the second problem, that the amplify doesn’t start the syncing process automatically when the connection goes back again, the problem is still happening on the new version, and for this comment "https://github.com/aws-amplify/amplify-swift/issues/2323#issuecomment-1289605889 ", none of the hub events are being received, and calling start data store alone will not solve the problem, I had to call "Stop data store" then "Start data store" to initiate the syncing process again

[lawmicha]

Hi @medhatIbsais-Harri , can you clarify how you are refreshing the tokens when the network connection is back? Are you reacting to Network Framework events then calling Amplify.Auth APIs?

For the second problem, I believe this is the current behavior of DataStore, it is not reacting to the connection going back up again so there is a delayed recovery of data synchronization. I don't believe there is a data issue here, however eventual / delayed synchronization of data, and a clear feature request we'd like to tackle. If you could share some of the code snippets you are doing to achieve what you want, we can take a look to see how we can better optimize the system or further explore whether there's a bug in the system.

[medhatIbsais-Harri]

Hello @lawmicha, this code snippet we added to avoid the unauthorized error until you solve this problem, so as you can see in the code below, we refresh our token, and then sync data store by calling, Amplify.DataStore.start, then Amplify.DataStore.stop, and finally Amplify.DataStore.start, thats the workaround to force starting the datastore, the refreshIDToken method uses Amplify.Auth.fetchAuthSession

             `if notifictaion.name == NSNotification.Name(rawValue: NetworkingManagerNotifications.connectedToInternet.rawValue {
                
                // Refresh Token
                self.refreshIDToken { _ in
                    self.status = Status.syncWillStart
    
                    // Sync data store
                    self.syncDataStore { }
                }
            }`

[lawmicha]

Thanks for the code snippet, I believe what you are doing is optimistically restarting the sync process whenever the app detects that its connected to the internet. Once the PR is merged, you can update the code in syncDataStore back to calling stop then start. In regards to DataStore listening to network events and taking similar actions to what you are doing in your code snippet will be a much larger effort. Currently, developer shouldn't need to restart the sync process and data will be retrieved eventually on any of the subsequent DataStore API calls. Do you find that the code snippet is required for your app use cases? Are you facing any other problems w/ this or other Amplify related APIs?

[medhatIbsais-Harri]

Hi @lawmicha, the above code snippet that is responsible for refreshing the ID tokens, and thats for to avoid the unauthorized error that it returns when you launch the app without network connectivity and then turn ON the wifi, so when you fix this problem we can remove the refreshing the ID tokens when the network connection is back again.
its good to mention that the access token expiration time is one hour, so if the app remains offline more that one hour, in this case the access token is expired so after returning back online we have to refresh it again, otherwise the DataStore will keeps returning unauthorized error in the logs

[lawmicha]

Thank you for providing us the details of your use case. DataStore relies on the Auth plugin to provide the auth info when making requests to AppSync. When the access to the GraphQL model's is controlled by OIDC/Cognito User Pool auth then DataStore will retrieve the auth token from Auth plugin, and add that to the request to AppSync. For Cognito User Pool, by default it will use the access token.

We should be able to test by waiting for the access token to expire, and then call DataStore.start() (or perhaps we can modify the token expiry time at runtime in a testing context or configure the token to be vended with a very short duration, and then directly make a request to the AppSync APIs, such as a subscription request or a syncQuery or mutation request, using Amplify.API plugin). When a token expires, the API call should return unauthorized.

I think DataStore can pre-emptively refresh the session during the sync process by calling fetchAuthSession. I'm assuming this is a low-cost API to call, such that if the session is valid, it will just return the session. However, if the requests are still unauthorized, it may be the scenario where the user is actually not authorized to access that data. They may be a guest user or the model's access control does not allow read operation. Before doing this, I need a better understanding of ID Token and access token, what is the expected behavior of the Auth plugin? Shouldn't the access token be refreshed automatically?

cc @royjit - when the access token expires after 1 hr, how to refresh it or how does it get refreshed? Are developers expected to refresh the access token themselves?

[medhatIbsais-Harri]

Hi @lawmicha, if the access token expired and then I tried to call the DataStore.start() it keeps sending me unauthorized error in the logs, even if you call it multiple times, until I refresh it my self.

waiting for @royjit answer for your question.

[royjit]

Auth plugin should automatically refresh the token when it is expired as along as the refresh token is valid. If the refresh token is not valid, auth plugin will return a sessionExpired error and the user needs to signIn again.
From the code snippet above, you are using fetchAuthSession to refresh the id token, which is the same method DataStore should use to get the tokens.

[medhatIbsais-Harri]

Thank you @royjit, but the DataStore doesn’t automatically refresh the tokens, each time you call DataStore.start you will receive unauthorized error in the logs

[lawmicha]

Hi @medhatIbsais-Harri, can you clarify, each time DataStore.start is called, do you mean after waiting 1 hour for the access token to expire, then call DataStore.start it will get unauthorized?

[medhatIbsais-Harri]

Hi @lawmicha, Yes exactly.

[lawmicha]

@medhatIbsais-Harri, how are you setting up your auth provider? are you using OIDC provider and providing your own getToken method? or using the default Cognito User Pool provider? I'm trying to narrow down the auth setup to accurately reproduce this. I believe the exact code to debug into is at this line: https://github.com/aws-amplify/amplify-swift/blob/v1/AmplifyPlugins/DataStore/AWSDataStoreCategoryPlugin/Sync/SubscriptionSync/IncomingAsyncSubscriptionEventPublisher.swift#L206-L214

If we wait an hour for the access token to expire, then call DataStore.start from the app, it should start the sync process and try to establish the subscriptions. It should hit those lines of code. awsAuthService.getToken() calls fetchAuthSession and oidcAuthProvider.getLatestAuthToken() calls the developer's own auth provider (which may not have a call to fetchAuthSession)

[medhatIbsais-Harri]

Hello @lawmicha, yes we are using this AmplifyOIDCAuthProvider and implement the getLatestAuthToken method

[lawmicha]

Hi @medhatIbsais-Harri , that sounds the problem is in the custom implementation of retrieving the token. Can you show us what your implementation of getLatestAuthToken looks like? I'm assuming it's missing the fetchAuthSession call. If it doesn't contain that, are you able to add that and retest to see if it solves the problem? DataStore uses the token and passes it to the downstream services, which relies on the token returned from this method to be valid

[medhatIbsais-Harri]

Hello @lawmicha we are using the fetchAuthSession,
Amplify.Auth.fetchAuthSession

[lawmicha]

Hey @medhatIbsais-Harri I have some questions for this use case

1. How does fetchAuthSession refresh the refresh token from your OIDC provider? Which OIDC provider are you using? A reproducible sample and steps to set up your auth use case would be helpful.
2. Can you add logging in the getLatestAuthToken call to get the token payload when you reproduce the issue? And verify that the issue is or is not that the access token is expired?

Feel free to respond in your support ticket if there are details that you'd like to keep private.

[medhatIbsais-Harri]

Hello @lawmicha, I can confirm that this issue solved on Amplify version 1.28.3
I tested it on version 1.28.0 and its appears as the logs above, and then when I tested the same flow on version 1.28.3 it worked correctly, don't know if your team fixed something related to this or not.

[medhatIbsais-Harri]

@lawmicha can you please check it with your team to ensure that it's resolved?

[lawmicha]

Hi @medhatIbsais-Harri, glad to hear that the latest version is working for you. The problem as I understand it is that the user is unauthorized when using the token from Auth.fetchAuthSession. Please correct me if i'm wrong. There are multiple layers of functionality that goes into Auth.fetchAuthSession, in Amplify 1.x.x, we pass through the request to the iOS SDK's AWSMobileClient. I can see in 1.28.1, the iOS SDK dependency was bumped up to v2.28.0: https://github.com/aws-amplify/amplify-swift/releases/tag/v1.28.1

In iOS SDK AWSMobileClient 2.28.0, there's at least this AWSMobileClient change related to a race condition for getToken https://github.com/aws-amplify/aws-sdk-ios/releases/tag/2.28.0 aws-amplify/aws-sdk-ios#4290 I can't say for certain if this is the problem you were seeing without more information from your repro and more context on the impact of that issue that was fixed. The issue that was fixed is related to a crash, which doesn't sound like what you're seeing. If you check your dependencies version for aws-sdk-ios, I think it should be taking all patch versions, and the latest SDK version is 2.28.5, so there may be other changes as well (all SDK releases https://github.com/aws-amplify/aws-sdk-ios/releases)

It doesn't appear to be any changes in 1.28.2 and 1.28.3 that is related to the SDK or Auth
https://github.com/aws-amplify/amplify-swift/releases/tag/v1.28.2
https://github.com/aws-amplify/amplify-swift/releases/tag/v1.28.3

I'd recommend comparing your app runtime against 1.28.1 and 1.28.0 to see if 1.28.1 fixes the problem as that will be a good indication that the SDK changes fixed the problem.

In Amplify 2.x.x, we have fully rewritten the Amplify.Auth against the new Swift SDK, and recommend trying this out as well.

[medhatIbsais-Harri]

Hello @lawmicha, it doesn’t work on version 1.28.1 nor version 1.28.3, sorry my bad
but when I launched the app in online mode and wait until the syncing process finished, then tuned OFF the wifi for more that one hour until the access token expired, then after approx. 1.5 hours I turned ON the wifi, and forced the sycning process to start by calling the snippet of code

Amplify.DataStore.start { _ in
    Amplify.DataStore.stop { _ in
        Amplify.DataStore.start { _ in

        }
    }
}

I received this error in the logs:

 ****** Amplify Manager: network connection is Active: true
 ****** Amplify Manager: network connection is Active: true
2022-12-07 12:50:36.226252+0200 TeamHub Pro[549:45712] [AuthRuleDecorator] Attempted to subscribe to a model with owner based authorization without brand_id
which was specified (or defaulted to) as the identity claim.
2022-12-07 12:50:36.242765+0200 TeamHub Pro[549:45712] [AuthRuleDecorator] Attempted to subscribe to a model with owner based authorization without brand_id
which was specified (or defaulted to) as the identity claim.
2022-12-07 12:50:36.270656+0200 TeamHub Pro[549:45712] [AuthRuleDecorator] Attempted to subscribe to a model with owner based authorization without brand_id
which was specified (or defaulted to) as the identity claim.
2022-12-07 12:50:37.086316+0200 TeamHub Pro[549:45783] ConnectionProviderError.unauthorized
2022-12-07 12:50:37.086687+0200 TeamHub Pro[549:45783] ConnectionProviderError.unauthorized
2022-12-07 12:50:37.086875+0200 TeamHub Pro[549:45783] ConnectionProviderError.unauthorized
 ****** Amplify Manager: Subscription Established
 ****** Amplify Manager: Sync Queries Started
2022-12-07 12:50:37.260644+0200 TeamHub Pro[549:45712] [tcp] tcp_input [C16.1:2] flags=[R.] seq=3515718711, ack=1579494287, win=1558 state=ESTABLISHED rcv_nxt=3515718711, snd_una=1579494287
2022-12-07 12:50:38.049540+0200 TeamHub Pro[549:45716] [RemoteSyncEngine] One or more errors occurred syncing models. See below for detailed error description.
2022-12-07 12:50:38.049801+0200 TeamHub Pro[549:45716] [RemoteSyncEngine] DataStoreError: An error occurred syncing Clock
Caused by:
DataStoreError: The HTTP response status code is [401].
Recovery suggestion: The metadata associated with the response is contained in the HTTPURLResponse.
For more information on HTTP status codes, take a look at
https://en.wikipedia.org/wiki/List_of_HTTP_status_codes
Caused by:
APIError: The HTTP response status code is [401].
Recovery suggestion: The metadata associated with the response is contained in the HTTPURLResponse.
For more information on HTTP status codes, take a look at
https://en.wikipedia.org/wiki/List_of_HTTP_status_codes
2022-12-07 12:50:38.059464+0200 TeamHub Pro[549:45716] [ReadyEventEmitter] Failed to emit ready event, error: DataStoreError: One or more errors occurred syncing models. See below for detailed error description.
Recovery suggestion: DataStoreError: An error occurred syncing Clock
Caused by:
DataStoreError: The HTTP response status code is [401].
Recovery suggestion: The metadata associated with the response is contained in the HTTPURLResponse.
For more information on HTTP status codes, take a look at
https://en.wikipedia.org/wiki/List_of_HTTP_status_codes
Caused by:
APIError: The HTTP response status code is [401].
Recovery suggestion: The metadata associated with the response is contained in the HTTPURLResponse.
For more information on HTTP status codes, take a look at
https://en.wikipedia.org/wiki/List_of_HTTP_status_codes
Caused by:
DataStoreError: One or more errors occurred syncing models. See below for detailed error description.
Recovery suggestion: DataStoreError: An error occurred syncing Clock
Caused by:
DataStoreError: The HTTP response status code is [401].
Recovery suggestion: The metadata associated with the response is contained in the HTTPURLResponse.
For more information on HTTP status codes, take a look at
https://en.wikipedia.org/wiki/List_of_HTTP_status_codes
Caused by:
APIError: The HTTP response status code is [401].
Recovery suggestion: The metadata associated with the response is contained in the HTTPURLResponse.
For more information on HTTP status codes, take a look at
https://en.wikipedia.org/wiki/List_of_HTTP_status_codes
2022-12-07 12:50:38.063654+0200 TeamHub Pro[549:45716] [AWSDataStorePlugin] StorageEngine completed with error: DataStoreError: One or more errors occurred syncing models. See below for detailed error description.
Recovery suggestion: DataStoreError: An error occurred syncing Clock
Caused by:
DataStoreError: The HTTP response status code is [401].
Recovery suggestion: The metadata associated with the response is contained in the HTTPURLResponse.
For more information on HTTP status codes, take a look at
https://en.wikipedia.org/wiki/List_of_HTTP_status_codes
Caused by:
APIError: The HTTP response status code is [401].
Recovery suggestion: The metadata associated with the response is contained in the HTTPURLResponse.
For more information on HTTP status codes, take a look at
https://en.wikipedia.org/wiki/List_of_HTTP_status_codes
Caused by:
DataStoreError: One or more errors occurred syncing models. See below for detailed error description.
Recovery suggestion: DataStoreError: An error occurred syncing Clock
Caused by:
DataStoreError: The HTTP response status code is [401].
Recovery suggestion: The metadata associated with the response is contained in the HTTPURLResponse.
For more information on HTTP status codes, take a look at
https://en.wikipedia.org/wiki/List_of_HTTP_status_codes
Caused by:
APIError: The HTTP response status code is [401].
Recovery suggestion: The metadata associated with the response is contained in the HTTPURLResponse.
For more information on HTTP status codes, take a look at
https://en.wikipedia.org/wiki/List_of_HTTP_status_codes

[lawmicha]

Hi @medhatIbsais-Harri , is the first error expected? Attempted to subscribe to a model with owner based authorization without brand_id Do you have the token payload to confirm the token is correct? It sounds like the token that was vended to you from your Auth backend did not add the brand_id in the claims.

The ConnectionProviderError.unauthorized comes from the subscription request to AppSync websockets, and the HTTP 401 error comes from DataStore performing syncQuery API to AppSync

[medhatIbsais-Harri]

Hello @lawmicha, the first one is expected yes, never mind, but if you can see the other returned logs

[lawmicha]

If the first request is unauthorized and is expected, I would also expect that the syncQuery operation is also unauthorized if your token is missing the brand_id. You can enable X-Ray tracing through AppSync to further debug the service response https://docs.aws.amazon.com/appsync/latest/devguide/x-ray-tracing.html . I would also suggest adding more logging to your app's refresh token process to narrow out the differences between the token payload that resulted in a successful request verse the unauthorized one

[medhatIbsais-Harri]

Hello @lawmicha, even after solving this issue, if I turned OFF the wifi after launching the app, then wait in offline mode until the token expires, then after turning it ON again, the data store will not start even if you called DataStore.start

[lawmicha]

Hi @medhatIbsais-Harri, DataStore will not start successfully if the token has expired. DataStore will not refresh the token for you. See some of the earlier questions, those should narrow down problems with your token refresh mechanism:

1. How does fetchAuthSession refresh the refresh token from your OIDC provider? Which OIDC provider are you using? A reproducible sample and steps to set up your auth use case would be helpful.
2. Can you add logging in the getLatestAuthToken call to get the token payload when you reproduce the issue? And verify that the issue is or is not that the access token is expired?