Specific JS fetch() fails on 0.66.4 (OR: How to debug react-native Android native code?)

[Avishayy]

New Version

0.66.4

Old Version

0.62.2

Build Target(s)

Android debug and release

Output of react-native info

$ react-native info
info Fetching system and libraries information...
(node:36495) Warning: Accessing non-existent property 'padLevels' of module exports inside circular dependency
(Use `node --trace-warnings ...` to show where the warning was created)
System:
    OS: macOS 11.6
    CPU: (8) x64 Intel(R) Core(TM) i7-1068NG7 CPU @ 2.30GHz
    Memory: 70.23 MB / 32.00 GB
    Shell: 5.8 - /bin/zsh
  Binaries:
    Node: 17.0.1 - /usr/local/bin/node
    Yarn: 1.22.1 - /usr/local/bin/yarn
    npm: 8.1.0 - /usr/local/bin/npm
    Watchman: 2021.11.01.00 - /usr/local/bin/watchman
  Managers:
    CocoaPods: 1.10.2 - /usr/local/bin/pod
  SDKs:
    iOS SDK:
      Platforms: DriverKit 21.0.1, iOS 15.0, macOS 12.0, tvOS 15.0, watchOS 8.0
    Android SDK: Not Found
  IDEs:
    Android Studio: 2020.3 AI-203.7717.56.2031.7583922
    Xcode: 13.1/13A1030d - /usr/bin/xcodebuild
  Languages:
    Java: 11.0.10 - /usr/bin/javac
  npmPackages:
    @react-native-community/cli: Not Found
    react: 17.0.2 => 17.0.2
    react-native: 0.66.4 => 0.66.4
    react-native-macos: Not Found
  npmGlobalPackages:
    *react-native*: Not Found

Issue and Reproduction Steps

I'm trying to call fetch in a specific point in my application, which succeeded in the previous version and the exact same call succeeds if I try it again and it happens every time. I don't have a minimal reproducer and I've been debugging it for a few hours already.

I'll note that it does work as expected on iOS.

I'm asking for some help on how to debug the actual react-native native code (not a module), I've found my way into sendReqeust() at ReactAndroid/src/main/java/com/facebook/react/modules/network/NetworkingModule.java.

The code does log on error:

    try {
      sendRequestInternal(...);
    } catch (Throwable th) {
      FLog.e(TAG, "Failed to send url request: " + url, th);
      final RCTDeviceEventEmitter eventEmitter = getEventEmitter("sendRequest error");
      if (eventEmitter != null) {
        ResponseUtil.onRequestError(eventEmitter, requestId, th.getMessage(), th);
      }
    }

but the logs never appear, I did try using FLog.setLoggingDelegate() on my react application class with my own delegate (that uses logcat), to no avail.

Ideally I'll be able to debug react-native code with Android Studio, but since NPM ships a binary rather than source code, it's not possible. I could dig further to try and understand how to compile the sources but it might take a while so I'm shooting my shot here.

Thanks.

[cortinico]

So you can follow a variety of approach:

I don't have a minimal reproducer and I've been debugging it for a few hours already.

Not having a minimal reproducer is actually the bummer here. I would try to isolate the code as much as possible. Ideally creating a new project from a blank template and trying to replicate the bug, would be great.

That would also help other understand what's going on.

Ideally I'll be able to debug react-native code with Android Studio, but since NPM ships a binary rather than source code, it's not possible. I could dig further to try and understand how to compile the sources but it might take a while so I'm shooting my shot here.

The fact that NPM ships a binary for ReactAndroid should not prevent you from debugging. If you place a breakpoint that should just work.

As an alternative you can:

1. Checkout the react-native repo and try to use the rn-tester sample app as a playground to reproduce your issue. There you will be building from source, so it should be easy to see what's going on.
2. Follow this guide to build react-native from source rather than from the binary package.

[Avishayy]

The fact that NPM ships a binary for ReactAndroid should not prevent you from debugging. If you place a breakpoint that should just work.

Android Studio doesn't recognize that as part of the project's code, so I can't place breakpoints in it.

I'll try the linked guide and keep you updated, thank you.

[Avishayy]

Alright, this took a while to figure out, and I'm not really sure how to point the blame but here goes:

I did manage to debug by deleting NetworkingModule.java from the classes jar inside the react-native aar and then implementing NetworkingModule.java (with the same package path) in my project. (Actually, I just found out it is possible to find the class in the aar by double shift in Android Studio and then ticking 'include non-project items', whoops, I guess I had some cache problems?)

My project does these two things:

1. HTTP/1.1 POST to the backend to connect using OAuth
2. HTTP/1.1 POST to fetch all user's data after login

The first POST always succeeds, the second POST fails (with a JS exception) on RN 0.66.4 but succeeds on RN 0.62.2. After stepping in sendRequestInternal() at NetworkModule.java for a while and seeing the stack of the failure (at the onFailure callback):

EOFException (and the fact we are at CallServerInterceptor) hint that we are using a connection that doesn't return anything.

While trying to understand what causes this exception to trigger, I remembered we have a certificate pinning implementation in the project. It looks something like this:

        OkHttpClient.Builder client = new OkHttpClient.Builder()
                .connectTimeout(0, TimeUnit.MILLISECONDS)
                .readTimeout(0, TimeUnit.MILLISECONDS)
                .writeTimeout(0, TimeUnit.MILLISECONDS)
                // Added this to bypass bug in rn-fetch-blob <= 0.12.0 (see https://github.com/joltup/rn-fetch-blob/issues/490#issuecomment-654326087)
                .retryOnConnectionFailure(false)
                .cookieJar(new ReactCookieJarContainer())
                .certificatePinner(certificatePinner);

        client.addInterceptor(new UserAgentInterceptor(mUserAgent));

This is the client which will be used for the HTTP exchanges (as we later override the regular client with it), so it made me think something here might be the problem. After commenting out some lines I found out the culprit was the connection retry. AKA .retryOnConnectionFailure(false), which was a hacky fix to a crash in some RN library.

So everything's all good, right? Well, not really. Why did this work on RN 0.62.2 then?

I found out if I wait a decent amount of the time before the second request then it succeeds, which was odd. I ended up debugging OkHtp for a while and spent some time understanding its implementation (with the interceptors and such).

I'll save you the long story and take you right to the point of interest, ConnectInterceptor.kt (OkHttp 4.9.1):

object ConnectInterceptor : Interceptor {
  @Throws(IOException::class)
  override fun intercept(chain: Interceptor.Chain): Response {
    val realChain = chain as RealInterceptorChain
    val exchange = realChain.call.initExchange(chain)
    val connectedChain = realChain.copy(exchange = exchange)
    return connectedChain.proceed(realChain.request)
  }

Fairly simple (after looking it for a while) - this interceptor is responsible for connecting to the server, exchange will hold all information about the exchange of requests and responses (including the relevant socket), I looked at it and saw that it was the exact same socket for POST #2 and POST #1, even though the first POST had its connection shut down already.

initExchange() will also attempt to find an existing connection by using an exchangeFinder.find() which calls ExchangeFinder.findHealthyConnection(), findHealthyConnection() will try to find a candidate connection in the pool (by calling findConnection()) and then call candidate.isHealthy(doExtensiveHealthChecks), likeso:

private fun findHealthyConnection(
    connectTimeout: Int,
    readTimeout: Int,
    writeTimeout: Int,
    pingIntervalMillis: Int,
    connectionRetryEnabled: Boolean,
    doExtensiveHealthChecks: Boolean
  ): RealConnection {
    while (true) {
      val candidate = findConnection(
          connectTimeout = connectTimeout,
          readTimeout = readTimeout,
          writeTimeout = writeTimeout,
          pingIntervalMillis = pingIntervalMillis,
          connectionRetryEnabled = connectionRetryEnabled
      )

      // Confirm that the connection is good.
      if (candidate.isHealthy(doExtensiveHealthChecks)) {
        return candidate
      }

      // If it isn't, take it out of the pool.
      candidate.noNewExchanges()

      ...
    }

Apparently, the previous connection (from the first POST) is used, that connection is not usable anymore. However, let's keep on looking into isHealthy():

  fun isHealthy(doExtensiveChecks: Boolean): Boolean {
    assertThreadDoesntHoldLock()

    val nowNs = System.nanoTime()

    val rawSocket = this.rawSocket!!
    val socket = this.socket!!
    val source = this.source!!
    if (rawSocket.isClosed || socket.isClosed || socket.isInputShutdown ||
            socket.isOutputShutdown) {
      return false
    }

    val http2Connection = this.http2Connection
    if (http2Connection != null) {
      return http2Connection.isHealthy(nowNs)
    }

    val idleDurationNs = synchronized(this) { nowNs - idleAtNs }
    if (idleDurationNs >= IDLE_CONNECTION_HEALTHY_NS && doExtensiveChecks) {
      return socket.isHealthy(source)
    }

    return true
  }

It seems like socket isn't actually shutdown in anyway:

    if (rawSocket.isClosed || socket.isClosed || socket.isInputShutdown ||
            socket.isOutputShutdown) {
      return false
    }

and I'm using HTTP/1.1 with flask for the backend, so eventually we'll get to:

    val idleDurationNs = synchronized(this) { nowNs - idleAtNs }
    if (idleDurationNs >= IDLE_CONNECTION_HEALTHY_NS && doExtensiveChecks) {
      return socket.isHealthy(source)
    }

idleAtNs is defined as:

  /** Timestamp when `allocations.size()` reached zero. Also assigned upon initial connection. */
  internal var idleAtNs = Long.MAX_VALUE

So, equal to the time of the initial connection in our case.

doExtensiveChecks is set to true (exchangeFinder.find() sets it as doExtensiveHealthChecks = chain.request.method != "GET"), IDLE_CONNECTION_HEALTHY_NS is set to 10 seconds. So if 10 seconds has passed since the connection was opened, we'll do extensive checks on the socket (and find out it's not available), this explains the "waiting between the fetches" that caused it to work.

Fine, so we're using a bad socket, why did it work on RN 0.62.2? That version uses OkHttp 3.12.1

The sources are not identical but the functionality is generally the same, except on isHealthy():

  public boolean isHealthy(boolean doExtensiveChecks) {
    if (socket.isClosed() || socket.isInputShutdown() || socket.isOutputShutdown()) {
      return false;
    }

    if (http2Connection != null) {
      return !http2Connection.isShutdown();
    }

    if (doExtensiveChecks) {
      try {
        int readTimeout = socket.getSoTimeout();
        try {
          socket.setSoTimeout(1);
          if (source.exhausted()) {
            return false; // Stream is exhausted; socket is closed.
          }
          return true;
        } finally {
          socket.setSoTimeout(readTimeout);
        }
      } catch (SocketTimeoutException ignored) {
        // Read timed out; socket is good.
      } catch (IOException e) {
        return false; // Couldn't read; socket is closed.
      }
    }

    return true;
  }

The if (doExtensiveChecks) { ... } block (which is equivalent to socket.isHealthy()) is called regardless of whether 10 seconds has passed (if doExtensiveChecks is set, which is also true in this version) and this forces it to get a new connection from the pool.

To conclude, this regression happens because OkHttp 4.9.1 wants to have 10 idle seconds on a connection before doing extensive health checks on it.

This has nothing to do with react-native directly, and OkHttp is doing this to be smart about its checks, the action points for me are to understand why the socket wasn't properly shutdown (is it even supposed to?) and potentially remove the unmaintained library that forced to disable the retry connection logic.

tl;dr The new OkHttp version introduced an optimization that had our stale connection used, we also had a hacky fix for a library that disabled retry on connection failure, together they caused this weird issue.

Cheers.

edit:
Though, we see that there's a FIN from both sides on that connection, so the connection should be shutdown..
Maybe it is a bug in OkHttp? I'll check the older version in debug

edit 2:
I debugged the 3.12.1 version as well and it seems like it's regarded as not shutdown at that version too