search

aws-amplify / amplify-swift

A declarative library for application development using cloud services.
Apache License 2.0
460 stars 198 forks source link

Amplify.API.subscribe can not be connected to server in the first time launch app #3831

Open santoso8118 opened 3 months ago

santoso8118 commented 3 months ago

Describe the bug

When user login to our app We config Amplify with below configurations:

 if let url = url {
       do {
            try Amplify.add(plugin: AWSCognitoAuthPlugin())
            try Amplify.add(plugin: AWSAPIPlugin())
            try Amplify.add(plugin: AWSPinpointAnalyticsPlugin())

            let configuration = try AmplifyConfiguration(configurationFile: url)
            try Amplify.configure(configuration)

        } catch {
            // Need to handle error if Amplify init fails
            print("Failed to initialize Amplify with \(error.localizedDescription)")
        }
}

In the first time install app and open app then login successfully then we call Amplify.API.subscribe to our subscription but I only got failed connection and we can not receive any datas from server, the states as below:

  1. connecting
  2. disconnected (when we call cancel)

As normal connection states should be as below:

  1. connecting
  2. connected
  3. disconnected (when we call cancel)

The issue only happen for the first time subcribe. In the second time we successfully connect and get data After relaunch the app and we try Amplify.API.subscribe again, all subscriptions are working fine.

Steps To Reproduce

1. Refresh Install Application
2. Login to app
3. Then call **Amplify.API.subscribe** realtime data
4. For the fist time subscribe the connection does not successfully
5. In the second time we call **Amplify.API.subscribe** for the same realtime event it can connect successfully and return the data correcly

Expected behavior

Amplify.API.subscribe should always connect successfully even the very first time

Amplify Framework Version

2.33.3

Amplify Categories

API

Dependency manager

Swift PM

Swift version

5.10

CLI version

12.12.4

Xcode version

15.2

Relevant log output

<details>
<summary>Log Messages</summary>

INSERT LOG MESSAGES HERE



### Is this a regression?

No

### Regression additional context

_No response_

### Platforms

iOS

### OS Version

iOS 16.2

### Device

iPhone 11

### Specific to simulators

_No response_

### Additional context

_No response_
harsh62 commented 3 months ago

Thanks for opening the issue. Our team will look into the issue and provide update.

santoso8118 commented 3 months ago

@harsh62 Could you check why Amplify.API.subscribe returns connecting state and never returns connected state ?

lawmicha commented 3 months ago

Hi @santoso8118, do you have any verbose logs we can investigate to see what is happening? Do you have Amplify.Logging.logLevel = .verbose set?

santoso8118 commented 3 months ago

Thanks @lawmicha I will set log level and update to you

santoso8118 commented 3 months ago

Hi @lawmicha This is the log when the issue happen its failed to subscribe and returns timeout error Could you help to check what is the issue


[APIAppSyncRealTimeClient] [AppSyncRealTimeClient] Received subscription request id: 13BCE33A-4FAB-4488-B36A-DE17EDFDDDA9, query: {"variables":{"userId":"12fc012c-1893-4b2e-886e-9f9601bc974d"},"query":"subscription RefreshMockEvent($userId: String!) {\n  refreshMockEvent(userId: $userId) {\n    __typename\n    userId\n    eventType\n    message\n    distance\n    chargeAmount\n    detailMessage\n    data\n  }\n}"}
2024-08-27 10:38:25.598221+0800  [APIAppSyncRealTimeSubscription] [AppSyncRealTimeSubscription-13BCE33A-4FAB-4488-B36A-DE17EDFDDDA9] Start subscribing
10:38:25.598 AM 💚 DEBUG AppSync.subscribeToMockObuEvent():237 - Subscription subscribeToMockObuEvent connect state is connecting
10:38:25.598 AM 💚 DEBUG AppSync.subscribeToMockObuEvent():237 - Subscription subscribeToMockObuEvent connect state is connecting
10:38:25.599 AM 💚 DEBUG AppSync.subscribeToMockObuEvent():237 - Subscription subscribeToMockObuEvent connect state is connecting
2024-08-27 10:38:25.600461+0800  [WebSocketClient] [WebSocketClient] WebSocket write message string: {"type":"start","id":"13BCE33A-4FAB-4488-B36A-DE17EDFDDDA9","payload":{"data":"{\"variables\":{\"userId\":\"12fc012c-1893-4b2e-886e-9f9601bc974d\"},\"query\":\"subscription RefreshMockEvent($userId: String!) {\\n  refreshMockEvent(userId: $userId) {\\n    __typename\\n    userId\\n    eventType\\n    message\\n    distance\\n    chargeAmount\\n    detailMessage\\n    data\\n  }\\n}\"}","extensions":{"authorization":{"host":"hsjyntfl6vfxfcbya6rr2mi2p4.appsync-api.ap-southeast-1.amazonaws.com","Authorization":"eyJraWQiOiJYTm9rMU5PNnd5VmxWbkdcL0Vib1wveUhkY3Y4VTREcHpRYjBVWjJrWnpwWDA9IiwiYWxnIjoiUlMyNTYifQ.eyJzdWIiOiIxMmZjMDEyYy0xODkzLTRiMmUtODg2ZS05Zjk2MDFiYzk3NGQiLCJjb2duaXRvOmdyb3VwcyI6WyJhcC1zb3V0aGVhc3QtMV9LakdEWHRlUHFfU2lnbkluV2l0aEFwcGxlIl0sImlzcyI6Imh0dHBzOlwvXC9jb2duaXRvLWlkcC5hcC1zb3V0aGVhc3QtMS5hbWF6b25hd3MuY29tXC9hcC1zb3V0aGVhc3QtMV9LakdEWHRlUHEiLCJ2ZXJzaW9uIjoyLCJjbGllbnRfaWQiOiIzb2t2dTY2MGNmbWRmZ2JmYzI4M2gwMzJhbiIsInRva2VuX3VzZSI6ImFjY2VzcyIsInNjb3BlIjoiYXdzLmNvZ25pdG8uc2lnbmluLnVzZXIuYWRtaW4gb3BlbmlkIHByb2ZpbGUiLCJhdXRoX3RpbWUiOjE3MjQ3MjYxOTMsImV4cCI6MTcyNDgxMjU5MywiaWF0IjoxNzI0NzI2MTkzLCJqdGkiOiIwZjQ0YWE0My01MmZhLTRjNzktODViMS0xOGJhMTg5YjQ1ZWUiLCJ1c2VybmFtZSI6InNpZ25pbndpdGhhcHBsZV8wMDEyNTcuNTc2MzdlZmEwMDg1NDhkNzhjNjQ2NzIyMTM5N2E1OTQuMTAwMyJ9.zMhv03jBqgV_VIHjIttiNPMi3o4bbLL7Ht50YmvfGR8Tk7O4TMmDMHvY3m2O2GkldRJRSnFy6Ogotxbi-cppM_E67NeTfuYcZzlWyqFgVPiMCoWWO7oMTbHGzxmEm2h-eWlnZjGlUTrdGEclx9hB9GVjm1hj6L_4mfjGdqcpNIwJe71oEf4W5mRbNLD6V4kCNX4ajtbSLKEYyrtJXjG0Y88tFaj013qLPj2t5XNdNZwIrqDnps6a99nZ0FNUVaMnTxSh_jGLq6Tc1kuxM5FzjDBiVbIWBg4ItiS3Ir-RJ1lAPCKSkXNB26dYcBRXpKMcp-PMJFqurkH9eKeZvHrGow"}}}}
2024-08-27 10:38:25.609249+0800  [APIAppSyncRealTimeClient] [AppSyncRealTimeClient]Failed to send AppSync request start(AWSAPIPlugin.AppSyncRealTimeRequest.StartRequest(id: "13BCE33A-4FAB-4488-B36A-DE17EDFDDDA9", data: "{\"variables\":{\"userId\":\"12fc012c-1893-4b2e-886e-9f9601bc974d\"},\"query\":\"subscription RefreshMockEvent($userId: String!) {\\n  refreshMockEvent(userId: $userId) {\\n    __typename\\n    userId\\n    eventType\\n    message\\n    distance\\n    chargeAmount\\n    detailMessage\\n    data\\n  }\\n}\"}", auth: nil)), error: Error Domain=kNWErrorDomainPOSIX Code=53 "Software caused connection abort" UserInfo={NSDescription=Software caused connection abort}
2024-08-27 10:38:30.600763+0800  [APIAppSyncRealTimeSubscription] [AppSyncRealTimeSubscription-13BCE33A-4FAB-4488-B36A-DE17EDFDDDA9] Failed to subscribe, error: timeout
AnirudhWinimy commented 3 months ago

@lawmicha This seems to be related to https://github.com/aws-amplify/amplify-swift/issues/3632 @santoso8118 and i have noticed that this happens when moving the app to background and foreground.

The app sync subscription is unable to recover after it disconnects when app is in background.

Even after upgrading to 2.37.0 we still see the error. However now we receive the following error in addition in log in 2.37.0:

Amplify.APIError error 3.

lawmicha commented 3 months ago

Hi @AnirudhWinimy / @santoso8118 , from my understanding, the changes made by @5d (please chime in if I'm wrong here) in https://github.com/aws-amplify/amplify-swift/pull/3800 for https://github.com/aws-amplify/amplify-swift/issues/3632 released in 2.37.0 will propagate the connection lost error back to the caller.

The APIError has an error description, recovery suggestion, and optional underlying error. In the PR, we are returning APIError.networkError with an underlying error of URLError(.networkConnectionLost) code line 411. Is this what you are getting when you reproduce the scenario of backgrounding to foregrounding? If so, you can check if the underlying error is the URLError networkConnectionLost and perform subscribe to retry connecting to websocket and establishing the subscription.

santoso8118 commented 3 months ago

Hi @lawmicha :

When the error happens we try to perform subscription again its always got failed with the same error. Base on the timing that SDK give log error timeout, its not a timeout actually. It seems the subscription get timeout immediately when I call subscribe again.

By the way could you tell me how long subscription get timeout if can not connect to server ?

AnirudhWinimy commented 3 months ago

@lawmicha

When the error happens we try to perform subscription again its always got failed with the same error. Base on the timing that SDK give log error timeout, its not a timeout actually. It seems the subscription get timeout immediately when I call subscribe again.

By the way could you tell me how long subscription get timeout if can not connect to server ?

To elaborate further, your suggestion works when we downgrade to version 2.28.0, i.e we can re-subscribe when the app is back to the foreground.

However since upgrading to 2.33.3 (and even on 2.37.0) whenever the app goes to the background and returns to the foreground, calling re-subscribe consistently fails with a network timeout error almost immediately. In reality there is no connection error and any mutations sent works.

The error lines when attempting to re-subscribe are shared in https://github.com/aws-amplify/amplify-swift/issues/3831#issuecomment-2311473235

2024-08-27 10:38:25.609249+0800  [APIAppSyncRealTimeClient] [AppSyncRealTimeClient]Failed to send AppSync request start(AWSAPIPlugin.AppSyncRealTimeRequest.StartRequest(id: "13BCE33A-4FAB-4488-B36A-DE17EDFDDDA9", data: "{\"variables\":{\"userId\":\"12fc012c-1893-4b2e-886e-9f9601bc974d\"},\"query\":\"subscription RefreshMockEvent($userId: String!) {\\n  refreshMockEvent(userId: $userId) {\\n    __typename\\n    userId\\n    eventType\\n    message\\n    distance\\n    chargeAmount\\n    detailMessage\\n    data\\n  }\\n}\"}", auth: nil)), error: Error Domain=kNWErrorDomainPOSIX Code=53 "Software caused connection abort" UserInfo={NSDescription=Software caused connection abort}
2024-08-27 10:38:30.600763+0800  [APIAppSyncRealTimeSubscription] [AppSyncRealTimeSubscription-13BCE33A-4FAB-4488-B36A-DE17EDFDDDA9] Failed to subscribe, error: timeout
5d commented 3 months ago

Hi @lawmicha This is the log when the issue happen its failed to subscribe and returns timeout error Could you help to check what is the issue


[APIAppSyncRealTimeClient] [AppSyncRealTimeClient] Received subscription request id: 13BCE33A-4FAB-4488-B36A-DE17EDFDDDA9, query: {"variables":{"userId":"12fc012c-1893-4b2e-886e-9f9601bc974d"},"query":"subscription RefreshMockEvent($userId: String!) {\n  refreshMockEvent(userId: $userId) {\n    __typename\n    userId\n    eventType\n    message\n    distance\n    chargeAmount\n    detailMessage\n    data\n  }\n}"}
2024-08-27 10:38:25.598221+0800  [APIAppSyncRealTimeSubscription] [AppSyncRealTimeSubscription-13BCE33A-4FAB-4488-B36A-DE17EDFDDDA9] Start subscribing
10:38:25.598 AM 💚 DEBUG AppSync.subscribeToMockObuEvent():237 - Subscription subscribeToMockObuEvent connect state is connecting
10:38:25.598 AM 💚 DEBUG AppSync.subscribeToMockObuEvent():237 - Subscription subscribeToMockObuEvent connect state is connecting
10:38:25.599 AM 💚 DEBUG AppSync.subscribeToMockObuEvent():237 - Subscription subscribeToMockObuEvent connect state is connecting
2024-08-27 10:38:25.600461+0800  [WebSocketClient] [WebSocketClient] WebSocket write message string: {"type":"start","id":"13BCE33A-4FAB-4488-B36A-DE17EDFDDDA9","payload":{"data":"{\"variables\":{\"userId\":\"12fc012c-1893-4b2e-886e-9f9601bc974d\"},\"query\":\"subscription RefreshMockEvent($userId: String!) {\\n  refreshMockEvent(userId: $userId) {\\n    __typename\\n    userId\\n    eventType\\n    message\\n    distance\\n    chargeAmount\\n    detailMessage\\n    data\\n  }\\n}\"}","extensions":{"authorization":{"host":"hsjyntfl6vfxfcbya6rr2mi2p4.appsync-api.ap-southeast-1.amazonaws.com","Authorization":"eyJraWQiOiJYTm9rMU5PNnd5VmxWbkdcL0Vib1wveUhkY3Y4VTREcHpRYjBVWjJrWnpwWDA9IiwiYWxnIjoiUlMyNTYifQ.eyJzdWIiOiIxMmZjMDEyYy0xODkzLTRiMmUtODg2ZS05Zjk2MDFiYzk3NGQiLCJjb2duaXRvOmdyb3VwcyI6WyJhcC1zb3V0aGVhc3QtMV9LakdEWHRlUHFfU2lnbkluV2l0aEFwcGxlIl0sImlzcyI6Imh0dHBzOlwvXC9jb2duaXRvLWlkcC5hcC1zb3V0aGVhc3QtMS5hbWF6b25hd3MuY29tXC9hcC1zb3V0aGVhc3QtMV9LakdEWHRlUHEiLCJ2ZXJzaW9uIjoyLCJjbGllbnRfaWQiOiIzb2t2dTY2MGNmbWRmZ2JmYzI4M2gwMzJhbiIsInRva2VuX3VzZSI6ImFjY2VzcyIsInNjb3BlIjoiYXdzLmNvZ25pdG8uc2lnbmluLnVzZXIuYWRtaW4gb3BlbmlkIHByb2ZpbGUiLCJhdXRoX3RpbWUiOjE3MjQ3MjYxOTMsImV4cCI6MTcyNDgxMjU5MywiaWF0IjoxNzI0NzI2MTkzLCJqdGkiOiIwZjQ0YWE0My01MmZhLTRjNzktODViMS0xOGJhMTg5YjQ1ZWUiLCJ1c2VybmFtZSI6InNpZ25pbndpdGhhcHBsZV8wMDEyNTcuNTc2MzdlZmEwMDg1NDhkNzhjNjQ2NzIyMTM5N2E1OTQuMTAwMyJ9.zMhv03jBqgV_VIHjIttiNPMi3o4bbLL7Ht50YmvfGR8Tk7O4TMmDMHvY3m2O2GkldRJRSnFy6Ogotxbi-cppM_E67NeTfuYcZzlWyqFgVPiMCoWWO7oMTbHGzxmEm2h-eWlnZjGlUTrdGEclx9hB9GVjm1hj6L_4mfjGdqcpNIwJe71oEf4W5mRbNLD6V4kCNX4ajtbSLKEYyrtJXjG0Y88tFaj013qLPj2t5XNdNZwIrqDnps6a99nZ0FNUVaMnTxSh_jGLq6Tc1kuxM5FzjDBiVbIWBg4ItiS3Ir-RJ1lAPCKSkXNB26dYcBRXpKMcp-PMJFqurkH9eKeZvHrGow"}}}}
2024-08-27 10:38:25.609249+0800  [APIAppSyncRealTimeClient] [AppSyncRealTimeClient]Failed to send AppSync request start(AWSAPIPlugin.AppSyncRealTimeRequest.StartRequest(id: "13BCE33A-4FAB-4488-B36A-DE17EDFDDDA9", data: "{\"variables\":{\"userId\":\"12fc012c-1893-4b2e-886e-9f9601bc974d\"},\"query\":\"subscription RefreshMockEvent($userId: String!) {\\n  refreshMockEvent(userId: $userId) {\\n    __typename\\n    userId\\n    eventType\\n    message\\n    distance\\n    chargeAmount\\n    detailMessage\\n    data\\n  }\\n}\"}", auth: nil)), error: Error Domain=kNWErrorDomainPOSIX Code=53 "Software caused connection abort" UserInfo={NSDescription=Software caused connection abort}
2024-08-27 10:38:30.600763+0800  [APIAppSyncRealTimeSubscription] [AppSyncRealTimeSubscription-13BCE33A-4FAB-4488-B36A-DE17EDFDDDA9] Failed to subscribe, error: timeout

Hi @santoso8118

According to the log, the websocket encountered a kernel-level error: kNWErrorDomainPOSIX with code 53, indicating "Software caused connection abort." This error typically occurs when the application is moved to the background.

The subscription timeout error happens 5 seconds after the request is sent, which is expected behavior since we’ve set a default 5-second timeout for a connected websocket to receive a response from the server.

To better understand the complete testing scenario, could you provide the full log from when you reproduce this issue? This additional information would help us gain a more comprehensive view of the problem and its context.

ref:

santoso8118 commented 2 days ago

Hi @lawmicha

We already share all the logs that we have after enable the verbose log and reproduce the issue. As you said the subscription get timeout after 5 seconds its fine. But after app enters background the web socket got disconnected and then app comes back to foreground again we can not subscribe app sync event again successfully.

I see that there are some release versions recently that fixed issues relate to appsync and web socket connection. Do you know any released version that fixed this issue. Please advice!

tylerjroach commented 2 days ago

Hi @santoso8118,

We are currently trying to replicate the behavior on our latest version and will get back to you once we have an answer. Thank you for the log provided here and the code example with support.

harsh62 commented 1 day ago

@santoso8118

So I spend considerable time trying to reproduce the issue and was unable to see the subscription error reported. I have tried on both the latest version of Amplify and also on the affected version (2.33.3) in the ticket. Amplify behaves consistently every time.

I have followed the Amplify documentation guide to setup a simple app to reproduce the issue in an isolated environment.

My subscription code is exactly the same mentioned in the documentation and I am using the following strategy to test backgrounding and foregrounding the app. 

// Create an observable object instance.
    @StateObject var vm = TodoViewModel()
    @Environment(\.scenePhase) var scenePhase

    var body: some View {
        VStack {
            Text("Hello")
                .onChange(of: scenePhase) { oldPhase, newPhase in
                    if newPhase == .active {
                        print("App is Active, start subscription ")
                        vm.subscribe()
                    } else if newPhase == .background {
                        print("App Backgrounded, cancel subscription")
                        vm.cancel()
                    }
                }
            }
        }
   }

Just so that everybody is on the same page, following is my view models subscription and cancellation calls. 

    // Subscription
    private var subscription: AmplifyAsyncThrowingSequence<GraphQLSubscriptionEvent<Todo>>? = nil

    func subscribe() {
        self.subscription = Amplify.API.subscribe(request: .subscription(of: Todo.self, type: .onCreate))
        Task {
            guard let subscription = subscription else { return }
            do {
                for try await subscriptionEvent in subscription {
                    handleSubscriptionEvent(subscriptionEvent)
                }
            } catch {
                print("Subscription has terminated with \(error)")
            }
        }
    }

    // Cancel subscription
    func cancel() {
        self.subscription?.cancel()
    }

App verbose Logs that I have observed during my debugging session

As of next steps, I would suggest that try to reproduce the issue in a local isolated environment and share that with the team otherwise its very difficult to further investigate the issue.

AnirudhWinimy commented 1 day ago

@harsh62

We recently migrated from AWS AppSync SDK for iOS to aws amplify sdk as per the deprecation notice (https://github.com/awslabs/aws-mobile-appsync-sdk-ios)

In the official aws notification for us to migrate we were provided the following link to upgrade which we are following https://docs.amplify.aws/gen1/swift/build-a-backend/graphqlapi/upgrade-guide/

We are using a similar mechanism to subscribe shared in the link above

  let refreshDataSetMutation = RefreshDataSetSubscription(notificationType: key)
    let graphQLRequest = GraphQLRequest(document: RefreshDataSetSubscription.operationString, variables: refreshDataSetMutation.variables?.jsonObject, responseType: RefreshDataSetSubscription.Data.self)
    let subscription = Amplify.API.subscribe(request: graphQLRequest)

The above works for the first time launch and the re-subscribe from background to foreground works in 2.28.0 using the above mechanism.

However after upgrading above 2.28.0 this mechanism stops working.

tylerjroach commented 1 hour ago

Hi @AnirudhWinimy,

Using the latest version of Amplify, can you please attempt to create a sample app demonstrating the bug that you are experiencing and we could pull that app down and test? As @harsh62 mentioned, we have been unable to reproduce the reported bug that is being described.