search

aws-amplify / amplify-js

A declarative JavaScript library for application development using cloud services.
https://docs.amplify.aws/lib/q/platform/js
Apache License 2.0
9.43k stars 2.13k forks source link

Subscription Timeout too short, ack from AWSRealTime was not received on CONNECTION_INIT_TIMEOUT #9226

Closed abel30567 closed 2 years ago

abel30567 commented 2 years ago

Before opening, please confirm:

JavaScript Framework

React Native

Amplify APIs

PubSub

Amplify Categories

api

Environment information

``` System: OS: macOS 11.6 CPU: (8) x64 Apple M1 Memory: 17.66 MB / 16.00 GB Shell: 5.8 - /bin/zsh Binaries: Node: 14.17.1 - /usr/local/bin/node Yarn: 1.22.4 - ~/.yarn/bin/yarn npm: 6.14.13 - /usr/local/bin/npm Watchman: 2021.10.04.00 - /usr/local/bin/watchman Browsers: Brave Browser: 95.1.31.88 Chrome: 95.0.4638.69 Safari: 15.0 npmPackages: @babel/cli: ^7.4.3 => 7.10.1 @babel/core: ^7.6.4 => 7.10.2 @babel/plugin-proposal-class-properties: ^7.3.4 => 7.10.1 @babel/plugin-transform-flow-strip-types: ^7.3.4 => 7.10.1 @babel/plugin-transform-named-capturing-groups-regex: ^7.4.2 => 7.8.3 @babel/preset-env: ^7.3.4 => 7.10.2 @babel/runtime: ^7.6.3 => 7.10.2 @react-native-async-storage/async-storage: ^1.15.11 => 1.15.11 @react-native-community/datetimepicker: ^3.0.1 => 3.0.1 @react-native-community/eslint-config: ^0.0.5 => 0.0.5 @react-native-community/netinfo: ^5.9.6 => 5.9.6 @react-native-picker/picker: ^1.12.0 => 1.12.0 @react-navigation/core: ^3.5.1 => 3.7.6 @react-navigation/native: ^3.6.2 => 3.7.13 @sentry/react-native: ^2.2.0 => 2.2.0 HelloWorld: 0.0.1 Sample: 0.0.1 amazon-cognito-identity-js: ^3.1.3 => 3.3.3 (5.2.3) aws-amplify: ^4.3.6 => 4.3.6 aws-amplify-react-native: ^4.2.4 => 4.2.4 aws-sdk: ^2.731.0 => 2.731.0 babel-eslint: ^10.0.1 => 10.1.0 (10.0.1) babel-jest: ^24.9.0 => 24.9.0 babel-plugin-transform-remove-console: ^6.9.4 => 6.9.4 base-64: ^0.1.0 => 0.1.0 console-browserify: ^1.1.0 => 1.2.0 depcheck: ^0.8.3 => 0.8.4 depcheck-test-e2e: 0.0.1 enzyme: ^3.9.0 => 3.11.0 enzyme-adapter-react-16: ^1.12.1 => 1.15.2 eslint: ^6.5.1 => 6.8.0 eslint-config-prettier: ^4.1.0 => 4.3.0 (6.11.0) eslint-plugin-import: ^2.16.0 => 2.21.1 eslint-plugin-jest: ^22.4.1 => 22.21.0 (22.4.1) eslint-plugin-prettier: ^3.0.1 => 3.1.3 (2.6.2) eslint-plugin-react: ^7.12.4 => 7.20.0 (7.12.4) eslint-plugin-react-native: ^3.6.0 => 3.8.1 (3.6.0) example: 0.1.0 flatted: ^2.0.1 => 2.0.2 graphql: 0.13.0 => 0.13.0 (14.5.0, 14.0.0) hermes-inspector-msggen: 1.0.0 immutability-helper: ^3.0.0 => 3.1.1 intl: ^1.2.5 => 1.2.5 jest: ^24.9.0 => 24.9.0 memo-parser: 0.2.1 metro-react-native-babel-preset: ^0.56.0 => 0.56.4 native-base: ^2.12.0 => 2.13.12 path-browserify: 0.0.0 => 0.0.0 prettier: 1.16.4 => 1.16.4 process: ^0.11.10 => 0.11.10 react: 16.9.0 => 16.9.0 react-animated: 0.1.0 react-dom: 16 => 16.13.1 react-native: 0.61.2 => 0.61.2 react-native-camera: ^3.9.0 => 3.28.0 react-native-circular-progress: ^1.3.6 => 1.3.6 react-native-code-push: ^6.3.0 => 6.3.0 react-native-datawedge-intents: https://github.com/CoreLogicLLC/react-native-datawedge-intents => 0.1.7 react-native-device-info: ^5.2.1 => 5.6.1 react-native-dotenv: ^0.2.0 => 0.2.0 react-native-fs: ^2.16.6 => 2.16.6 react-native-gesture-handler: ^1.0.16 => 1.6.1 react-native-image-pan-zoom: ^2.1.11 => 2.1.12 react-native-level-fs: ^3.0.1 => 3.0.1 react-native-loading-spinner-overlay: ^1.0.1 => 1.1.0 react-native-modals: ^0.19.9 => 0.19.9 react-native-paper: 2.16.0 => 2.16.0 react-native-queue: ^1.2.1 => 1.2.1 react-native-reanimated: ^1.3.0 => 1.9.0 react-native-restart: ^0.0.17 => 0.0.17 react-native-screens: ^2.0.0-alpha.7 => 2.8.0 react-native-smooth-pincode-input: ^1.0.3 => 1.0.9 react-native-sound: ^0.10.12 => 0.10.12 react-native-splash-screen: ^3.2.0 => 3.2.0 react-native-svg: ^9.2.4 => 9.13.6 react-native-udp: ^2.6.1 => 2.7.0 react-native-url-polyfill: ^1.3.0 => 1.3.0 react-native-vector-icons: ^6.3.0 => 6.6.0 react-native-voice: ^0.2.6 => 0.2.6 react-navigation: ^4.0.10 => 4.3.9 react-navigation-backhandler: ^1.2.0 => 1.4.0 react-navigation-drawer: ^2.3.2 => 2.4.13 react-navigation-material-bottom-tabs: ^2.1.5 => 2.2.12 react-navigation-stack: ^1.10.3 => 1.10.3 react-navigation-tabs: ^2.5.6 => 2.8.13 react-test-renderer: 16.9.0 => 16.9.0 (16.13.1) realm: 3.6.5 => 3.6.5 (2.29.2) realm-react-native: 0.0.1 rn-fetch-blob: 0.10.16 => 0.10.16 rn-nodeify: ^10.0.1 => 10.2.0 uuid: ^3.3.2 => 3.4.0 (3.3.2, 8.3.2, 7.0.3) npmGlobalPackages: aws-cdk: 1.112.0 npm: 6.14.13 react-native-cli: 2.0.1 serve: 11.3.2 serverless: 2.52.0 typescript: 4.3.5 ```

Describe the bug

I am trying to create a subscription to a certain mutation using React Native and amplify-js. But I keep getting Connection failed: Connection timeout: ack from AWSRealTime was not received on 15000 ms errors on initializing the subscription.

Expected behavior

The subscription is expected to remain listening for any changes to a certain mutation. It should reproduce something like the logs below

``` LOG [DEBUG] 26:27.373 AWSAppSyncRealTimeProvider - Initializaling retryable Handshake LOG [DEBUG] 26:27.375 Util - bound attempt #1 with this vars: [{"awsRealTimeUrl":"wss://**e30="}] LOG [DEBUG] 26:27.375 AWSAppSyncRealTimeProvider - Initializing handshake wss://**e30= LOG [DEBUG] 26:28.939 AWSAppSyncRealTimeProvider - subscription message from AWS AppSyncRealTime: {"type":"connection_ack","payload":{"connectionTimeoutMs":300000}} LOG [DEBUG] 26:28.941 AWSAppSyncRealTimeProvider - Notifying connection successful LOG [DEBUG] 26:28.956 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"type":"ka"} LOG [DEBUG] 26:28.956 AWSAppSyncRealTimeProvider {"id": "", "observer": null, "query": "", "variables": {}} LOG [DEBUG] 26:29.218 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"id":"1f240057-bb56-4614-9002-fbd2963693ff","type":"start_ack"} LOG [DEBUG] 26:29.218 AWSAppSyncRealTimeProvider {"id": "1f240057-bb56-4614-9002-fbd2963693ff", "observer": {"_subscription": {"_cleanup": [Function anonymous], "_observer": [Object], "_queue": undefined, "_state": "ready"}}, "query": "subscription packageUpdates { packageUpdates { id quantity } } ", "variables": {}} LOG [DEBUG] 26:29.219 AWSAppSyncRealTimeProvider - subscription ready for {"query":"subscription packageUpdates {\n packageUpdates {\n id\n quantity\n }\n}\n","variables":{}} LOG [DEBUG] 27:28.512 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"type":"ka"} LOG [DEBUG] 27:28.517 AWSAppSyncRealTimeProvider {"id": "", "observer": null, "query": "", "variables": {}} ```

Reproduction steps

  1. Create a react native app
  2. Install 
    "aws-amplify": "^4.3.6", 
"@react-native-async-storage/async-storage": "^1.15.11",
"@react-native-picker/picker": "^1.12.0",
"@react-native-community/netinfo": "^5.9.6",
  3. Create a subscription

Code Snippet

import { API, graphqlOperation } from "aws-amplify";

function packagesUpdated() {
    return API.graphql(
      graphqlOperation("subscription packageUpdates {
             packageUpdates {
               id
               quantity
             }
        }")
    );
  }

export default class Index extends Component {

  subscription() {
    return packagesUpdated().subscribe({
      next: data => {
        this.setState(data);
        return data;
      },
      error: error => { 
        this.errorHandling(error);
      }
    });
  }

  componentDidMount() {
  this.subscription();
  }
}

Log output

``` LOG [DEBUG] 07:37.952 AWSAppSyncRealTimeProvider - Initializaling retryable Handshake LOG [DEBUG] 07:37.954 Util - bound attempt #1 with this vars: [{"awsRealTimeUrl":"wss://**e30="}] LOG [DEBUG] 07:37.954 AWSAppSyncRealTimeProvider - Initializing handshake wss://**e30= LOG [DEBUG] 07:39.996 Util - error on bound [Error: Connection timeout: ack from AWSRealTime was not received on 15000 ms] LOG [DEBUG] 07:39.998 Util - bound retrying in 288.4903060735886 ms LOG [DEBUG] 07:40.25 AWSAppSyncRealTimeProvider - subscription message from AWS AppSyncRealTime: {"type":"connection_ack","payload":{"connectionTimeoutMs":300000}} LOG [DEBUG] 07:40.46 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"type":"ka"} LOG [DEBUG] 07:40.47 AWSAppSyncRealTimeProvider {"id": "", "observer": null, "query": "", "variables": {}} LOG [DEBUG] 07:40.394 Util - bound attempt #2 with this vars: [{"awsRealTimeUrl":"wss://**e30="}] LOG [DEBUG] 07:40.395 AWSAppSyncRealTimeProvider - Initializing handshake wss://**e30= LOG [DEBUG] 07:43.289 Util - error on bound [Error: Connection timeout: ack from AWSRealTime was not received on 15000 ms] LOG [DEBUG] 07:43.291 Util - bound retrying in 430.39164233895065 ms LOG [DEBUG] 07:43.357 AWSAppSyncRealTimeProvider - subscription message from AWS AppSyncRealTime: {"type":"connection_ack","payload":{"connectionTimeoutMs":300000}} LOG [DEBUG] 07:43.378 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"type":"ka"} LOG [DEBUG] 07:43.379 AWSAppSyncRealTimeProvider {"id": "", "observer": null, "query": "", "variables": {}} LOG [DEBUG] 07:45.321 Util - bound attempt #3 with this vars: [{"awsRealTimeUrl":"wss://**e30="}] LOG [DEBUG] 07:45.322 AWSAppSyncRealTimeProvider - Initializing handshake wss://**e30= LOG [DEBUG] 07:46.421 Util - error on bound [Error: Connection timeout: ack from AWSRealTime was not received on 15000 ms] LOG [DEBUG] 07:46.422 Util - bound retrying in 884.4488780390627 ms LOG [DEBUG] 07:46.492 AWSAppSyncRealTimeProvider - subscription message from AWS AppSyncRealTime: {"type":"connection_ack","payload":{"connectionTimeoutMs":300000}} LOG [DEBUG] 07:46.521 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"type":"ka"} LOG [DEBUG] 07:46.521 AWSAppSyncRealTimeProvider {"id": "", "observer": null, "query": "", "variables": {}} LOG [DEBUG] 07:46.650 Util - bound attempt #4 with this vars: [{"awsRealTimeUrl":"wss://**e30="}] LOG [DEBUG] 07:46.651 AWSAppSyncRealTimeProvider - Initializing handshake wss://**e30= LOG [DEBUG] 07:48.311 Util - error on bound [Error: Connection timeout: ack from AWSRealTime was not received on 15000 ms] LOG [DEBUG] 07:48.312 Util - bound retrying in 1614.2461740188141 ms LOG [DEBUG] 07:48.338 AWSAppSyncRealTimeProvider - subscription message from AWS AppSyncRealTime: {"type":"connection_ack","payload":{"connectionTimeoutMs":300000}} LOG [DEBUG] 07:48.363 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"type":"ka"} LOG [DEBUG] 07:48.364 AWSAppSyncRealTimeProvider {"id": "", "observer": null, "query": "", "variables": {}} LOG [DEBUG] 07:48.493 Util - bound attempt #5 with this vars: [{"awsRealTimeUrl":"wss://**e30="}] LOG [DEBUG] 07:48.494 AWSAppSyncRealTimeProvider - Initializing handshake wss://**e30= LOG [DEBUG] 07:49.244 Util - error on bound [Error: Connection timeout: ack from AWSRealTime was not received on 15000 ms] LOG [DEBUG] 07:49.245 Util - bound retrying in 3220.628163615507 ms LOG [DEBUG] 07:49.274 AWSAppSyncRealTimeProvider - subscription message from AWS AppSyncRealTime: {"type":"connection_ack","payload":{"connectionTimeoutMs":300000}} LOG [DEBUG] 07:49.303 AWSAppSyncRealTimeProvider - subscription message from AWS AppSync RealTime: {"type":"ka"} LOG [DEBUG] 07:49.303 AWSAppSyncRealTimeProvider {"id": "", "observer": null, "query": "", "variables": {}} LOG [DEBUG] 07:49.413 Util - bound attempt #6 with this vars: [{"awsRealTimeUrl":"wss://**e30="}] LOG [DEBUG] 07:49.413 AWSAppSyncRealTimeProvider - Initializing handshake wss://**e30= LOG [DEBUG] 07:50.216 Util - error on bound [Error: Connection timeout: ack from AWSRealTime was not received on 15000 ms] LOG [DEBUG] 07:50.218 Util - bound retrying in false ms LOG [DEBUG] 07:50.222 AWSAppSyncRealTimeProvider {"err": [Error: Connection timeout: ack from AWSRealTime was not received on 15000 ms]} LOG [DEBUG] 07:50.238 AWSAppSyncRealTimeProvider - Error while unsubscribing undefined LOG [DEBUG] 07:50.266 AWSAppSyncRealTimeProvider - subscription message from AWS AppSyncRealTime: {"type":"connection_ack","payload":{"connectionTimeoutMs":300000}} LOG [DEBUG] 07:50.346 AWSAppSyncRealTimeProvider - subscription message from AWS AppSyncRealTime: {"type":"ka"} LOG [DEBUG] 07:50.465 AWSAppSyncRealTimeProvider - WebSocket closed ```

aws-exports.js

No response

Manual configuration

No response

Additional configuration

No response

Mobile Device

No response

Mobile Operating System

No response

Mobile Browser

No response

Mobile Browser Version

No response

Additional information and screenshots

Temporary Workaround

I increased the CONNECTION_INIT_TIMEOUT and the START_ACK_TIMEOUT to get expected behavior in the AWSAppSyncRealTimeProvider and that got it to work. From 15000 => 150000 https://github.com/aws-amplify/amplify-js/blob/main/packages/pubsub/src/Providers/AWSAppSyncRealTimeProvider.ts#L130-L139

chrisbonifacio commented 2 years ago

Hi @abel30567 👋 thanks for raising this issue. Currently trying to reproduce this. So, the behavior you're seeing is that the websocket is taking more than 15 seconds to connect? That seems unusually long.

I did notice that one of your dependencies, @react-native-community/netinfo, is out of date. Could you try upgrading it to the latest version of 7.1.2 and see if that makes a difference in connection speed?

abel30567 commented 2 years ago

@chrisbonifacio I tried updating it and got the same issue. I figured out my issue though. It turns out the device I was developing with had it's time delayed for more than 30 seconds. I synced my device's NTP Server and now it seems to be working with that update.

github-actions[bot] commented 1 year ago

This issue has been automatically locked since there hasn't been any recent activity after it was closed. Please open a new issue for related bugs.

Looking for a help forum? We recommend joining the Amplify Community Discord server *-help channels or Discussions for those types of questions.