launchdarkly / js-core

LaunchDarkly monorepo for JavaScript SDKs
Other
12 stars 12 forks source link

Streaming not working on react-native android even with Flipper removed #405

Closed dan-trewin closed 3 months ago

dan-trewin commented 3 months ago

Describe the bug

Even with Flipper completely removed from our react-native project (as bullet point 4 describes here: https://github.com/launchdarkly/js-core/tree/main/packages/sdk/react-native#known-android-identify-issue), streaming still doesn't seem to be working properly for Android. The app doesn't hang on identify and initial flags are retrieved so thats good. But any changes to the LD flags through our dashboard are not being reflected live in the Android app as they should. The streaming is working as expected on iOS.

To reproduce

I have tried using the exact code from the quickstart section: https://github.com/launchdarkly/js-core/tree/main/packages/sdk/react-native#quickstart and the streaming changes are reflected live on iOS but not on android.

I think this issue should be quickly apparent, but please let me know if you need any more reproduction details!

Expected behavior

Updating the flags on the LD dashboard should immediately be reflected in the Android app like they are on iOS

Logs

On Android on app startup:

info: [LaunchDarkly] Opened LaunchDarkly stream connection
info: [LaunchDarkly] Will retry stream connection in 915 milliseconds

For comparison on iOS on app startup: Note: there is no line about retrying the streaming connection in x milliseconds

info: [LaunchDarkly] Opened LaunchDarkly stream connection

SDK version

"@launchdarkly/react-native-client-sdk": "^10.0.3"

Language version, developer tools

Not expo, just base "react-native": "0.72.12"

OS/platform

Tested on Pixel 7 Emulator and Physical Device Android 14

yusinto commented 3 months ago

We are investigating. Filed internally as 237290.

yusinto commented 3 months ago

@dan-trewin can you please set debug to true and report back the logs? Also, is it 100% failure all the time or does it work sometimes? I suspect there is a network/server error when establishing the streaming connection and the retry failed.

const featureClient = new ReactNativeLDClient(MOBILE_KEY, AutoEnvAttributes.Enabled, {
  debug: true,
});
dan-trewin commented 3 months ago

@yusinto unfortunately, streaming on Android does not work 100% of the time for my company's app.

I have turned on that debug flag you requested and this is my stripped down App.tsx for testing:

// App.tsx
import React, { useEffect } from 'react';
import { SafeAreaView, Text } from 'react-native'
import { AutoEnvAttributes, LDProvider, ReactNativeLDClient, useBoolVariation } from '@launchdarkly/react-native-client-sdk';

const featureClient = new ReactNativeLDClient('mobile-key', AutoEnvAttributes.Enabled, {
  debug: true,
});
const userContext = {
  kind: 'user',
  anonymous: true,
  key: '',
}

const App = () => {
  useEffect(() => {
    featureClient.identify(userContext)
  }, []);

  return (
    <LDProvider client={featureClient}>
      <Welcome />
    </LDProvider>
  );
};

const Welcome = () => {
  const flagValue = useBoolVariation('flag-key', false);

  return (
    <SafeAreaView>
      <Text>Welcome to LaunchDarkly</Text>
      <Text>Flag value is {`${flagValue}`}</Text>
    </SafeAreaView>
  );
}

export default App;

After running the app, I turned the flag-key off and on multiple times from the LD dashboard. This is the resulting logs (I have replaced app name and flag names for security purposes):

 BUNDLE  ./index.js 

 LOG  debug: [LaunchDarkly] sdkData: {
  "name": "@launchdarkly/react-native-client-sdk",
  "version": "10.0.3",
  "userAgentBase": "ReactNativeClient"
}
 LOG  debug: [LaunchDarkly] sdkData: {
  "name": "@launchdarkly/react-native-client-sdk",
  "version": "10.0.3",
  "userAgentBase": "ReactNativeClient"
}
 LOG  debug: [LaunchDarkly] platformData: {
  "name": "React Native",
  "ld_application": {
    "key": "",
    "envAttributesVersion": "1.0",
    "locale": "en_US",
    "id": "",
    "name": "",
    "version": "",
    "versionName": ""
  },
  "ld_device": {
    "key": "",
    "envAttributesVersion": "1.0",
    "manufacturer": "Google",
    "model": "sdk_gphone64_arm64",
    "os": {
      "family": "android",
      "name": "android",
      "version": "34"
    }
  }
}
 LOG  debug: [LaunchDarkly] Started EventProcessor.
 LOG  Running "MyCompanyApp" with {"rootTag":51}
 LOG  debug: [LaunchDarkly] Context was unspecified or had no key; event will not be sent
 LOG  debug: [LaunchDarkly] platformData: {
  "name": "React Native",
  "ld_application": {
    "key": "",
    "envAttributesVersion": "1.0",
    "locale": "en_US",
    "id": "",
    "name": "",
    "version": "",
    "versionName": ""
  },
  "ld_device": {
    "key": "",
    "envAttributesVersion": "1.0",
    "manufacturer": "Google",
    "model": "sdk_gphone64_arm64",
    "os": {
      "family": "android",
      "name": "android",
      "version": "34"
    }
  }
}
 LOG  debug: [LaunchDarkly] platformData: {
  "name": "React Native",
  "ld_application": {
    "key": "",
    "envAttributesVersion": "1.0",
    "locale": "en_US",
    "id": "",
    "name": "",
    "version": "",
    "versionName": ""
  },
  "ld_device": {
    "key": "",
    "envAttributesVersion": "1.0",
    "manufacturer": "Google",
    "model": "sdk_gphone64_arm64",
    "os": {
      "family": "android",
      "name": "android",
      "version": "34"
    }
  }
}
 LOG  debug: [LaunchDarkly] Identifying {"kind":"multi","user":{"anonymous":true,"key":"2b88cfc2-0ea3-456e-8b9c-f703dd785121"},"ld_device":{"envAttributesVersion":"1.0","manufacturer":"Google","model":"sdk_gphone64_arm64","os":{"name":"android","version":"34","family":"android"},"key":"5bf34f46-5970-46f5-83a1-8eba6a232162"}}
 LOG  debug: [LaunchDarkly] Using storage
 LOG  debug: [LaunchDarkly] change: context: {"kind":"multi","user":{"anonymous":true,"key":"2b88cfc2-0ea3-456e-8b9c-f703dd785121"},"ld_device":{"envAttributesVersion":"1.0","manufacturer":"Google","model":"sdk_gphone64_arm64","os":{"name":"android","version":"34","family":"android"},"key":"5bf34f46-5970-46f5-83a1-8eba6a232162"}}, flags: flag-1,flag-2,flag-3
 LOG  debug: [LaunchDarkly] sdkData: {
  "name": "@launchdarkly/react-native-client-sdk",
  "version": "10.0.3",
  "userAgentBase": "ReactNativeClient"
}
 LOG  debug: [LaunchDarkly] [EventSource] Will open new connection in 0 ms.
 LOG  debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: HEADERS_RECEIVED(2), status: 200
 LOG  debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: LOADING(3), status: 200
 LOG  info: [LaunchDarkly] Opened LaunchDarkly stream connection
 LOG  debug: [LaunchDarkly] [EventSource][onreadystatechange][OPEN] Connection opened.
 LOG  debug: [LaunchDarkly] Received put event
 LOG  debug: [LaunchDarkly] Streamer PUT: flag-1,flag-2,flag-3
 LOG  debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: LOADING(3), status: 200
 LOG  debug: [LaunchDarkly] Not emitting changes from PUT
 LOG  debug: [LaunchDarkly] App state prev: active, next: active
 LOG  debug: [LaunchDarkly] No action needed.
 LOG  debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: DONE(4), status: 200
 LOG  debug: [LaunchDarkly] [EventSource][onreadystatechange][DONE] Operation done.
 LOG  debug: [LaunchDarkly] [EventSource] Will open new connection in 558 ms.
 LOG  info: [LaunchDarkly] Will retry stream connection in 558 milliseconds
 LOG  debug: [LaunchDarkly] Flushing 1 events

Note: I did test streaming on Android with a fresh create react-native app and it does work as expected so there is definitely something different about my company's app that is somehow conflicting with your SDK. Unfortunately, the debug logs dont really provide anything very useful in tracking down the issue. On the working iOS side, I never see logs like: LOG info: [LaunchDarkly] Will retry stream connection in 558 milliseconds tho so I still feel like that's hinting at the issue. I would've expected some error codes (non 200s) from the sdk tho in the debug logs 🤔

Any help is appreciated. Thanks!

yusinto commented 3 months ago

@dan-trewin Please upgrade to 10.0.5 which has a bugfix for streaming retries and also more logging in error scenarios. If the issue persists, please re-open this issue and update it with the new debug output. It should give more details of the error. Thank you.

dan-trewin commented 3 months ago

@yusinto The new version does seem to fix the bug in that our android app seems to properly detect changes to LD flags live now (as I flip them on/off on the LD dashboard).

However, I am still constantly seeing logs about the stream needing to be re-opened/re-tried. And these logs just keep coming thru the app throughout its entire life. This worries me alittle as there's a chance it may be resource/CPU intensive to keep closing/reopening these streams

Wondering if you think that will be an issue or if you have any ideas as to why this would be happening? It seems like to me we should now be seeing some error logs around why this is happening with your changes but we aren't 😞

Debug Output ``` LOG debug: [LaunchDarkly] sdkData: { "name": "@launchdarkly/react-native-client-sdk", "version": "10.0.5", "userAgentBase": "ReactNativeClient" } LOG debug: [LaunchDarkly] [EventSource] Will open new connection in 0 ms. LOG info: [LaunchDarkly] Closed LaunchDarkly stream connection INFO [rn-pendo-sdk] React Navigation Init. LOG debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: HEADERS_RECEIVED(2), status: 200 LOG debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: LOADING(3), status: 200 LOG info: [LaunchDarkly] Opened LaunchDarkly stream connection LOG debug: [LaunchDarkly] [EventSource][onreadystatechange][OPEN] Connection opened. LOG debug: [LaunchDarkly] Received put event LOG debug: [LaunchDarkly] Streamer PUT: flag-1,flag-2,flag-3 LOG debug: [LaunchDarkly] OnIdentifyResolve no changes to emit from: streamer PUT. LOG debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: LOADING(3), status: 200 LOG debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: DONE(4), status: 200 LOG debug: [LaunchDarkly] [EventSource][onreadystatechange][DONE] Operation done. LOG debug: [LaunchDarkly] [EventSource] Will open new connection in 659 ms. LOG info: [LaunchDarkly] Will retry stream connection in 659 milliseconds LOG info: [LaunchDarkly] Closed LaunchDarkly stream connection LOG debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: OPENED(1), status: 0 LOG debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: HEADERS_RECEIVED(2), status: 200 LOG debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: LOADING(3), status: 200 LOG info: [LaunchDarkly] Opened LaunchDarkly stream connection LOG debug: [LaunchDarkly] [EventSource][onreadystatechange][OPEN] Connection opened. LOG debug: [LaunchDarkly] Received put event LOG debug: [LaunchDarkly] Streamer PUT: flag-1,flag-2,flag-3 LOG debug: [LaunchDarkly] OnIdentifyResolve no changes to emit from: streamer PUT. LOG debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: DONE(4), status: 200 LOG debug: [LaunchDarkly] [EventSource][onreadystatechange][DONE] Operation done. LOG debug: [LaunchDarkly] [EventSource] Will open new connection in 711 ms. LOG info: [LaunchDarkly] Will retry stream connection in 711 milliseconds LOG info: [LaunchDarkly] Closed LaunchDarkly stream connection LOG debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: OPENED(1), status: 0 LOG debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: HEADERS_RECEIVED(2), status: 200 LOG debug: [LaunchDarkly] [EventSource][onreadystatechange] ReadyState: LOADING(3), status: 200 LOG info: [LaunchDarkly] Opened LaunchDarkly stream connection LOG debug: [LaunchDarkly] [EventSource][onreadystatechange][OPEN] Connection opened. LOG debug: [LaunchDarkly] Received put event LOG debug: [LaunchDarkly] Streamer PUT: flag-1,flag-2,flag-3 ... [Logs keep showing stuff like this over and over ^^^] ```

I'll defer to your judgement on whether the issue is worth re-opening. Thanks for the help!

yusinto commented 3 months ago

@dan-trewin are you able to share a minimal reproducible project so I can debug this further please? It looks like in your application there is some network configuration/policy that forces open XHR requests to close after a PUT is completed.

sli-rbi commented 2 months ago

for anyone still having the same issue, please check out this:

https://github.com/expo/expo/issues/27526

dan-trewin commented 2 months ago

@yusinto Sorry for not getting back to you earlier. Appreciate all the help, but we couldn't share any more reproduction details.

@sli-rbi Thanks so much for that suggestion. We aren't using expo but this did help me figure out our app's issue as it also had to do with okhttp. In case anyone else runs into this issue, our react-native app was setting a "custom http client" in our app's MainApplication.kt file like so:

  override fun onCreate() {
      super.onCreate()
      // Setting the custom http client with no cache enabled
      OkHttpClientProvider.setOkHttpClientFactory(CustomOkHttpClientFactory())
      SoLoader.init(this, false)
      if (BuildConfig.IS_NEW_ARCHITECTURE_ENABLED) {
          // If you opted-in for the New Architecture, we load the native entry point for this app.
          load()
      }
  }

The "custom http client" was used to disable the cache for security reasons, however we neglected to add the "no timeout" logic that the regular react-native http client adds: https://github.com/facebook/react-native/blob/v0.73.6/packages/react-native/ReactAndroid/src/main/java/com/facebook/react/modules/network/OkHttpClientProvider.java#L55-L61. After adding that logic to our "custom http client" everything related to android streams and LD worked as expected ❗ 😄